FS#33791 - [networkmanager] extremely slow startup with systemd

Attached to Project: Arch Linux
Opened by Benedikt (Schwefelsaeure) - Saturday, 09 February 2013, 21:30 GMT
Last edited by Gerardo Exequiel Pozzi (djgera) - Tuesday, 11 February 2014, 04:43 GMT
Task Type Bug Report
Category Upstream Bugs
Status Closed
Assigned To Jan de Groot (JGC)
Architecture x86_64
Severity Low
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 3
Private No

Details

Description:

The problem started several months ago and was already discussed in a thread (https://bbs.archlinux.org/viewtopic.php?id=152261): enabling NetworkManager.service via systemctl results in very slow boot time. systemd-analyze blame output (see also attached systemd-analyze plot output):

56350ms NetworkManager.service
2062ms gdm.service
1298ms systemd-vconsole-setup.service
...
29ms polkit.service
3ms sys-fs-fuse-connections.mount

Here the relevant output from journalctl -b (see http://pastebin.com/W1hhi3qd for full log):
-- Logs begin at So 2012-10-21 14:32:10 CEST, end at Sa 2013-02-09 21:01:01 CET. --
Feb 08 15:02:37 idefix systemd-journal[176]: Allowing runtime journal files to grow to 394.1M.
...
Feb 08 15:02:45 idefix NetworkManager[431]: <info> NetworkManager (version 0.9.6.4) is starting...
Feb 08 15:02:45 idefix NetworkManager[431]: <info> Read config file /etc/NetworkManager/NetworkManager.conf
Feb 08 15:02:45 idefix NetworkManager[431]: <info> WEXT support is enabled
Feb 08 15:02:45 idefix NetworkManager[431]: <info> VPN: loaded org.freedesktop.NetworkManager.openconnect
Feb 08 15:02:45 idefix dbus[434]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service'
Feb 08 15:02:45 idefix polkitd[449]: Started polkitd version 0.109
Feb 08 15:02:46 idefix polkitd[449]: Loading rules from directory /etc/polkit-1/rules.d
Feb 08 15:02:46 idefix polkitd[449]: Loading rules from directory /usr/share/polkit-1/rules.d
Feb 08 15:02:46 idefix polkitd[449]: Finished loading, compiling and executing 2 rules
!!! Notice the delay here !!!
Feb 08 15:03:39 idefix dbus[434]: [system] Successfully activated service 'org.freedesktop.PolicyKit1'
Feb 08 15:03:39 idefix NetworkManager[431]: <error> [1360332190.625914] [nm-manager-auth.c:87] pk_authority_get(): Failed to initialize PolicyKit: (24) Error initializing authority: Fehler beim Aufruf von StartServiceByName für org.freedesktop.PolicyKit1: Zeitüberschreitung wurde erreicht
Feb 08 15:03:39 idefix polkitd[449]: Lost the name org.freedesktop.PolicyKit1 - exiting
Feb 08 15:03:39 idefix NetworkManager[431]: <info> Loaded plugin keyfile: (c) 2007 - 2010 Red Hat, Inc. To report bugs please use the NetworkManager mailing list.

Two things caught my eyes (line numbers referes to the full log on pastebin):
1. Line 947: There is a timeout ("pk_authority_get(): Failed to initialize PolicyKit: (24) Error initializing authority: ..."). I guess NetworkManager tries to call Authorization Manager (polkitd) although it is not activated yet.
2. See here, polkitd is reported as "Started" after it was called by NetworkManager (at line 947):
Line 952: Feb 08 15:03:39 idefix systemd[1]: Started Authorization Manager.
...
Line 967: Feb 08 15:03:39 idefix systemd[1]: Starting Authorization Manager..
...
Line 975: Feb 08 15:03:39 idefix systemd[1]: Started Authorization Manager.

But the strange thing is that polkit is started twice.

If NetworkManager.service really relies on polkitd.service, maybe NetworkManager.service unit file should include a "After=polkitd.service" line or something else.

The possible fixes from the thread do not relate to our problem:
1. Add gnome-keyring to .xinitrc: I don't use gnome-keyring at all.
2. Use b43 driver from AUR: I don't have a Broadcom wireless module. I have an "Intel Corporation Centrino Wireless-N 1000 [Condor Peak]" module in my Dell XPS 15 L502X notebook.

After the slow start, NetworkManager works perfectly.

I don't know if it is an upstream bug or not, but the thread shows that more people are affected by this problem, and there is no general solution so far.

Additional info:
networkmanager 0.9.6.4-1
polkit 0.109-1
systemd 197-4

Output from lspci: http://pastebin.com/qJ5gAxzQ

Steps to reproduce:
   startup.svg (247.6 KiB)
This task depends upon

Closed by  Gerardo Exequiel Pozzi (djgera)
Tuesday, 11 February 2014, 04:43 GMT
Reason for closing:  Fixed
Comment by Jelle van der Waa (jelly) - Sunday, 10 February 2013, 10:54 GMT
This is probably a problem on your side here networkmanager starts:
226ms NetworkManager.service

Note that i tweaked my dhcpcd.conf and only use a wire :)
Comment by Benedikt (Schwefelsaeure) - Sunday, 10 February 2013, 19:45 GMT
Even if the problem is located on "my" side, the problem exists and some people are affected by it. See the threads:
- https://bbs.archlinux.org/viewtopic.php?id=152261
- https://bbs.archlinux.org/viewtopic.php?id=152019

Unfortunately, both are not solved, and it is not obvious which package(systemd, networkmanager, polkitd, ...) causes the problem. Also the first search results on the internet only point to Arch Linux. Therefore, I think it's Arch related and not really package related. For Mageia distro, there was also opened a bug report one year ago: https://bugs.mageia.org/show_bug.cgi?id=4509 (it was finally marked as "RESOLVED FIXED")

Maybe it's possible to narrow down the source of the problem.
Comment by Benedikt (Schwefelsaeure) - Thursday, 12 September 2013, 15:27 GMT
The slow startup was so annoying that I decided to reinstall Arch Linux completely. I used the ISO release 2013.09.01 (with kernel 3.10.10) and the problem is gone now. :) Therefore, I cannot help with this problem any longer.

Loading...