You are not logged in.

Pages: 1 2

#1 2012-11-04 19:07:56

pntruongan
Member
Registered: 2011-01-31
Posts: 63

[gnome3.6, systemd]NetworkManager make polkit start extremely slow

I have been using gnome ever since and recently It got updated to 3.6. And thus I was forced to switch to systemd as well. Nothing break so far because I have follow the change to migrate settings away from rc.conf before. So Everything run fine after update. But the things is even though system boot quite fast at first, things change after I  re-enable Networkmanager with 

systemctl enable NetworkManager.service

Without NetworkManager, the system boot in less than 25 seconds. And I can start Networkmanager almost instantly after login with gdm. Hoever, Enable Network manager make polkit took more than 15 seconds to activating and Network manager itself took no less time to start.

Without NetworkManager this is the output of systemd-analyze blame

   778ms media-movie.mount
   298ms systemd-udevd.service
   226ms systemd-udev-trigger.service
   221ms systemd-remount-fs.service
   200ms systemd-vconsole-setup.service
   164ms systemd-sysctl.service
   155ms accounts-daemon.service
   129ms rc-local.service
   114ms ntpd.service
   103ms systemd-tmpfiles-setup.service
    87ms sys-kernel-debug.mount
    83ms media-data.mount
    82ms gdm.service
    74ms udisks2.service
    74ms dev-hugepages.mount
    67ms dev-mqueue.mount
    61ms colord.service
    60ms systemd-logind.service
    37ms rtkit-daemon.service
    27ms polkit.service
    15ms systemd-user-sessions.service
     8ms upower.service
     6ms tmp.mount
     2ms sys-fs-fuse-connections.mount

And when NetworkManager enabled bad become worse:

 19533ms NetworkManager.service
 18620ms polkit.service
  2846ms media-movie.mount
   596ms systemd-logind.service
   529ms ntpd.service
   447ms systemd-udevd.service
   439ms systemd-udev-trigger.service
   413ms systemd-vconsole-setup.service
   406ms systemd-remount-fs.service
   373ms systemd-sysctl.service
   343ms rc-local.service
   278ms gdm.service
   193ms media-data.mount
    97ms sys-kernel-debug.mount
    62ms dev-hugepages.mount
    61ms colord.service
    56ms dev-mqueue.mount
    51ms udisks2.service
    49ms systemd-tmpfiles-setup.service
    31ms rtkit-daemon.service
    21ms systemd-hostnamed.service
    15ms accounts-daemon.service
     9ms upower.service
     6ms tmp.mount
     6ms systemd-user-sessions.service
     6ms modem-manager.service
     4ms sys-fs-fuse-connections.mount

I googled around but was not able to find any clue. What was the problem and how can I fix it?

Offline

#2 2012-11-04 19:19:23

Scimmia
Fellow
Registered: 2012-09-01
Posts: 12,081

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

I've been having the same issue, haven't found a fix yet.

Online

#3 2012-11-04 20:36:25

MyLordAngus
Member
Registered: 2010-12-23
Posts: 10

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

You can try the command 

journalctl _SYSTEMD_UNIT=NetworkManager.service

to see all logs related to NetworkManager. Perhaps you will find something interesting.

Offline

#4 2012-11-05 02:49:06

pntruongan
Member
Registered: 2011-01-31
Posts: 63

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

MyLordAngus wrote:

You can try the command 

journalctl _SYSTEMD_UNIT=NetworkManager.service

to see all logs related to NetworkManager. Perhaps you will find something interesting.

I don't have much exprience to reading log so I could have missed something. But I found in the log that NetworkManager stall for 19s at the line
<info>Loading plugin keyfile
Is this a real problem and how to address it?

I include a portion of the log here in case I miss something that was more important:

-- Reboot --
Nov 05 09:19:08 pnta-laptop NetworkManager[365]: <info> NetworkManager (version 0.9.6.4) is starting...
Nov 05 09:19:08 pnta-laptop NetworkManager[365]: <info> Read config file /etc/NetworkManager/NetworkManager.conf
Nov 05 09:19:08 pnta-laptop NetworkManager[365]: <info> WEXT support is enabled
Nov 05 09:19:08 pnta-laptop NetworkManager[365]: <info> VPN: loaded org.freedesktop.NetworkManager.openvpn
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: <info> Loaded plugin keyfile: (c) 2007 - 2010 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing Auto K-KHMT ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'Auto K-KHMT'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing UIT VPN connection 1 ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'UIT VPN connection 1'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing Auto UIT-Staff ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'Auto UIT-Staff'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing Auto CTSV ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'Auto CTSV'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing Auto UIT.CTSV ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'Auto UIT.CTSV'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing sv2 ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'sv2'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing Viettel Mobile D-com 3G ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'Viettel Mobile D-com 3G'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing Auto Binh Duong ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'Auto Binh Duong'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing Auto Elearning ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'Auto Elearning'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing Auto UIT-Public ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'Auto UIT-Public'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing Auto Huong ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'Auto Huong'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing lab ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'lab'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing Auto UIT LAB ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'Auto UIT LAB'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile: parsing Wired connection 1 ...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: keyfile:     read connection 'Wired connection 1'
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: <info> trying to start the modem manager...
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: <info> monitoring kernel firmware directory '/lib/firmware'.
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: <info> rfkill1: found WiFi radio killswitch (at /sys/devices/pci0000:00/0000:00:1c.5/0000:02:00.0/bcma0:0/ieee80211/phy
Nov 05 09:19:27 pnta-laptop NetworkManager[365]: <info> rfkill0: found WiFi radio killswitch (at /sys/devices/platform/acer-wmi/rfkill/rfkill0) (platform driver acer-wm
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> WiFi enabled by radio killswitch; enabled by state file
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> WWAN enabled by radio killswitch; disabled by state file
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> WiMAX enabled by radio killswitch; enabled by state file
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> Networking is enabled by state file
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <warn> failed to allocate link cache: (-10) Operation not supported
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (eth0): carrier is OFF
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (eth0): new Ethernet device (driver: 'tg3' ifindex: 2)
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (eth0): exported as /org/freedesktop/NetworkManager/Devices/0
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (eth0): now managed
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (eth0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (eth0): bringing up device.
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (eth0): preparing device.
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (eth0): deactivating device (reason 'managed') [2]
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0): using nl80211 for WiFi device control
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0): new 802.11 WiFi device (driver: 'brcmsmac' ifindex: 3)
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0): exported as /org/freedesktop/NetworkManager/Devices/1
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0): now managed
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0): bringing up device.
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0): preparing device.
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0): deactivating device (reason 'managed') [2]
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <warn> /sys/devices/virtual/net/lo: couldn't determine device driver; ignoring...
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <warn> /sys/devices/virtual/net/lo: couldn't determine device driver; ignoring...
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> modem-manager is now available
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> wpa_supplicant started
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0) supports 4 scan SSIDs
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0): supplicant interface state: starting -> ready
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <warn> Trying to remove a non-existant call id.
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0): supplicant interface state: ready -> inactive
Nov 05 09:19:28 pnta-laptop NetworkManager[365]: <info> (wlan0) supports 4 scan SSIDs
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Auto-activating connection 'Auto K-KHMT'.
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) starting connection 'Auto K-KHMT'
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Activation (wlan0/wireless): connection 'Auto K-KHMT' has security, and secrets exist.  No new secrets needed.
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Config: added 'ssid' value 'K-KHMT'
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Config: added 'scan_ssid' value '1'
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Config: added 'psk' value '<omitted>'
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> Config: set interface ap_scan to 1
Nov 05 09:19:29 pnta-laptop NetworkManager[365]: <info> (wlan0): supplicant interface state: inactive -> scanning
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> (wlan0): supplicant interface state: authenticating -> associating
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> (wlan0): supplicant interface state: associating -> associated
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> (wlan0): supplicant interface state: associated -> 4-way handshake
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'K-KHMT'.
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0]
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> dhclient started with pid 427
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Beginning IP6 addrconf.
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Nov 05 09:19:30 pnta-laptop dhclient[427]: Internet Systems Consortium DHCP Client 4.2.4-P2
Nov 05 09:19:30 pnta-laptop dhclient[427]: Copyright 2004-2012 Internet Systems Consortium.
Nov 05 09:19:30 pnta-laptop dhclient[427]: All rights reserved.
Nov 05 09:19:30 pnta-laptop dhclient[427]: For info, please visit https://www.isc.org/software/dhcp/
Nov 05 09:19:30 pnta-laptop dhclient[427]: 
Nov 05 09:19:30 pnta-laptop NetworkManager[365]: <info> (wlan0): DHCPv4 state changed nbi -> preinit
Nov 05 09:19:30 pnta-laptop dhclient[427]: Listening on LPF/wlan0/5c:ac:4c:86:8f:d1
Nov 05 09:19:30 pnta-laptop dhclient[427]: Sending on   LPF/wlan0/5c:ac:4c:86:8f:d1
Nov 05 09:19:30 pnta-laptop dhclient[427]: Sending on   Socket/fallback
Nov 05 09:19:30 pnta-laptop dhclient[427]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) starting DHCPv6 as requested by IPv6 router...
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Beginning DHCPv6 transaction (timeout in 45 seconds)
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info> dhclient started with pid 498
Nov 05 09:19:33 pnta-laptop dhclient[498]: Internet Systems Consortium DHCP Client 4.2.4-P2
Nov 05 09:19:33 pnta-laptop dhclient[498]: Copyright 2004-2012 Internet Systems Consortium.
Nov 05 09:19:33 pnta-laptop dhclient[498]: Internet Systems Consortium DHCP Client 4.2.4-P2
Nov 05 09:19:30 pnta-laptop dhclient[427]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) starting DHCPv6 as requested by IPv6 router...
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Beginning DHCPv6 transaction (timeout in 45 seconds)
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info> dhclient started with pid 498
Nov 05 09:19:33 pnta-laptop dhclient[498]: Internet Systems Consortium DHCP Client 4.2.4-P2
Nov 05 09:19:33 pnta-laptop dhclient[498]: Copyright 2004-2012 Internet Systems Consortium.
Nov 05 09:19:33 pnta-laptop dhclient[498]: All rights reserved.
Nov 05 09:19:33 pnta-laptop dhclient[498]: For info, please visit https://www.isc.org/software/dhcp/
Nov 05 09:19:33 pnta-laptop dhclient[498]: 
Nov 05 09:19:33 pnta-laptop dhclient[498]: Bound to *:546
Nov 05 09:19:33 pnta-laptop dhclient[498]: Listening on Socket/wlan0
Nov 05 09:19:33 pnta-laptop dhclient[498]: Sending on   Socket/wlan0
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info> (wlan0): DHCPv6 state changed nbi -> preinit6
Nov 05 09:19:33 pnta-laptop dhclient[427]: DHCPACK from 192.168.137.1
Nov 05 09:19:33 pnta-laptop dhclient[427]: bound to 192.168.137.194 -- renewal in 245 seconds.
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info> (wlan0): DHCPv4 state changed preinit -> reboot
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info>   address 192.168.137.194
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info>   prefix 24 (255.255.255.0)
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info>   gateway 192.168.137.1
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info>   nameserver '192.168.137.1'
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info>   domain name 'mshome.net'
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Nov 05 09:19:33 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) started...
Nov 05 09:19:33 pnta-laptop dhclient[498]: XMT: Solicit on wlan0, interval 1030ms.
Nov 05 09:19:34 pnta-laptop NetworkManager[365]: <info> (wlan0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Nov 05 09:19:34 pnta-laptop NetworkManager[365]: <info> Policy set 'Auto K-KHMT' (wlan0) as default for IPv4 routing and DNS.
Nov 05 09:19:34 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) successful, device activated.
Nov 05 09:19:34 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) complete.
Nov 05 09:19:34 pnta-laptop dhclient[498]: XMT: Solicit on wlan0, interval 2040ms.
Nov 05 09:19:36 pnta-laptop dhclient[498]: XMT: Solicit on wlan0, interval 4020ms.
Nov 05 09:19:40 pnta-laptop dhclient[498]: XMT: Solicit on wlan0, interval 8150ms.
Nov 05 09:19:49 pnta-laptop dhclient[498]: XMT: Solicit on wlan0, interval 16530ms.
Nov 05 09:20:05 pnta-laptop dhclient[498]: XMT: Solicit on wlan0, interval 32980ms.
Nov 05 09:20:18 pnta-laptop NetworkManager[365]: <warn> (wlan0): DHCPv6 request timed out.
Nov 05 09:20:18 pnta-laptop NetworkManager[365]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 498
Nov 05 09:20:18 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
Nov 05 09:20:18 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) started...
Nov 05 09:20:18 pnta-laptop NetworkManager[365]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) complete.

Offline

#5 2012-11-05 11:20:42

Schwefelsaeure
Member
Registered: 2010-02-16
Posts: 17

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

Same problem here and haven't found a solution yet. For me, the problem have already been existing since Gnome 3.4.

Maybe, someone has a clue how to fix it.

Obviously, there is a problem with PolicyKit: "<error> [1352109216.403721] [nm-manager-auth.c:87] pk_authority_get(): Failed to initialize PolicyKit:"
But, see the attached logs below.

systemd-analyze blame

 43235ms NetworkManager.service
 39697ms polkit.service
  2004ms systemd-logind.service
  1908ms gdm.service
  ...

journalctl --this-boot _SYSTEMD_UNIT=NetworkManager.service

-- Logs begin at Sun, 2012-10-21 14:32:10 CEST, end at Wed, 2012-10-24 19:15:28 CEST. --
Nov 05 10:53:10 idefix NetworkManager[384]: <info> NetworkManager (version 0.9.6.4) is starting...
Nov 05 10:53:10 idefix NetworkManager[384]: <info> Read config file /etc/NetworkManager/NetworkManager.conf
Nov 05 10:53:10 idefix NetworkManager[384]: <info> WEXT support is enabled
Nov 05 10:53:11 idefix NetworkManager[384]: <info> VPN: loaded org.freedesktop.NetworkManager.openconnect
Nov 05 10:53:51 idefix NetworkManager[384]: <error> [1352109216.403721] [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
Nov 05 10:53:51 idefix NetworkManager[384]: <info> Loaded plugin keyfile: (c) 2007 - 2010 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Nov 05 10:53:51 idefix NetworkManager[384]: keyfile: parsing WLAN-7B4964 (automatisch) ...
Nov 05 10:53:51 idefix NetworkManager[384]: keyfile:     read connection 'WLAN-7B4964 (automatisch)'
Nov 05 10:53:51 idefix NetworkManager[384]: <info> trying to start the modem manager...
Nov 05 10:53:51 idefix NetworkManager[384]: <info> monitoring kernel firmware directory '/lib/firmware'.
Nov 05 10:53:51 idefix NetworkManager[384]: <info> rfkill0: found WiFi radio killswitch (at /sys/devices/pci0000:00/0000:00:1c.1/0000:03:00.0/ieee80211/phy0/rfkill0) (driver iwlwifi)
Nov 05 10:53:51 idefix NetworkManager[384]: <info> WiFi enabled by radio killswitch; enabled by state file
Nov 05 10:53:51 idefix NetworkManager[384]: <info> WWAN enabled by radio killswitch; enabled by state file
Nov 05 10:53:51 idefix NetworkManager[384]: <info> WiMAX enabled by radio killswitch; enabled by state file
Nov 05 10:53:51 idefix NetworkManager[384]: <info> Networking is enabled by state file
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (wlan0): using nl80211 for WiFi device control
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (wlan0): new 802.11 WiFi device (driver: 'iwlwifi' ifindex: 3)
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (wlan0): exported as /org/freedesktop/NetworkManager/Devices/0
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (wlan0): now managed
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (wlan0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (wlan0): bringing up device.
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (wlan0): preparing device.
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (wlan0): deactivating device (reason 'managed') [2]
Nov 05 10:53:51 idefix NetworkManager[384]: <warn> failed to allocate link cache: (-10) Operation not supported
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (eth0): carrier is OFF
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (eth0): new Ethernet device (driver: 'r8169' ifindex: 2)
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (eth0): exported as /org/freedesktop/NetworkManager/Devices/1
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (eth0): now managed
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (eth0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (eth0): bringing up device.
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (eth0): preparing device.
Nov 05 10:53:51 idefix NetworkManager[384]: <info> (eth0): deactivating device (reason 'managed') [2]
Nov 05 10:53:51 idefix NetworkManager[384]: <info> Added default wired connection 'Kabelgebundene Verbindung 1' for /sys/devices/pci0000:00/0000:00:1c.5/0000:06:00.0/net/eth0
Nov 05 10:53:51 idefix NetworkManager[384]: <warn> /sys/devices/virtual/net/lo: couldn't determine device driver; ignoring...
Nov 05 10:53:51 idefix NetworkManager[384]: <warn> /sys/devices/virtual/net/lo: couldn't determine device driver; ignoring...
Nov 05 10:53:51 idefix NetworkManager[384]: <info> wpa_supplicant started
Nov 05 10:53:52 idefix NetworkManager[384]: <info> (wlan0) supports 5 scan SSIDs
Nov 05 10:53:52 idefix NetworkManager[384]: <info> (wlan0): supplicant interface state: starting -> ready
Nov 05 10:53:52 idefix NetworkManager[384]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
Nov 05 10:53:52 idefix NetworkManager[384]: <warn> Trying to remove a non-existant call id.
Nov 05 10:53:52 idefix NetworkManager[384]: <info> (wlan0): supplicant interface state: ready -> inactive
Nov 05 10:53:52 idefix NetworkManager[384]: <info> (wlan0) supports 5 scan SSIDs
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Auto-activating connection 'WLAN-7B4964 (automatisch)'.
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Activation (wlan0) starting connection 'WLAN-7B4964 (automatisch)'
Nov 05 10:53:52 idefix NetworkManager[384]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Nov 05 10:53:52 idefix NetworkManager[384]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Activation (wlan0/wireless): connection 'WLAN-7B4964 (automatisch)' has security, and secrets exist.  No new secrets needed.
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Config: added 'ssid' value 'WLAN-7B4964'
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Config: added 'scan_ssid' value '1'
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Config: added 'auth_alg' value 'OPEN'
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Config: added 'psk' value '<omitted>'
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Nov 05 10:53:52 idefix NetworkManager[384]: <info> Config: set interface ap_scan to 1
Nov 05 10:53:52 idefix NetworkManager[384]: <info> (wlan0): supplicant interface state: inactive -> scanning
Nov 05 10:53:52 idefix NetworkManager[384]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Nov 05 10:53:52 idefix NetworkManager[384]: <info> (wlan0): supplicant interface state: authenticating -> associating
Nov 05 10:53:52 idefix NetworkManager[384]: <info> (wlan0): supplicant interface state: associating -> associated
Nov 05 10:53:57 idefix NetworkManager[384]: <info> (wlan0): supplicant interface state: associated -> 4-way handshake
Nov 05 10:53:57 idefix NetworkManager[384]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed
Nov 05 10:53:57 idefix NetworkManager[384]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'WLAN-7B4964'.
Nov 05 10:53:57 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
Nov 05 10:53:57 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
Nov 05 10:53:57 idefix NetworkManager[384]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0]
Nov 05 10:53:57 idefix NetworkManager[384]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Nov 05 10:53:57 idefix NetworkManager[384]: <info> dhclient started with pid 602
Nov 05 10:53:57 idefix NetworkManager[384]: <info> Activation (wlan0) Beginning IP6 addrconf.
Nov 05 10:53:59 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Nov 05 10:53:59 idefix dhclient[602]: Internet Systems Consortium DHCP Client 4.2.4-P2
Nov 05 10:53:59 idefix dhclient[602]: Copyright 2004-2012 Internet Systems Consortium.
Nov 05 10:53:59 idefix dhclient[602]: All rights reserved.
Nov 05 10:53:59 idefix dhclient[602]: For info, please visit https://www.isc.org/software/dhcp/
Nov 05 10:53:59 idefix dhclient[602]: 
Nov 05 10:53:59 idefix NetworkManager[384]: <info> (wlan0): DHCPv4 state changed nbi -> preinit
Nov 05 10:53:59 idefix dhclient[602]: Listening on LPF/wlan0/74:e5:0b:3e:99:ac
Nov 05 10:53:59 idefix dhclient[602]: Sending on   LPF/wlan0/74:e5:0b:3e:99:ac
Nov 05 10:53:59 idefix dhclient[602]: Sending on   Socket/fallback
Nov 05 10:53:59 idefix dhclient[602]: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 6
Nov 05 10:54:01 idefix dhclient[602]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Nov 05 10:54:01 idefix dhclient[602]: DHCPOFFER from 192.168.2.1
Nov 05 10:54:03 idefix dhclient[602]: DHCPACK from 192.168.2.1
Nov 05 10:54:03 idefix dhclient[602]: bound to 192.168.2.106 -- renewal in 134949 seconds.
Nov 05 10:54:03 idefix NetworkManager[384]: <info> (wlan0): DHCPv4 state changed preinit -> bound
Nov 05 10:54:03 idefix NetworkManager[384]: <info>   address 192.168.2.106
Nov 05 10:54:03 idefix NetworkManager[384]: <info>   prefix 24 (255.255.255.0)
Nov 05 10:54:03 idefix NetworkManager[384]: <info>   gateway 192.168.2.1
Nov 05 10:54:03 idefix NetworkManager[384]: <info>   nameserver '192.168.2.1'
Nov 05 10:54:03 idefix NetworkManager[384]: <info>   domain name 'Speedport_W_700V'
Nov 05 10:54:03 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Nov 05 10:54:09 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) started...
Nov 05 10:54:10 idefix NetworkManager[384]: <info> (wlan0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Nov 05 10:54:10 idefix NetworkManager[384]: <info> Policy set 'WLAN-7B4964 (automatisch)' (wlan0) as default for IPv4 routing and DNS.
Nov 05 10:54:10 idefix NetworkManager[384]: <info> Activation (wlan0) successful, device activated.
Nov 05 10:54:10 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) complete.
Nov 05 10:54:17 idefix NetworkManager[384]: <info> (wlan0): IP6 addrconf timed out or failed.
Nov 05 10:54:17 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
Nov 05 10:54:17 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) started...
Nov 05 10:54:17 idefix NetworkManager[384]: <info> Activation (wlan0) Stage 4 of 5 (IPv6 Configure Timeout) complete.

Last edited by Schwefelsaeure (2012-11-05 17:24:29)

Offline

#6 2012-11-08 17:19:07

pntruongan
Member
Registered: 2011-01-31
Posts: 63

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

A little bump for this thread. I'm using grub legacy (grub 0.97-21) could it be relate to the problem anyhow

Offline

#7 2012-11-09 13:03:23

MyLordAngus
Member
Registered: 2010-12-23
Posts: 10

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

I'm using Syslinux and I have no problem. Grub Legacy is not supported anymore, so you can upgrade to GRUB 2 or Syslinux, but I'm not sure the problem is related to the bootloader. If you have a problem with Polkit, maybe this command can help you

systemctl status polkit.service

Offline

#8 2012-11-12 11:43:35

Feydaykyn
Member
Registered: 2011-11-04
Posts: 11

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

Hi,
I got this problem too and things improved when I noticed it was asking my keyring key once I was logged, so I figured the gnome-keyring-daemon wasn't linked to my session. As a fix, I added to my .xinitrc :

eval $(/usr/bin/gnome-keyring-daemon --start --components=gpg,pkcs11,secrets,ssh)

Now a systemd-analyse --blame gives :
9951ms NetworkManager.service
8221ms polkit.service

I don't know if better speed can be achieved. I think I have some wireless network which are not system-wide too, so that may adds up. Ok now that's really better:

1698ms NetworkManager.service
...
14ms polkit.service

Last edited by Feydaykyn (2012-11-12 11:49:46)

Offline

#9 2012-11-14 03:32:04

pntruongan
Member
Registered: 2011-01-31
Posts: 63

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

Feydaykyn wrote:

Hi,
I got this problem too and things improved when I noticed it was asking my keyring key once I was logged, so I figured the gnome-keyring-daemon wasn't linked to my session. As a fix, I added to my .xinitrc :

eval $(/usr/bin/gnome-keyring-daemon --start --components=gpg,pkcs11,secrets,ssh)

Now a systemd-analyse --blame gives :
9951ms NetworkManager.service
8221ms polkit.service

I don't know if better speed can be achieved. I think I have some wireless network which are not system-wide too, so that may adds up. Ok now that's really better:

1698ms NetworkManager.service
...
14ms polkit.service

Hi Feydaykyn. Can you please give more detail of your fix? I'm using gdm and the gdm login screen take a really long time to show up. So what file should I edit? ~/.xinitrc or /etc/X11/xinit/xinitrc ?

Offline

#10 2012-11-14 05:18:02

Feydaykyn
Member
Registered: 2011-11-04
Posts: 11

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

Hi,

you  should édit your  ~/.xinitrc, hope  this  help :-)

Offline

#11 2012-11-17 16:39:24

pntruongan
Member
Registered: 2011-01-31
Posts: 63

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

Feydaykyn wrote:

Hi,

you  should édit your  ~/.xinitrc, hope  this  help :-)

It helped indeed. But I ran into another problem. Although your trick make systemd-analyze report a short boot time, the system in fact took a very long time to get to the point where I can type password in GDM. Anyways, thanks a lot for your work around I guess I will have something else to figure out and may be create another thread.

Offline

#12 2012-11-17 18:57:56

Feydaykyn
Member
Registered: 2011-11-04
Posts: 11

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

Have you tried to use the optimise daemon (see the systemd page) ?

Offline

#13 2012-11-18 05:48:08

pntruongan
Member
Registered: 2011-01-31
Posts: 63

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

Feydaykyn wrote:

Have you tried to use the optimise daemon (see the systemd page) ?

I've read the systemd page on arch wiki but I'm afraid I'm not aware off the optimise you mentioned. I don't use systemd read ahead, in favor of e4rat, can you give more hint please?

Offline

#14 2012-11-18 08:05:12

Feydaykyn
Member
Registered: 2011-11-04
Posts: 11

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

My bad I was thinking of the readahead daemon, in my case it helped speed up boot. I cannot help you further, sorry!

Offline

#15 2012-11-18 10:56:57

Raqua
Member
Registered: 2007-11-24
Posts: 146

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

I am having the same issue and I think it is probably realted to this error:
<error> [1353231207.431672] [nm-manager-auth.c:87] pk_authority_get(): Failed to initialize PolicyKit: (24) Error initializing authority: Error calling StartServiceByName for org.freedesktop.PolicyKit1: Timeout was reached

I have not found anything meaningful while trying to google it. Maybe some dev can shed a light here.

Offline

#16 2012-11-26 21:10:59

beaverusiv
Member
From: Taupo, New Zealand
Registered: 2011-07-09
Posts: 41

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

Feydaykyn wrote:

I got this problem too and things improved when I noticed it was asking my keyring key once I was logged, so I figured the gnome-keyring-daemon wasn't linked to my session. As a fix, I added to my .xinitrc :

eval $(/usr/bin/gnome-keyring-daemon --start --components=gpg,pkcs11,secrets,ssh)

Anyone know how this would translate to a KDE command (kwallet?).

Offline

#17 2012-11-26 23:48:28

Scimmia
Fellow
Registered: 2012-09-01
Posts: 12,081

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

*deleted*

Last edited by Scimmia (2012-11-26 23:56:48)

Online

#18 2012-11-27 11:42:43

Bastian
Member
Registered: 2012-05-17
Posts: 43

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

I can confirm this issue here. Got some pretty terrible boot times.

49650ms NetworkManager.service
  3662ms systemd-udevd.service
  2570ms systemd-vconsole-setup.service
  2141ms mnt-windows.mount
  2082ms systemd-remount-fs.service
  1993ms accounts-daemon.service
  1965ms colord.service
  1846ms polkit.service
  1764ms dev-mqueue.mount
  1744ms dev-hugepages.mount
  1733ms systemd-udev-trigger.service
  1691ms sys-kernel-debug.mount
  1610ms systemd-binfmt.service
   995ms proc-sys-fs-binfmt_misc.mount
   926ms systemd-logind.service
   909ms gdm.service
   686ms systemd-sysctl.service
   464ms udisks2.service
   361ms systemd-tmpfiles-setup.service
   173ms systemd-readahead-replay.service
   112ms systemd-hostnamed.service
   105ms systemd-readahead-collect.service
    94ms systemd-user-sessions.service
    91ms rtkit-daemon.service
    85ms upower.service
    11ms tmp.mount
     4ms wpa_supplicant.service
     1ms sys-fs-fuse-connections.mount

Offline

#19 2012-11-30 09:25:58

I-sty
Member
From: Romania
Registered: 2012-11-30
Posts: 60
Website

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

Hi,

Me too confirm this issue. But I am not using Gnome, I using XFCE.

17373ms NetworkManager.service
  3932ms psd.service
  1446ms laptop-mode.service
  1423ms systemd-logind.service
   814ms polkit.service
   701ms run-media-isty-Vegyes1.mount
   669ms udisks2.service
   624ms systemd-remount-fs.service
   556ms upower.service
   549ms systemd-udev-trigger.service
   480ms systemd-sysctl.service
   467ms dev-hugepages.mount
   454ms sys-kernel-debug.mount
   447ms lm_sensors.service
   428ms systemd-vconsole-setup.service
   423ms systemd-udevd.service
   418ms run-media-isty-Vegyes2.mount
   375ms dev-mqueue.mount
   336ms systemd-user-sessions.service
   217ms wpa_supplicant.service
   128ms udisks.service
   119ms systemd-tmpfiles-setup.service
    23ms tmp.mount
     1ms sys-fs-fuse-connections.mount

Offline

#20 2012-11-30 18:09:44

keepitsimpleengineer
Member
From: San Joaquin Valley, CA
Registered: 2012-06-25
Posts: 382

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

On an inexpensive laptop (Lenovo S12 Intel) running Gnome 3.6…

[root@KISE-007 Desktop]# systemd-analyze blame
 85761ms NetworkManager.service
  4436ms sshdgenkeys.service
  4426ms polkit.service
  3977ms accounts-daemon.service
  3952ms gdm.service
  2712ms systemd-remount-fs.service
  2680ms systemd-logind.service
  2479ms systemd-vconsole-setup.service
  2164ms systemd-binfmt.service
  1449ms systemd-sysctl.service
  1431ms dev-mqueue.mount
  1424ms dev-hugepages.mount
  1419ms sys-kernel-debug.mount
  1370ms proc-sys-fs-binfmt_misc.mount
  1211ms systemd-udevd.service
  1177ms systemd-udev-trigger.service
  1029ms wpa_supplicant.service
   919ms systemd-tmpfiles-setup.service
   605ms rtkit-daemon.service
   600ms colord.service
   417ms udisks2.service
   405ms systemd-user-sessions.service
   281ms tmp.mount
   227ms upower.service
   171ms dev-sda2.swap
     3ms sys-fs-fuse-connections.mount

Even worse, it drops the connection albeit after a long time and will not reconnect without restart (system on NetworkManager.service)

EDIT: I noticed dbus was starting after NetworkManager so I copied NetworkManager.service from /usr/lib/systemd/system/ to /etc/systemd/system/ and added the line "After=dbus.service" under "unit". and "systemd-analyze blame" reports "19568ms NetworkManager.service".

A little better...

Last edited by keepitsimpleengineer (2012-12-01 00:08:42)

Al Einstein: "Man soll die Dinge so einfach machen wie möglich ~ aber nicht einfacher." (Things should be as simple as possible ~ but not too simple.) ~ Al (Einstein) war ein Cousin von Albert, "Al" ist die Abkürzung für Aloysius

Offline

#21 2012-12-01 04:43:22

Joel
Member
From: Tijuana, BC, México
Registered: 2011-12-21
Posts: 122

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

Did you try change the manager with other liter, like wicd?

* PC: Intel Core 2 DUO E6550 @ 2.33 GHz with 2 GB RAM: Archlinux-i686 with xfce4.
* Laptop: Intel Core 2 DUO T6600 @ 2.20 GHz with 4 GB RAM: Archlinux-x86-64 with xfce4.
* AUR contributor.

Offline

#22 2012-12-03 08:10:00

Bastian
Member
Registered: 2012-05-17
Posts: 43

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

I suddenly start experiencing much faster bootups. Network Manager went from taking 50 seconds to boot to 6 seconds. I am still not quite sure how come. o_O

  6399ms NetworkManager.service
  4559ms systemd-tmpfiles-setup.service
  4283ms systemd-udevd.service
  3272ms systemd-vconsole-setup.service
  3167ms mnt-windows.mount
  1723ms systemd-remount-fs.service
  1693ms dev-hugepages.mount
  1665ms dev-mqueue.mount
  1615ms sys-kernel-debug.mount
  1424ms gdm.service
  1283ms systemd-binfmt.service
  1195ms systemd-sysctl.service
   802ms systemd-udev-trigger.service
   307ms systemd-logind.service
   268ms proc-sys-fs-binfmt_misc.mount
   238ms colord.service
   151ms systemd-user-sessions.service
   134ms systemd-readahead-replay.service
   122ms polkit.service
   117ms systemd-readahead-collect.service
    73ms rtkit-daemon.service
    50ms accounts-daemon.service
    27ms udisks2.service
    26ms wpa_supplicant.service
    21ms tmp.mount
     7ms upower.service
     1ms sys-fs-fuse-connections.mount

Offline

#23 2012-12-03 15:13:51

I-sty
Member
From: Romania
Registered: 2012-11-30
Posts: 60
Website

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

Hi,

For me since Dec 02 the network-manager's working perfecty at boot time.
plot

Here is some statistics.

Startup finished in 2330ms (kernel) + 17434ms (userspace) = 19765ms
Startup finished in 2265ms (kernel) + 19187ms (userspace) = 21453ms
Startup finished in 2246ms (kernel) + 20269ms (userspace) = 22516ms
Startup finished in 2324ms (kernel) + 18075ms (userspace) = 20400ms
Startup finished in 2248ms (kernel) + 18791ms (userspace) = 21040ms
Startup finished in 2407ms (kernel) + 27289ms (userspace) = 29696ms
Startup finished in 2451ms (kernel) + 25630ms (userspace) = 28082ms
Startup finished in 2374ms (kernel) + 22542ms (userspace) = 24916ms
Startup finished in 2252ms (kernel) + 8291ms  (userspace) = 10543ms
Startup finished in 2459ms (kernel) + 26011ms (userspace) = 28470ms
Startup finished in 2252ms (kernel) + 22347ms (userspace) = 24600ms
Startup finished in 2360ms (kernel) + 13106ms (userspace) = 15466ms
Startup finished in 15378ms (kernel) + 7838ms (userspace) = 23216ms
Dec 02:
Startup finished in 2534ms (kernel) + 8398ms  (userspace) = 10933ms
Startup finished in 29891ms (kernel) + 7982ms (userspace) = 37873ms
Dec 03:
Startup finished in 2766ms (kernel) + 8833ms (userspace) = 11600ms

The last dates is:

systemd-analyze blame
  3654ms NetworkManager.service
  2235ms udisks2.service
  2014ms upower.service
  1827ms systemd-logind.service
   986ms run-media-isty-Vegyes1.mount
   956ms systemd-remount-fs.service
   808ms polkit.service
   690ms run-media-isty-Vegyes2.mount
   609ms dev-hugepages.mount
   603ms sys-kernel-debug.mount
   573ms systemd-sysctl.service
   542ms dev-mqueue.mount
   506ms systemd-vconsole-setup.service
   311ms systemd-udevd.service
   300ms lm_sensors.service
   292ms udisks.service
   211ms systemd-user-sessions.service
   194ms systemd-udev-trigger.service
   169ms systemd-tmpfiles-setup.service
    69ms wpa_supplicant.service
    23ms tmp.mount
    12ms sys-fs-fuse-connections.mount
     1ms proc-sys-fs-binfmt_misc.mount

Offline

#24 2012-12-10 23:28:36

myle
Member
Registered: 2011-08-11
Posts: 35

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

Same problem here. I am not even using Gnome (but I have it installed).

$ systemd-analyze blame 
 24919ms NetworkManager.service
 11425ms polkit.service
  4198ms systemd-logind.service
  1253ms systemd-binfmt.service
  1226ms systemd-remount-fs.service
  1129ms systemd-udevd.service
  1123ms systemd-udev-trigger.service
  1030ms dev-mqueue.mount
  1003ms sys-kernel-debug.mount
   943ms dev-hugepages.mount
   890ms proc-sys-fs-binfmt_misc.mount
   870ms systemd-tmpfiles-setup.service
   842ms systemd-vconsole-setup.service
   423ms systemd-user-sessions.service
   263ms systemd-sysctl.service
   224ms console-kit-log-system-start.service
   140ms wpa_supplicant.service
   139ms home.mount
    90ms dev-sda1.swap
    89ms rtkit-daemon.service
    39ms mnt-downloads.mount
    27ms tmp.mount
     1ms sys-fs-fuse-connections.mount

Last edited by myle (2012-12-10 23:28:50)

Offline

#25 2012-12-11 00:14:03

keepitsimpleengineer
Member
From: San Joaquin Valley, CA
Registered: 2012-06-25
Posts: 382

Re: [gnome3.6, systemd]NetworkManager make polkit start extremely slow

keepitsimpleengineer wrote:

On an inexpensive laptop (Lenovo S12 Intel) running Gnome 3.6…

[root@KISE-007 Desktop]# systemd-analyze blame
 85761ms NetworkManager.service
  4436ms sshdgenkeys.service

Even worse, it drops the connection albeit after a long time and will not reconnect without restart (system on NetworkManager.service)

EDIT: I noticed dbus was starting after NetworkManager so I copied NetworkManager.service from /usr/lib/systemd/system/ to /etc/systemd/system/ and added the line "After=dbus.service" under "unit". and "systemd-analyze blame" reports "19568ms NetworkManager.service".

FWIW: I dropped Gnome3.6 and did a fresh install of Archlinus(2012-12-1)/Xfce4(4.1).

Now NetworkManager down to 9065ms, but still dropping wireless connection.

  9065ms NetworkManager.service
  3272ms systemd-logind.service
  2208ms polkit.service
  2075ms upower.service
  2046ms rtkit-daemon.service
  1334ms systemd-tmpfiles-setup.service
  1256ms tmp.mount
  1240ms sys-kernel-debug.mount
  1240ms wpa_supplicant.service
  1056ms systemd-remount-fs.service
  1054ms dev-hugepages.mount
  1048ms systemd-udev-trigger.service
  1020ms systemd-udevd.service
  1014ms dev-mqueue.mount
  1009ms systemd-vconsole-setup.service
   895ms systemd-sysctl.service
   876ms ntpd.service
   817ms udisks2.service
   513ms systemd-user-sessions.service
     3ms proc-sys-fs-binfmt_misc.mount

Last edited by keepitsimpleengineer (2012-12-11 00:17:26)

Al Einstein: "Man soll die Dinge so einfach machen wie möglich ~ aber nicht einfacher." (Things should be as simple as possible ~ but not too simple.) ~ Al (Einstein) war ein Cousin von Albert, "Al" ist die Abkürzung für Aloysius

Offline

Pages: 1 2

Board footer

Powered by FluxBB