| View previous topic :: View next topic |
| Author |
Message |
jhon987
Apprentice
Joined: 18 Nov 2013
Posts: 297
|
 Posted: Tue Jun 03, 2014 11:02 am Post subject: Systemd slow boot (NetworkManager) ? |
 |
|
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 |
|
 |
eccerr0r
Watchman
Joined: 01 Jul 2004
Posts: 9679
Location: almost Mile High in the USA
|
| Posted: Tue Jun 03, 2014 6:57 pm Post subject: |
|
|
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 |
|
|
jhon987
Apprentice
Joined: 18 Nov 2013
Posts: 297
|
| Posted: Tue Jun 03, 2014 8:26 pm Post subject: |
|
|
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 |
|
|
ferreirafm
Guru
Joined: 28 Jul 2005
Posts: 487
Location: Sao Paulo, Brazil
|
| Posted: Thu Aug 14, 2014 3:57 pm Post subject: |
|
|
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 |
|
|
eccerr0r
Watchman
Joined: 01 Jul 2004
Posts: 9679
Location: almost Mile High in the USA
|
| Posted: Sat Aug 16, 2014 5:22 am Post subject: |
|
|
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/Radeon R7 250/24GB DDR3/256GB SSD
What am I supposed watching? |
|
| Back to top |
|
|
dmpogo
Advocate
Joined: 02 Sep 2004
Posts: 3267
Location: Canada
|
| Posted: Sat Aug 16, 2014 6:22 am Post subject: |
|
|
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 |
|
|
eccerr0r
Watchman
Joined: 01 Jul 2004
Posts: 9679
Location: almost Mile High in the USA
|
| Posted: Sat Aug 16, 2014 3:06 pm Post subject: |
|
|
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/Radeon R7 250/24GB DDR3/256GB SSD
What am I supposed watching? |
|
| Back to top |
|
|
ferreirafm
Guru
Joined: 28 Jul 2005
Posts: 487
Location: Sao Paulo, Brazil
|
| Posted: Wed Aug 20, 2014 9:31 pm Post subject: |
|
|
| 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 |
|
|
|
Desktop Environments
