Debugging 20s pause in boot time in rawhide

[Lennart Poettering]

On Sun, 16.01.11 01:32, Jason D. Clinton (me at jasonclinton.com) wrote:

> There's a twenty second pause in my boot sequence, shown below, before GDM
> starts and I'm not certain if it's in NetworkManager waiting on org.bluez,
> bluez itself or the bluez systemd unit file. (Or maybe I'm completely off.)
> Later on, the bluetooth.service starts normally and Bluetooth is working
> normally. Any ideas how to debug this?
> 
> Jan 16 00:59:39 jclinton-laptop NetworkManager[1157]: <info> Activation
> (eth0) Stage 4 of 5 (IP4 Configure Get) complete.
> Jan 16 00:59:39 jclinton-laptop NetworkManager[1157]: <info> Activation
> (eth0) Stage 5 of 5 (IP Configure Commit) started...
> Jan 16 00:59:40 jclinton-laptop NetworkManager[1157]: <info> (eth0): device
> state change: 7 -> 8 (reason 0)
> Jan 16 00:59:40 jclinton-laptop NetworkManager[1157]: <info> Policy set
> 'Auto eth0' (eth0) as default for IPv4 routing and DNS.
> Jan 16 00:59:40 jclinton-laptop NetworkManager[1157]: <info> Updating
> /etc/hosts with new system hostname
> Jan 16 00:59:40 jclinton-laptop NetworkManager[1157]: <info> Activation
> (eth0) successful, device activated.
> Jan 16 00:59:40 jclinton-laptop NetworkManager[1157]: <info> Activation
> (eth0) Stage 5 of 5 (IP Configure Commit) complete.
> Jan 16 00:59:40 jclinton-laptop ntpd[1168]: Listen normally on 4 eth0
> 192.168.0.139 UDP 123
> Jan 16 00:59:40 jclinton-laptop ntpd[1168]: peers refreshed
> Jan 16 00:59:42 jclinton-laptop kernel: [   26.723156] ehci_hcd
> 0000:00:1a.7: PCI INT D disabled
> Jan 16 00:59:42 jclinton-laptop kernel: [   26.736202] ehci_hcd
> 0000:00:1a.7: power state changed by ACPI to D3
> Jan 16 00:59:42 jclinton-laptop ntpd[1168]: Listen normally on 5 eth0
> fe80::21c:25ff:fea0:814f UDP 123
> Jan 16 00:59:42 jclinton-laptop ntpd[1168]: peers refreshed
> Jan 16 00:59:42 jclinton-laptop ntpd_intres[1205]: DNS
> 0.fedora.pool.ntp.org-> 70.86.250.6
> Jan 16 00:59:43 jclinton-laptop ntpd_intres[1205]: DNS
> 1.fedora.pool.ntp.org-> 199.4.28.166
> Jan 16 00:59:43 jclinton-laptop ntpd_intres[1205]: DNS
> 2.fedora.pool.ntp.org-> 208.75.88.4
> Jan 16 00:59:43 jclinton-laptop ntpd_intres[1205]: DNS
> 3.fedora.pool.ntp.org-> 68.68.18.78
> Jan 16 00:59:50 jclinton-laptop ntpd[1168]: 0.0.0.0 c61c 0c clock_step
> +0.355294 s
> Jan 16 00:59:50 jclinton-laptop ntpd[1168]: 0.0.0.0 c614 04 freq_mode
> Jan 16 00:59:51 jclinton-laptop ntpd[1168]: 0.0.0.0 c618 08 no_sys_peer
> Jan 16 01:00:01 jclinton-laptop NetworkManager[1157]: <warn> bluez error
> getting default adapter: Activation of org.bluez timed out

Smells like a bluez problem. Note sure what is going on there.

It might be a good idea to pass systemd.log_level=debug and
systemd.log_target=kmsg on the kernel cmdline and then inspect "dmesg"
after boot to figure out what is going on. 

My uneducated guess is that for some reason bluez is ordered after NM
but NM wants to use bluez and hence we have a deadlock which is resolved
via the timeout you see. On my own machine I do not see that behaviour
however, which makes this very suspicious.

Lennart

-- 
Lennart Poettering - Red Hat, Inc.