extremely slow shell starts (trying to debug, dbus related)

[Neal Becker]

On my server, after updating f20->f21, shell startup is _extremely_ slow.

Using strace, it appears that the problem is dbus

08:22:57 connect(5, {sa_family=AF_LOCAL, 
sun_path="/var/run/dbus/system_bus_socket"}, 33) = 0
...
08:22:57 recvmsg(5, 0x7fff640c3970, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource 
temporarily unavailable)
08:22:57 poll([{fd=5, events=POLLIN}], 1, 25000) = 1 ([{fd=5, revents=POLLIN}])
08:23:22 recvmsg(5, {msg_name(0)=NULL, 
msg_iov(1)=[{"l\3\1\0013\0\0\0\4\0\0\0m\0\0\0\6\1s\0\7\0\0\0:1.1155\0"..., 
2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 179
08:23:22 write(6, "\1\0\0\0\0\0\0\0", 8) = 8

Notice the 30second wait for a response from dbus?

Also in /var/log/messages, various dbus messages such as:
Dec 30 08:19:32 nbecker7 su: (to root) nbecker on pts/0
Dec 30 08:20:02 nbecker7 dbus[809]: [system] Connection has not authenticated 
soon enough, closing it (auth_timeout=30000ms, elapsed: 30004ms)

Any hints?

[Cameron Simpson]

On 30Dec2014 08:36, Neal Becker  wrote:
> On my server, after updating f20->f21, shell startup is _extremely_ slow.
>
> Using strace, it appears that the problem is dbus
>
> 08:22:57 connect(5, {sa_family=AF_LOCAL,
> sun_path="/var/run/dbus/system_bus_socket"}, 33) = 0
> ...
> 08:22:57 recvmsg(5, 0x7fff640c3970, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource
> temporarily unavailable)
> 08:22:57 poll([{fd=5, events=POLLIN}], 1, 25000) = 1 ([{fd=5, revents=POLLIN}])
> 08:23:22 recvmsg(5, {msg_name(0)=NULL,
> msg_iov(1)=[{"l\3\1\0013\0\0\0\4\0\0\0m\0\0\0\6\1s\0\7\0\0\0:1.1155\0"...,
> 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 179
> 08:23:22 write(6, "\1\0\0\0\0\0\0\0", 8) = 8
>
> Notice the 30second wait for a response from dbus?
>
> Also in /var/log/messages, various dbus messages such as:
> Dec 30 08:19:32 nbecker7 su: (to root) nbecker on pts/0
> Dec 30 08:20:02 nbecker7 dbus[809]: [system] Connection has not authenticated
> soon enough, closing it (auth_timeout=30000ms, elapsed: 30004ms)
>
> Any hints?

Those log line times don't match the strace times. But I'll assume they're 
typical, and associate with your shell startups timingwise.

A few questions:

- why does the shell use dbus at all? (just wondering, I'm presuming this is some bash feature new to me)

- can you strace dbus (pid 809 in the above log)? using strace's -f option if dbus forks.

- 30s is in my head as a standard DNS timeout, but it is also common to some 
other things and your sample strace above shows only 25s. (Though I notice also 
that the timeout in the poll() call is itself exactly 25s).

So you're not seeing a 25s wait before dbus replies, you're seeing a 25s 
timeout on the client (your shell?)?

I'd be trying 2 things: see if dbus has a config option to turn up its 
debugging messages, and strace dbus around a shell start. Eg:

strace -p 809 -f -o strace.dbus.out

Disclaimer: not running Fedora here, so this is all general advice.

Cheers,
Cameron Simpson

They utter mere words; with empty oaths they make promises; so lawsuits
  spring up like poisonous weeds in the furrows of the field.
Sounds like 20th-century USA, doesn't it? This is from the book of Hosea,
chapter 10, the 4th verse. It's only a few thousand years old...
        - Dan Nitschke

[Fedora] extremely slow shell starts (trying to debug, dbus related)

[Walter Cazzola]

Hi,
some times ago I'd a similar behavior I didn't dig much in that so I
don't know if dbus was the resposible of the delay in my case but I
found out that the delay was provoked by the loading of a really huge
.history file. Removed that and the options to save it anything worked
smoothly as usual. Maybe this apply to you as well.

Walter

On Tue, 30 Dec 2014, Neal Becker wrote:
> On my server, after updating f20->f21, shell startup is _extremely_ slow.
>
> Using strace, it appears that the problem is dbus
>
> 08:22:57 connect(5, {sa_family=AF_LOCAL,
> sun_path="/var/run/dbus/system_bus_socket"}, 33) = 0
> ...
> 08:22:57 recvmsg(5, 0x7fff640c3970, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource
> temporarily unavailable)
> 08:22:57 poll([{fd=5, events=POLLIN}], 1, 25000) = 1 ([{fd=5, revents=POLLIN}])
> 08:23:22 recvmsg(5, {msg_name(0)=NULL,
> msg_iov(1)=[{"l\3\1\0013\0\0\0\4\0\0\0m\0\0\0\6\1s\0\7\0\0\0:1.1155\0"...,
> 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 179
> 08:23:22 write(6, "\1\0\0\0\0\0\0\0", 8) = 8
>
> Notice the 30second wait for a response from dbus?
>
> Also in /var/log/messages, various dbus messages such as:
> Dec 30 08:19:32 nbecker7 su: (to root) nbecker on pts/0
> Dec 30 08:20:02 nbecker7 dbus[809]: [system] Connection has not authenticated
> soon enough, closing it (auth_timeout=30000ms, elapsed: 30004ms)
>
> Any hints?

--