Bug 971650 - Bootup takes relatively long, because of Network Manager.service
Bootup takes relatively long, because of Network Manager.service
Status: CLOSED CURRENTRELEASE
Product: Fedora
Classification: Fedora
Component: NetworkManager (Show other bugs)
19
x86_64 Linux
unspecified Severity low
: ---
: ---
Assigned To: Dan Williams
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-06-07 01:01 EDT by hannes
Modified: 2014-03-25 18:53 EDT (History)
9 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2014-03-25 18:53:16 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


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

  None (edit)
Description hannes 2013-06-07 01:01:58 EDT
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 10:29:37 EDT
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 10:43:40 EDT
Hm, the NetworkManager people are not omniscient... Please at least attach the output from 'journalctl -u NetworkManager -b'.
Comment 3 hannes 2013-06-07 10:48:26 EDT
Created attachment 758193 [details]
journalctl -u NetworkManager -b
Comment 4 hannes 2013-06-07 10:49:08 EDT
Me neither, so I didn't know what they might need.
Comment 5 Jóhann B. Guðmundsson 2013-06-07 11:24:45 EDT
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 01:16:45 EDT
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 17:49:45 EDT
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 15:35:00 EDT
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 16:21:23 EDT
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 03:47:08 EDT
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 14:25:48 EDT
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.