Debugging 20s pause in boot time in rawhide

[Jason D. Clinton]

On Mon, Jan 17, 2011 at 15:09, Lennart Poettering <mzerqung at 0pointer.de>wrote:

> > 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.
>

I tried this here is some interesting output during boot:

Jan 17 20:56:22 jclinton-laptop kernel: [   19.475805] systemd[1]:
sys-devices-pci0000:00-0000:00:1a.1-usb4-4\x2d2-4\x2d2:1.0-bluetooth-hci0.device
changed dead -> plugged
Jan 17 20:56:22 jclinton-laptop kernel: [   19.475823] systemd[1]: Trying to
enqueue job bluetooth.target/start/fail
Jan 17 20:56:22 jclinton-laptop kernel: [   19.475840] systemd[1]: Installed
new job bluetooth.target/start as 146
Jan 17 20:56:22 jclinton-laptop kernel: [   19.475853] systemd[1]: Enqueued
job bluetooth.target/start as 146
Jan 17 20:56:22 jclinton-laptop kernel: [   19.475863] systemd[1]:
bluetooth.target changed dead -> active
Jan 17 20:56:22 jclinton-laptop kernel: [   19.475871] systemd[1]: Job
bluetooth.target/start finished, success=yes

So the bluetooth.target is now satisfied. Later on after 20s pause:

Jan 17 20:56:47 jclinton-laptop NetworkManager[1214]: <warn> bluez error
getting default adapter: Activation of org.bluez timed out

And then 4 seconds later when pulseaudio is starting, it triggers the D-Bus
Activation and then everything is fine.

Jan 17 20:56:51 jclinton-laptop pulseaudio[1721]: module-alsa-card.c: Failed
to find a working profile.
Jan 17 20:56:51 jclinton-laptop pulseaudio[1721]: module.c: Failed to load
module "module-alsa-card" (argument: "device_id="29"
name="platform-thinkpad_acpi" card_name="alsa_c
ard.platform-thinkpad_acpi" tsched=yes ignore_dB=no
card_properties="module-udev-detect.discovered=1""): initialization failed.
Jan 17 20:56:51 jclinton-laptop kernel: [   60.825082] systemd[1]: Got D-Bus
request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
Jan 17 20:56:51 jclinton-laptop kernel: [   60.826717] systemd[1]: Got D-Bus
request: org.freedesktop.systemd1.Activator.ActivationRequest() on
/org/freedesktop/DBus
Jan 17 20:56:51 jclinton-laptop kernel: [   60.826726] systemd[1]: Got D-Bus
activation request for bluetooth.service
Jan 17 20:56:51 jclinton-laptop kernel: [   60.827703] systemd[1]: Trying to
enqueue job bluetooth.service/start/replace
Jan 17 20:56:51 jclinton-laptop kernel: [   60.827929] systemd[1]: Installed
new job bluetooth.service/start as 658
Jan 17 20:56:51 jclinton-laptop kernel: [   60.827936] systemd[1]: Enqueued
job bluetooth.service/start as 658
Jan 17 20:56:51 jclinton-laptop kernel: [   60.827980] systemd[1]: About to
execute: /usr/sbin/bluetoothd -n
Jan 17 20:56:51 jclinton-laptop kernel: [   60.838118] systemd[1]: Forked
/usr/sbin/bluetoothd as 1727
Jan 17 20:56:51 jclinton-laptop kernel: [   60.838223] systemd[1]:
bluetooth.service changed dead -> start
Jan 17 20:56:51 jclinton-laptop kernel: [   60.838255] systemd[1]: Incoming
traffic on systemd-logger.socket
Jan 17 20:56:51 jclinton-laptop kernel: [   60.838290] systemd[1]: Trying to
enqueue job systemd-logger.service/start/replace
Jan 17 20:56:51 jclinton-laptop kernel: [   60.838315] systemd[1]: Installed
new job systemd-logger.service/start as 759
Jan 17 20:56:51 jclinton-laptop kernel: [   60.838325] systemd[1]: Enqueued
job systemd-logger.service/start as 759
Jan 17 20:56:51 jclinton-laptop kernel: [   60.838350] systemd[1]:
systemd-logger.socket changed listening -> running
Jan 17 20:56:51 jclinton-laptop kernel: [   60.838398] systemd[1]: About to
execute: /lib/systemd/systemd-logger
Jan 17 20:56:51 jclinton-laptop kernel: [   60.850099] systemd[1]: Forked
/lib/systemd/systemd-logger as 1728
Jan 17 20:56:51 jclinton-laptop kernel: [   60.850302] systemd[1]:
systemd-logger.service changed dead -> running
Jan 17 20:56:51 jclinton-laptop kernel: [   60.850323] systemd[1]: Job
systemd-logger.service/start finished, success=yes
Jan 17 20:56:51 jclinton-laptop bluetoothd[1727]: Bluetooth deamon 4.85

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.
>

I did an rpm -Va and I have no unit files which are not verified so it
appears that I am starting Networkmanager before pulseaudio instead of
with/after it. Perhaps my system has a unit file which requires
network.target but comes before pulseaudio?

I tried to generate a dot file of the dep. graph but dot in rawhide infinite
loops on the output.

This interesting though:
$ ls -l /etc/systemd/system/dbus-org.freedesktop.NetworkManager.service
lrwxrwxrwx. 1 root root 42 Oct 22 13:33
/etc/systemd/system/dbus-org.freedesktop.NetworkManager.service ->
/lib/systemd/system/NetworkManager.service
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.fedoraproject.org/pipermail/devel/attachments/20110117/b27ab887/attachment.html