Gentoo Forums
Gentoo Forums
Gentoo Forums
Quick Search: in
Systemd slow boot (NetworkManager) ?
View unanswered posts
View posts from last 24 hours

 
Reply to topic    Gentoo Forums Forum Index Desktop Environments
View previous topic :: View next topic  
Author Message
jhon987
Apprentice
Apprentice


Joined: 18 Nov 2013
Posts: 192

PostPosted: Tue Jun 03, 2014 11:02 am    Post subject: Systemd slow boot (NetworkManager) ? Reply with quote

hey guys,
I think I've emerged a new systemd revision a couple days ago, and since then I noticed some things have improved - such as journal flushing time on boot, however there are now new issues... perhaps some one here could help me fix them?
here are some logs:

Code:
systemd-analyze blame
         14.274s NetworkManager.service
         11.830s user@104.service
          9.779s polkit.service
          1.837s alsa-restore.service
          1.810s gpm.service
          1.764s systemd-logind.service
           998ms systemd-fsck-root.service
           879ms systemd-udev-settle.service
           835ms systemd-vconsole-setup.service
           779ms lvm2-activation-early.service
           746ms media-Windows.mount
           614ms colord.service
           601ms gdm.service
           577ms udisks2.service
           576ms dev-hugepages.mount
           554ms sys-kernel-debug.mount
           542ms systemd-modules-load.service
           520ms dev-mqueue.mount
           492ms systemd-udev-trigger.service
           464ms kmod-static-nodes.service
           339ms accounts-daemon.service

and also
Code:
systemd-analyze critical-chain
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

graphical.target @19.973s
└─multi-user.target @19.973s
  └─NetworkManager.service @5.699s +14.274s
    └─basic.target @5.651s
      └─timers.target @5.599s
        └─systemd-tmpfiles-clean.timer @5.580s
          └─sysinit.target @5.555s
            └─systemd-update-utmp.service @5.458s +89ms
              └─systemd-tmpfiles-setup.service @5.417s +27ms
                └─local-fs.target @5.398s
                  └─media-Windows.mount @4.645s +746ms
                    └─dev-sda2.device @4.570s

you may disregard the user@104.service (I added --start to xinitrc in one of my attempts to solve the issue) anyways, in my opinion it seems both NetworkManager and polkit are taking way too long to start (although polkit isn't mentioned on the critical chain) does anyone knows what can be done please?
Back to top
View user's profile Send private message
eccerr0r
Watchman
Watchman


Joined: 01 Jul 2004
Posts: 6355
Location: almost Mile High in the USA

PostPosted: Tue Jun 03, 2014 6:57 pm    Post subject: Reply with quote

What's it printing while starting up NetworkManager? What do you have as your default network connection?

BTW, I didn't know about these neat systemd tools:

Code:
           282ms gentoo-local-local.service
           225ms NetworkManager.service
           171ms systemd-udev-trigger.service
           166ms ModemManager.service
           128ms windows.mount
            72ms user@102.service
            70ms polkit.service
            63ms dev-mqueue.mount

- is what it looks like on my laptop (SSD). It does default to my WPA2-personal wifi port, not sure if it matters.
Back to top
View user's profile Send private message
jhon987
Apprentice
Apprentice


Joined: 18 Nov 2013
Posts: 192

PostPosted: Tue Jun 03, 2014 8:26 pm    Post subject: Reply with quote

First, thanks for replying.
eccerr0r wrote:
What's it printing while starting up NetworkManager?

do you mean dmesg?:
Code:
[    8.666725] Adding 1022972k swap on /dev/sda4.  Priority:-1 extents:1 across:1022972k
[    9.156699] systemd-journald[123]: Received request to flush runtime journal from PID 1
[    9.472888] usb 2-1.6: link qh8-0e01/ffff8800dac02b80 start 3 [1/2 us]
[   23.210167] r8169 0000:07:00.0 enp7s0: link down
[   23.210180] r8169 0000:07:00.0 enp7s0: link down
[   24.853730] r8169 0000:07:00.0 enp7s0: link up
[   24.913317] nvidia 0000:01:00.0: irq 66 for MSI/MSI-X
[  101.178312] pool (670) used greatest stack depth: 4312 bytes left

the above is the last bit of dmesg, the "slowness" starts at 9.472888] usb 2-1.6: link... that's about where networkmanager and polkit are starting. (if I'm not mistaking)
at the same time this is what I see in the boot log:
Code:
         Starting Accounts Service...
         Starting Authorization Manager...
[^[[32m  OK  ^[[0m] Started Authorization Manager.
[^[[32m  OK  ^[[0m] Started Accounts Service.
[^[[32m  OK  ^[[0m] Started Network Manager.

Quote:

What do you have as your default network connection?

I'm using a wired LAN connection, (for what it's worth I disabled ipv6 because my ISP doesn't support it yet, but I don't think it's relevant since I just now - after the problem has occurred - have added a -ipv6 to my useflags list)

Quote:
BTW, I didn't know about these neat systemd tools:

I'm glad I could introduce them to you.

BTW this is from Arch wiki - https://wiki.archlinux.org/index.php/systemd :
Quote:
Boot time increasing over time

After using systemd-analyze a number of users have noticed that their boot time has increased significantly in comparison with what it used to be. After using systemd-analyze blame NetworkManager is being reported as taking an unusually large amount of time to start.

The problem for some users has been due to /var/log/journal becoming too large. As such the solution is to remove every file within the folder (ideally making a backup of it somewhere, at least temporarily) and then setting a journal file size limit as described in #Journal size limit.
- it's not relevant...
but it's definitely a known bug, but no solution I could find... :(
Back to top
View user's profile Send private message
ferreirafm
Guru
Guru


Joined: 28 Jul 2005
Posts: 478
Location: Sao Paulo, Brazil

PostPosted: Thu Aug 14, 2014 3:57 pm    Post subject: Reply with quote

Don't know, but I think it's "normal". I have almost the same time for NM here.
After boot gmd hangs for three or four seconds before I see the login box.
However, any improvements are appreciated.
Best.

Code:
10.308s NetworkManager.service
          4.653s gdm.service
          3.272s systemd-logind.service
          3.270s gpm.service
          3.269s systemd-user-sessions.service
          1.937s accounts-daemon.service
          1.500s systemd-vconsole-setup.service
          1.209s systemd-fsck-root.service
           794ms dev-sda3.swap
           611ms systemd-sysctl.service
           550ms udisks2.service
           502ms sys-fs-fuse-connections.mount
           501ms dev-mqueue.mount
           448ms systemd-udev-trigger.service
           427ms tmp.mount
           423ms sys-kernel-config.mount
           363ms polkit.service
           341ms systemd-random-seed.service
           288ms colord.service
           267ms systemd-tmpfiles-clean.service
           255ms kmod-static-nodes.service
           238ms systemd-tmpfiles-setup.service
           215ms systemd-tmpfiles-setup-dev.service
Back to top
View user's profile Send private message
eccerr0r
Watchman
Watchman


Joined: 01 Jul 2004
Posts: 6355
Location: almost Mile High in the USA

PostPosted: Sat Aug 16, 2014 5:22 am    Post subject: Reply with quote

Something is really wrong. I don't think it's normal for NM to take that long to start but unsure why. This other SSD machine starts NetworkManager.servce in 138ms and it uses only Ethernet.

I'm wondering what networks you have defined, and whether you tried removing the networks and recreating them in nm-applet (or gnome-panel). I only have one profile for wired on this machine. It is set to "Connect Automatically" and my DHCP server is fairly quick at supplying leases (though NM/systemd should just let everything boot up even if it didn't get a lease, and then start up the dependent services once the lease is acquired.) You should also try setting it up to not connect automatically and see if there is any difference.

Note that on this machine, I can't run gdm, so I'm using slim as the login manager. Wish I could also show "gdm" as a started service here:

Code:
          1.150s systemd-udev-settle.service
          1.013s gentoo-local-baselayout1.service
           164ms root-swapfile.swap
           138ms NetworkManager.service
            90ms alsa-restore.service
            44ms systemd-remount-fs.service
            43ms libvirtd.service
            41ms systemd-udev-trigger.service
            40ms systemd-fsck-root.service
            28ms polkit.service
            26ms colord.service
            25ms udisks2.service
            23ms systemd-vconsole-setup.service
            11ms systemd-logind.service
            10ms accounts-daemon.service
             8ms sys-kernel-debug.mount
             8ms lvm2-activation-early.service
             7ms systemd-tmpfiles-setup-dev.service


I need to try installing systemd on a mechanical HDD system to see what the timing is like but I can't imagine it to be waiting a long time doing nothing, as that would also be very visible on an SSD machine - unless you can see the hdd thrashing while starting up NetworkManager? Both of these systemd machines I ran blame on are using RTL8169 Gbit ethernet as well (though the first one is using wifi).

Hmm...
_________________
Intel Core i7 2700K@ 4.1GHz/HD3000 graphics/8GB DDR3/180GB SSD
What am I supposed watching?
Back to top
View user's profile Send private message
dmpogo
Advocate
Advocate


Joined: 02 Sep 2004
Posts: 2395
Location: Canada

PostPosted: Sat Aug 16, 2014 6:22 am    Post subject: Reply with quote

It is suspicious that the link is twice down and then up. Looks like some timeout is hit, maybe even twice
(actually is the networking working after it is up ?). rtl driver may be loading firmware, although if it has trouble with that you usually get a record in dmesg. (*)


BTW, how many network cards do you have ? Could it be that it tries to bring up the disconnected one, times out twice (dhcpd usually times out in 6 or so sec, don't know about network manager) and then switches to the right one ?


(*) This was happen on my system - rtl driver, which worked just fine for almost 4 years, after upgrade of kernel and udev suddently complains that it cannot find a firmware - which I actually never had installed. Well, this is to debug for me tomorrow :)
Back to top
View user's profile Send private message
eccerr0r
Watchman
Watchman


Joined: 01 Jul 2004
Posts: 6355
Location: almost Mile High in the USA

PostPosted: Sat Aug 16, 2014 3:06 pm    Post subject: Reply with quote

I see that behavior on my system as well, despite my system booting NM fairly fast.
This is the networkmanager sequence of events that I see before Gnome starts:
Code:
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> NetworkManager (version 0.9.8.10) is starting...
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> Read config file /etc/NetworkManager/NetworkManager.conf
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> WEXT support is enabled
Aug 16 07:36:06 fujiko NetworkManager[1592]: Error parsing file '/etc/NetworkManager/NetworkManager.conf': No such file or directory
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> Loaded plugin keyfile: (c) 2007 - 2010 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Aug 16 07:36:06 fujiko NetworkManager[1592]: Error parsing file '/etc/NetworkManager/NetworkManager.conf': No such file or directory
Aug 16 07:36:06 fujiko NetworkManager[1592]: keyfile: parsing .keep_net-misc_networkmanager-0 ...
Aug 16 07:36:06 fujiko NetworkManager[1592]: Connection failed to verify: (unknown)
Aug 16 07:36:06 fujiko NetworkManager[1592]: keyfile:     error: invalid or missing connection property '(null)/connection setting not found'
Aug 16 07:36:06 fujiko NetworkManager[1592]: keyfile: parsing T-Mobile Internet*WebConnect ...
Aug 16 07:36:06 fujiko NetworkManager[1592]: keyfile:     read connection 'T-Mobile Internet/WebConnect'
Aug 16 07:36:06 fujiko NetworkManager[1592]: Error parsing file '/etc/NetworkManager/NetworkManager.conf': No such file or directory
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> monitoring kernel firmware directory '/lib/firmware'.
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> WiFi enabled by radio killswitch; enabled by state file
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> WWAN enabled by radio killswitch; disabled by state file
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> WiMAX enabled by radio killswitch; enabled by state file
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> Networking is enabled by state file
Aug 16 07:36:06 fujiko NetworkManager[1592]: <warn> failed to allocate link cache: (-26) Protocol mismatch
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> (enp4s0): carrier is OFF
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> (enp4s0): new Ethernet device (driver: 'r8169' ifindex: 2)
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> (enp4s0): exported as /org/freedesktop/NetworkManager/Devices/0
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> (enp4s0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> (enp4s0): bringing up device.
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> (enp4s0): preparing device.
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> (enp4s0): deactivating device (reason 'managed') [2]
Aug 16 07:36:06 fujiko NetworkManager[1592]: <info> Added default wired connection 'Wired connection 1' for /sys/devices/pci0000:00/0000:00:1c.2/0000:04:00.0/net/enp4s0
Aug 16 07:36:06 fujiko NetworkManager[1592]: <warn> /sys/devices/virtual/net/lo: couldn't determine device driver; ignoring...
Aug 16 07:36:06 fujiko NetworkManager[1592]: <warn> /sys/devices/virtual/net/lo: couldn't determine device driver; ignoring...

NM will then wait for link on Ethernet and complete the rest of the startup:
Code:
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> (enp4s0): carrier now ON (device state 20)
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> (enp4s0): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Auto-activating connection 'Wired connection 1'.
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) starting connection 'Wired connection 1'
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> (enp4s0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> NetworkManager state is now CONNECTING
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 1 of 5 (Device Prepare) started...
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 2 of 5 (Device Configure) scheduled...
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 1 of 5 (Device Prepare) complete.
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 2 of 5 (Device Configure) starting...
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> (enp4s0): device state change: prepare -> config (reason 'none') [40 50 0]
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 2 of 5 (Device Configure) successful.
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 3 of 5 (IP Configure Start) scheduled.
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 2 of 5 (Device Configure) complete.
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 3 of 5 (IP Configure Start) started...
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> (enp4s0): device state change: config -> ip-config (reason 'none') [50 70 0]
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> dhcpcd started with pid 1717
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Beginning IP6 addrconf.
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 3 of 5 (IP Configure Start) complete.
Aug 16 07:36:09 fujiko NetworkManager[1592]: <info> (enp4s0): DHCPv4 state changed nbi -> preinit
Aug 16 07:36:12 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 3 of 5 (IP Configure Start) starting DHCPv6 as requested by IPv6 router...
Aug 16 07:36:12 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Beginning DHCPv6 transaction (timeout in 45 seconds)
Aug 16 07:36:12 fujiko NetworkManager[1592]: <warn> the dhcpcd backend does not support IPv6.
Aug 16 07:36:16 fujiko NetworkManager[1592]: <info> wpa_supplicant started
Aug 16 07:36:18 fujiko NetworkManager[1592]: <info> (enp4s0): DHCPv4 state changed preinit -> bound
Aug 16 07:36:18 fujiko NetworkManager[1592]: <info>   address 10.0.0.61
Aug 16 07:36:18 fujiko NetworkManager[1592]: <info>   prefix 24 (255.255.255.0)
Aug 16 07:36:18 fujiko NetworkManager[1592]: <info>   gateway 10.0.0.1
Aug 16 07:36:18 fujiko NetworkManager[1592]: <info>   nameserver '205.171.3.25'
Aug 16 07:36:18 fujiko NetworkManager[1592]: <info>   nameserver '205.171.2.25'
Aug 16 07:36:18 fujiko NetworkManager[1592]: <info>   domain name 'Home'
Aug 16 07:36:18 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Aug 16 07:36:18 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 5 of 5 (IPv4 Commit) started...
Aug 16 07:36:19 fujiko NetworkManager[1592]: <info> (enp4s0): device state change: ip-config -> secondaries (reason 'none') [70 90 0]
Aug 16 07:36:19 fujiko NetworkManager[1592]: <info> Activation (enp4s0) Stage 5 of 5 (IPv4 Commit) complete.
Aug 16 07:36:19 fujiko NetworkManager[1592]: <info> (enp4s0): device state change: secondaries -> activated (reason 'none') [90 100 0]
Aug 16 07:36:19 fujiko NetworkManager[1592]: <info> NetworkManager state is now CONNECTED_GLOBAL
Aug 16 07:36:19 fujiko NetworkManager[1592]: <info> Policy set 'Wired connection 1' (enp4s0) as default for IPv4 routing and DNS.
Aug 16 07:36:19 fujiko NetworkManager[1592]: <info> Activation (enp4s0) successful, device activated.


The second half occurs asynchronously with bootup so it's hidden in the background. I don't see a wait for that 10 seconds except in the Gnome UI where it says "waiting for connection" but I can muck with nm-applet then...
_________________
Intel Core i7 2700K@ 4.1GHz/HD3000 graphics/8GB DDR3/180GB SSD
What am I supposed watching?
Back to top
View user's profile Send private message
ferreirafm
Guru
Guru


Joined: 28 Jul 2005
Posts: 478
Location: Sao Paulo, Brazil

PostPosted: Wed Aug 20, 2014 9:31 pm    Post subject: Reply with quote

eccerr0r wrote:
I'm wondering what networks you have defined, and whether you tried removing the networks and recreating them in nm-applet (or gnome-panel). I only have one profile for wired on this machine.

I have also just one profile. It's a wifi, however. Removing networks didn't change NM time. Perhaps you are right as the time is independent of the wifi connection itself.
eccerr0r wrote:
You should also try setting it up to not connect automatically and see if there is any difference.

Don't know how to set to not connect automatically. How can I do this?
eccerr0r wrote:
Note that on this machine, I can't run gdm, so I'm using slim as the login manager. Wish I could also show "gdm" as a started service here:

IMO, I think it has not anything to do with gdm. gdm delay seems to be related to nm-applet as they are started together in the .xinitrc.
If you get any clue, please drop me a line.
Best.

EDIT: correct drop instead droop
Back to top
View user's profile Send private message
Display posts from previous:   
Reply to topic    Gentoo Forums Forum Index Desktop Environments All times are GMT
Page 1 of 1

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum