Bug 971650 - Bootup takes relatively long, because of Network Manager.service
Summary: Bootup takes relatively long, because of Network Manager.service
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: NetworkManager
Version: 19
Hardware: x86_64
OS: Linux
unspecified
low
Target Milestone: ---
Assignee: Dan Williams
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-06-07 05:01 UTC by hannes
Modified: 2014-03-25 22:53 UTC (History)
9 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2014-03-25 22:53:16 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
bootup chart (81.23 KB, image/svg+xml)
2013-06-07 05:01 UTC, hannes
no flags Details
journalctl -u NetworkManager -b (12.49 KB, text/plain)
2013-06-07 14:48 UTC, hannes
no flags Details

Description hannes 2013-06-07 05:01:58 UTC
Created attachment 757983 [details]
bootup chart

Description of problem:
Hi all,

with the upgrade to f19, I noticed that bootup takes considerably longer than before with f18. This is caused by a really slow start of Network Manager

Version-Release number of selected component (if applicable):
rpm -qa systemd\*
systemd-204-4.fc19.x86_64
systemd-sysv-204-4.fc19.x86_64
systemd-libs-204-4.fc19.x86_64
systemd-ui-2-1.fc19.x86_64


How reproducible:
Every bootup


Additional info:
systemd-analyze blame
         22.046s NetworkManager.service
          5.535s lightdm.service
          3.694s systemd-fsck@dev-disk-by\x2duuid-7d28cf8d\x2dedc5\x2d4738\x2da030\x2d8198684aa7c2.service
          3.488s firewalld.service
          2.175s systemd-fsck@dev-disk-by\x2duuid-be983c67\x2d6eed\x2d40c1\x2db630\x2d2208d2c7d3d2.service
          1.508s preload.service
          1.456s dev-hugepages.mount
          1.428s sys-kernel-debug.mount
          1.416s dev-mqueue.mount
          1.415s systemd-fsck-root.service
          1.370s systemd-tmpfiles-setup.service
          1.334s home-johannes-daten.mount
          1.314s systemd-fsck@dev-disk-by\x2duuid-d7f627e9\x2d6262\x2d4fd2\x2d8089\x2d75edb32c2764.service
          1.232s systemd-tmpfiles-setup-dev.service
          1.052s systemd-udev-trigger.service
           986ms home.mount
           741ms plymouth-start.service
           658ms systemd-remount-fs.service
           642ms sys-kernel-config.mount
           639ms console-kit-daemon.service
           472ms systemd-logind.service
           456ms boot.mount
           315ms systemd-readahead-collect.service
           315ms systemd-readahead-replay.service
           294ms dev-disk-by\x2duuid-56e4ab8a\x2d4f38\x2d4bb4\x2dbfc7\x2d6452f0b2a164.swap
           283ms console-kit-log-system-start.service
           278ms systemd-tmpfiles-clean.service
           210ms accounts-daemon.service
           202ms colord.service
           152ms udisks2.service
           126ms systemd-random-seed-load.service
            62ms systemd-vconsole-setup.service
            51ms systemd-user-sessions.service
            34ms upower.service
            29ms var-tmp.mount
            28ms tmp.mount
            19ms systemd-journal-flush.service
            14ms polkit.service
            11ms sshd.service
             7ms rtkit-daemon.service
             6ms rc-local.service
             5ms systemd-readahead-done.service
             3ms systemd-update-utmp-runlevel.service
             3ms systemd-sysctl.service
             2ms wpa_supplicant.service
             1ms systemd-udevd.service
           467us sys-fs-fuse-connections.mount

Comment 1 hannes 2013-06-07 14:29:37 UTC
Ok, then I need to add:
rpm -qa NetworkManager\*
NetworkManager-glib-0.9.8.1-4.git20130515.fc19.x86_64
NetworkManager-0.9.8.1-4.git20130515.fc19.x86_64

Comment 2 Zbigniew Jędrzejewski-Szmek 2013-06-07 14:43:40 UTC
Hm, the NetworkManager people are not omniscient... Please at least attach the output from 'journalctl -u NetworkManager -b'.

Comment 3 hannes 2013-06-07 14:48:26 UTC
Created attachment 758193 [details]
journalctl -u NetworkManager -b

Comment 4 hannes 2013-06-07 14:49:08 UTC
Me neither, so I didn't know what they might need.

Comment 5 Jóhann B. Guðmundsson 2013-06-07 15:24:45 UTC
this is because of nm-wait-online is enabled by default ( in F18 it got enable by default in the network target I believe ) or pulled in by something and stalls everything else. There should be an bug about this already against nm

Comment 6 hannes 2013-06-08 05:16:45 UTC
I am not sure, if that's the reason, since this shows that the wait-online service is not enabled.

systemctl status NetworkManager-wait-online.service
NetworkManager-wait-online.service - Network Manager Wait Online
   Loaded: loaded (/usr/lib/systemd/system/NetworkManager-wait-online.service; disabled)
   Active: inactive (dead)

The start process of NetworkManager.service, probably shows the delay in more detail:
systemctl status NetworkManager.service 
NetworkManager.service - Network Manager
   Loaded: loaded (/usr/lib/systemd/system/NetworkManager.service; enabled)
   Active: active (running) since Sat 2013-06-08 06:37:00 CEST; 41min ago
 Main PID: 388 (NetworkManager)
   CGroup: name=systemd:/system/NetworkManager.service
           ├─ 388 /usr/sbin/NetworkManager --no-daemon
           └─1340 /sbin/dhclient -d -sf /usr/libexec/nm-dhcp-client.action -pf /var/run/dhclient-wlan0.pid -l...

Jun 08 06:37:07 caprica.localdomain NetworkManager[388]: <info> (wlan0): device state change: ip-config ->... 0]
Jun 08 06:37:07 caprica.localdomain NetworkManager[388]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Comm...te.
Jun 08 06:37:07 caprica.localdomain NetworkManager[388]: <info> (wlan0): device state change: secondaries ... 0]
Jun 08 06:37:07 caprica.localdomain NetworkManager[388]: <info> Policy set 'WLAN-CA1600' (wlan0) as defaul...NS.
Jun 08 06:37:07 caprica.localdomain NetworkManager[388]: <info> Activation (wlan0) successful, device activated.
Jun 08 06:37:26 caprica.localdomain NetworkManager[388]: <info> (wlan0): IP6 addrconf timed out or failed.
Jun 08 06:37:26 caprica.localdomain NetworkManager[388]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Conf......
Jun 08 06:37:26 caprica.localdomain NetworkManager[388]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Conf......
Jun 08 06:37:26 caprica.localdomain NetworkManager[388]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Conf...te.
Jun 08 07:10:14 caprica.localdomain NetworkManager[388]: nm_connection_get_setting_connection: assertion `...led
root@caprica:[johannes]#

Comment 7 Zbigniew Jędrzejewski-Szmek 2013-06-09 21:49:45 UTC
Jun 07 16:18:46 caprica.localdomain NetworkManager[394]: <info> NetworkManager (version 0.9.8.1-4.git20130515.fc19) is starting...
Jun 07 16:18:46 caprica.localdomain NetworkManager[394]: <info> Read config file /etc/NetworkManager/NetworkManager.conf
Jun 07 16:18:57 caprica.localdomain NetworkManager[394]: <info> WEXT support is enabled

...looks like NM is stuck in the initialization phase for 11 s.

Comment 8 hannes 2013-06-10 19:35:00 UTC
To me, this looks like a likely culprit:
Jun 08 06:37:26 caprica.localdomain NetworkManager[388]: <info> (wlan0): IP6 addrconf timed out or failed.

Comment 9 Jóhann B. Guðmundsson 2013-06-10 20:21:23 UTC
Well then there is /lib/systemd/system/NetworkManager-dispatcher.service

Which has Alias=dbus-org.freedesktop.nm-dispatcher.service

while the NM spec file has 

%{_datadir}/dbus-1/system-services/org.freedesktop.nm_dispatcher.service 

which contains nm_dispatcher.service with an underscore not "-" 

And that Alias= entry causes

"<warn> Dispatcher failed: (32) Unit dbus-org.freedesktop.nm-dispatcher.service failed to load: No such file or directory. See system logs and 'systemctl status dbus-org.freedesktop.nm-dispatcher.service' for details."

since the dbus-org.freedesktop.nm-dispatcher.service ( with "-" ) does not exist ( while the one with underscore does )

Comment 10 hannes 2013-07-07 07:47:08 UTC
This issue is still not fixed, even with the packages from the other bug report. I do have severe delays during bootup and I have no idea, where to look.

Comment 11 hannes 2013-07-11 18:25:48 UTC
Apparently the latest update fixed it:
rpm -qa NetworkManager\*
NetworkManager-0.9.8.2-8.git20130709.fc19.x86_64
NetworkManager-glib-0.9.8.2-8.git20130709.fc19.x86_64

systemd-analyze blame
         11.309s preload.service
          9.973s NetworkManager.service
          8.947s colord.service
          8.283s firewalld.service
          4.173s console-kit-daemon.service
          2.784s home-johannes-daten.mount
          2.241s systemd-logind.service
          2.024s lightdm.service
          1.957s polkit.service
          1.839s systemd-fsck@dev-disk-by\x2duuid-7d28cf8d\x2dedc5\x2d4738\x2da030\x2d8198684aa7c2.service
          1.539s systemd-fsck-root.service
          1.506s systemd-fsck@dev-disk-by\x2duuid-be983c67\x2d6eed\x2d40c1\x2db630\x2d2208d2c7d3d2.service
          1.330s sys-kernel-debug.mount
          1.317s dev-mqueue.mount
          1.305s dev-hugepages.mount
          1.251s systemd-udev-trigger.service
          1.037s systemd-fsck@dev-disk-by\x2duuid-d7f627e9\x2d6262\x2d4fd2\x2d8089\x2d75edb32c2764.service
           904ms console-kit-log-system-start.service
           860ms systemd-tmpfiles-setup-dev.service
           847ms plymouth-start.service
           807ms udisks2.service
           686ms home.mount
           681ms systemd-readahead-collect.service
           681ms systemd-readahead-replay.service
           592ms systemd-tmpfiles-clean.service
           578ms sys-kernel-config.mount
           435ms boot.mount
           430ms systemd-journal-flush.service
           406ms systemd-sysctl.service
           363ms dev-disk-by\x2duuid-56e4ab8a\x2d4f38\x2d4bb4\x2dbfc7\x2d6452f0b2a164.swap
           317ms systemd-udevd.service
           128ms var-tmp.mount
            54ms systemd-vconsole-setup.service
            54ms systemd-tmpfiles-setup.service
            47ms systemd-readahead-done.service
            42ms systemd-remount-fs.service
            29ms tmp.mount
            28ms systemd-random-seed-load.service
            11ms accounts-daemon.service
            10ms sshd.service
             8ms rtkit-daemon.service
             6ms wpa_supplicant.service
             5ms systemd-update-utmp-runlevel.service
             5ms NetworkManager-dispatcher.service
             3ms upower.service
             3ms rc-local.service
             1ms systemd-user-sessions.service
             1ms sys-fs-fuse-connections.mount


Note You need to log in before you can comment on or make changes to this bug.