Long wicked startup times when booting TW 4.15.13 aarch64 on Raspberry Pi-3B

I’ve occasionally checked systemd-analyze blame and then done some tuning to improve boot times (removing ModemManager and things like that). After the most recent update to 4.15.13 (booting off microSD rather than USB), I get this:

         30.265s wicked.service
          8.248s lvm2-monitor.service
          8.213s apparmor.service
          7.676s dev-mmcblk1p2.device
          6.277s ca-certificates.service
          6.111s systemd-hwdb-update.service
          2.564s initrd-switch-root.service
          1.659s smb.service
          1.468s wpa_supplicant.service
          1.454s systemd-journal-flush.service
          1.312s nmb.service
          1.154s sshd.service

I hadn’t seen such delays from wicked before (as best I can remember … I think I would have noticed a 30-sec delay).

Is anyone else seeing this kind of delay in wicked startup in an aarch64 TW RPi-3B environment? I’ve disabled IPv6 to try to speed it up – even removed the wickedd-dhcp6.service requests from wickedd.service – to no avail.

I’m not sure what else to look at or for. Any suggestions? Any other outliers in that blame listing that I might pay attention to?

Hi
Edit the /etc/sysconfig/networ/config file and set the WAIT_FOR_INTERFACE timeout to 0 also I set /etc/postfic/main.cf inet_protocols = ipv4

Wicked tuning:
1st: Check the systemd journal of the current boot for the time taken by the various network components:# journalctl --this-boot | grep -Ei ‘r8169|eth0|wicked|network|DHCP|ntp|nmb|smb’
Where ‘r8169’ is my physical Ethernet controller pointed to by “eth0”.

2nd: Tweak this “/etc/sysconfig/network/config” setting for the time taken from “systemd[1]: Reached target Host and Network Name Lookups” to “kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready” – I normally add 3 or 4 seconds extra to that time to allow the initial DHCP requests to complete. Note that, the final IPv6 DHCP request usually completes a second or two after everything else has completed:


## Type:        integer
## Default:     30
#
# Some interfaces need some time to come up or come asynchronously via hotplug.
# WAIT_FOR_INTERFACES is a global wait for all mandatory interfaces in
# seconds. If empty no wait occurs.
#
# WAIT_FOR_INTERFACES="30"
# WAIT_FOR_INTERFACES="12"
WAIT_FOR_INTERFACES="6"

And, also, this one if you have an “IPv6 forced by your ISP case”:


## Type:        string
## Default:     ""
#
# Allows to specify options to use when writting the /etc/resolv.conf,
# for example:
#       "debug attempts:1 timeout:10"
# See resolv.conf(5) manual page for details.
#
NETCONFIG_DNS_RESOLVER_OPTIONS="inet6 edns0 single-request single-request-reopen"

Some DSL Routers, when configured to be your DHCP server, need this in “/etc/sysconfig/network/dhcp”:


## Type:        yesno
## Default:     no
#
# Send a DHCPRELEASE to the server (sign off the address)? (yes|no)
# This may lead to getting a different address/hostname next time an address
# is requested. But some servers require it.
#
# DHCLIENT_RELEASE_BEFORE_QUIT="no"
DHCLIENT_RELEASE_BEFORE_QUIT="yes"

With these settings, my (AMD) Leap 42.3 boots are looking like this:


 > systemd-analyze
Startup finished in 2.305s (kernel) + 1.964s (initrd) + 17.157s (userspace) = 21.427s
 > systemd-analyze blame | head
          6.027s wicked.service
          5.330s nmb.service
          3.882s apparmor.service
          3.471s systemd-journal-flush.service
          1.593s home01.mount
          1.140s mysql.service
           735ms display-manager.service
           729ms plymouth-start.service
           668ms SuSEfirewall2.service
           603ms SuSEfirewall2_init.service
 > 

Ooops!! I’ve just now noticed that, the slow nmb server initialisation issue has returned … Normally the userspace time is about 5 seconds faster …

Thanks, Malcolm. Both looked like they’d be important parameters to change, but they made no difference:

         30.478s wicked.service
          9.171s lvm2-monitor.service
          8.879s apparmor.service
          8.705s dev-mmcblk0p2.device
          7.032s systemd-hwdb-update.service
          6.279s ca-certificates.service
          4.189s systemd-journal-flush.service
          2.506s initrd-switch-root.service
          1.773s smb.service
          1.294s sshd.service
          1.262s nmb.service

Off to try dcurtisfra’s suggestions for analysis and tuning. Post again after that.

For those thinking about this problem … please hold off! :slight_smile:

dcurtisfra’s suggestions below guided me in the right direction, I think, and I’m now analyzing the logs.

So I started here, and in looking at the first logs, I realized that the one change I made (that I can think of) prior to my last two zypper dup’s was to disconnect my eth0 cable … I’m now running strictly off wlan0, unlike when I was tuning earlier with ethernet connected.

So I plugged the ethernet cable back in and rebooted, and wicked’s launch time is now about 7 seconds.

It’s clear that something in the startup process is causing wicked (or something it depends upon) to wait for a long period (maybe 30 sec?).

I’m doing a log comparison now, but I don’t want to waste anyone else’s time trying to figure this out … with the analysis suggestions of dcurtisfra, I think I can get it.

I’ll post the results if I get it worked out.

Thanks, all!!

I looked in the places dcurtisfra suggested. Following Malcolm’s suggestion, I had already changed the WAIT to “0” with no effect. I’ve disabled IPv6 so I don’t think those parameters apply. So I don’t see anything else to do there.

Comparing the journalctl logs without and then with eth0 connected, I found the following differences in the logs:

Pi-6:/home/hdtodd # journalctl --this-boot | grep -Ei 'smsc95xx|wlan0|eth0|wicked|network|DHCP|ntp|nmb|smb'

Mar 28 08:28:08 Pi-6 wickedd[721]: ni_process_reap: process 782 has not exited yet; now doing a blocking waitpid()
Mar 28 08:28:08 Pi-6 wickedd[721]: ni_process_reap: process 784 has not exited yet; now doing a blocking waitpid()

Mar 28 08:28:10 Pi-6 kernel: smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xCDE1
Mar 28 08:28:10 Pi-6 wickedd-dhcp4[687]: eth0: Request to acquire DHCPv4 lease with UUID 588abb5a-c556-0700-d102-000006000000
Mar 28 08:28:11 Pi-6 wickedd-dhcp4[687]: eth0: Committed DHCPv4 lease with address 192.168.1.76 (lease time 86400 sec, renew in 43200 sec, rebind in 75600 sec)
Mar 28 08:28:11 Pi-6 avahi-daemon[694]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.76.
Mar 28 08:28:11 Pi-6 avahi-daemon[694]: New relevant interface eth0.IPv4 for mDNS.
Mar 28 08:28:11 Pi-6 avahi-daemon[694]: Registering new address record for 192.168.1.76 on eth0.IPv4.
Mar 28 08:28:15 Pi-6 wicked[764]: eth0            up

WITHOUT eth0 plugged in
Pi-6:/home/hdtodd # journalctl --this-boot | grep -Ei 'smsc95xx|wlan0|eth0|wicked|network|DHCP|ntp|nmb|smb'

Apr 06 15:23:12 Pi-6 wicked[761]: eth0            setup-in-progress

That is, aside from the exact sequence of some of the process completions, the only differences are in eth0 coming up vs being “setup-in-process” when there is no ethernet connection. But with the WAIT parameter set to “0” in both cases, I would have thought that eth0 setup-in-progress status would be irrelevant. [The Raspberry doesn’t have a battery-backed-up clock, so the logs start Mar 28, when the kernel was compiled, and jump to current date/time as soon as an IP connection is established to a time server. Curious to note that that seems to happen sooner with no EN cable connection, but I can’t think of an explanation.]

Comparing overall boot times without and with ethernet cabled, the timings look like this:

Apr 06 15:23:15 Pi-6 systemd[1]: Startup finished in 7.001s (kernel) + 4.220s (initrd) + 47.492s (userspace) = 58.714s.
Apr 06 15:23:19 Pi-6 systemd[1080]: Startup finished in 161ms.
Apr 06 15:34:15 Pi-6 systemd[1]: Startup finished in 7.001s (kernel) + 4.194s (initrd) + 25.140s (userspace) = 36.336s.
Apr 06 15:34:22 Pi-6 systemd[1249]: Startup finished in 159ms.

So there’s about 22 sec lost in userspace activity because the ethernet cable isn’t plugged in. And looking back several weeks in the journalctl log, every boot has been slowed by about that amount ever since I removed the EN connection.

I’ll continue to ponder this to see if I can figure out what’s causing the delay. If anyone has suggestions of where to look next, I’d welcome new ideas.

Got it!

Taking clues from both MalcolmLewis and dcurtisfra, I edited /etc/sysconfig/network/config to set

WAIT_FOR_INTERFACES="7"

rather than “0”.

Disconnected the Ethernet cable and rebooted, and got

Pi-6:/home/hdtodd # systemd-analyze blame
         16.343s apparmor.service
         15.748s lvm2-monitor.service
         15.488s dev-mmcblk0p2.device
         13.667s systemd-hwdb-update.service
          8.704s systemd-journal-flush.service
          8.008s systemd-tmpfiles-setup-dev.service
          7.317s wicked.service
          5.133s ca-certificates.service
          2.498s initrd-switch-root.service
          1.676s smb.service
          1.376s nmb.service
          1.328s sshd.service

So wicked is down to the same 7 sec whether or not the Ethernet cable is connected.

But I see that the top delayers are now taking about twice as long as they did before! Sigh.

Hope this helps others.

Never mind. Did another journalctl --vacuum-size=100M
and rebooted to get

Pi-6:/home/hdtodd # systemd-analyze blame
          7.337s wicked.service
          5.992s lvm2-monitor.service
          5.884s ca-certificates.service
          5.824s apparmor.service
          5.593s dev-mmcblk0p2.device
          4.000s systemd-hwdb-update.service
          2.524s initrd-switch-root.service
          1.662s smb.service
          1.423s nmb.service
          1.267s sshd.service
          1.175s systemd-journal-flush.service

with no Ethernet connection.

Fixed! Thanks Malcolm and dcurtisfra for your suggestions!

This started when I found that the boot time for Tumbleweed had gotten to be unreasonably long. I thought the cause would be a parameter in a config file. It turned out that the primary contributor was that I had moved from an Ethernet+wan0-connected configuration to a wan0-only configuration (that is, I had disconnected the Ethernet cable). Booting without the Ethernet connection cost approximately 25 seconds in boot time.

But I intended to leave this Pi as a wifi-only system (no Ethernet cable to it). And it seemed that there should be a parameter that would restore the faster boot time by telling wicked not to wait so long for network connections.

Following the suggestions of MalcolmLewis and dcurtisfra, I found that the long startup times were dependent upon the WAIT_FOR_INTERFACES parameter in /etc/sysconfig/network/config. Its default value is “30”; I’d seen before the suggestion to set it to “0” to speed up boot times, but I found that value didn’t help.

So I tried a variety of values for WAIT_FOR_INTERFACES and recorded the wicked startup times and the the systemd[1] startup times. Here are the results.

TW 4.15.13 aarch64 Raspberry Pi-3B Boot Times
Boot from microSD with Ethernet unplugged;
wlan0 activated; IPv6 disabled; using wicked
Dependence upon the setting for
WAIT_FOR_INTERFACES in /etc/sysconfig/network/config
journalctl --vacuum-size=100M between reboots
**WAIT setting
**
**
“”
“0”
“1”
“5”
“7”
“10”
“30”

It appears that the smallest non-zero setting is optimal for getting the fastest boot time in this particular environment (YMMV). Again, this is a very constrained environment: Tumbleweed 4.15.13 aarch64 on a Raspberry Pi-3B, booting off the microSD (not USB), and using the internal wlan0 and (disconnected) eth0.

Based upon these tests, I plan to leave WAIT_FOR_INTERFACES=“1” in my /etc/sysconfig/network/config file to optimize boot times. Cautions and forewarnings welcome. :wink:

Perhaps this information may help if you’re seeing long boot time on your openSUSE system.

Changed WAIT_FOR_INTERFACES in /etc/sysconfig/network/config from 30


erlangen:~ # systemd-analyze
Startup finished in 1.874s (kernel) + 840ms (initrd) + 18.165s (userspace) = 20.880s
graphical.target reached after 18.161s in userspace
erlangen:~ # systemd-analyze critical-chain |grep +
The time the unit takes to start is printed after the "+" character.
└─display-manager.service @16.638s +1.522s
  └─apache2.service @16.514s +114ms
      └─ntpd.service @16.465s +43ms
          └─wicked.service @1.140s +**15.320s**
            └─wickedd-nanny.service @1.131s +8ms
              └─wickedd.service @1.122s +7ms
                └─wickedd-auto4.service @1.091s +29ms
                            └─systemd-update-utmp.service @1.021s +3ms
                              └─auditd.service @1.004s +16ms
                                └─systemd-tmpfiles-setup.service @983ms +19ms
                                    └─home\x2dHDD.mount @742ms +237ms
                                        └─lvm2-monitor.service @176ms +561ms
erlangen:~ #

to 1

erlangen:~ # systemd-analyze
Startup finished in 1.880s (kernel) + 872ms (initrd) + 7.505s (userspace) = 10.258s
graphical.target reached after 7.494s in userspace
erlangen:~ # systemd-analyze critical-chain |grep +
The time the unit takes to start is printed after the "+" character.
  └─minidlna.service @2.286s +5.207s
      └─iscsi.service @2.254s +27ms
          └─wicked.service @1.209s +1.039s
            └─wickedd-nanny.service @1.200s +8ms
              └─wickedd.service @1.184s +14ms
                └─wickedd-dhcp4.service @1.145s +37ms
                            └─sys-fs-fuse-connections.mount @5.073s +39ms
                              └─systemd-modules-load.service @178ms +93ms
erlangen:~ # 

Any idea how to reduce wait for minidlna? Users don’t need it for graphical login.

Glad to see the reduced WAIT_FOR_INTERFACES helped your boot times so much.

Regarding minidlna: it isn’t part of the standard distribution for the Pi, so it isn’t running on mine. If it’s something you don’t use at all, you might just remove it (zypper rm minidlna). If it’s something you want to keep available but don’t usually use, you might just disable it (then re-enable when you want it):

sudo systemctl stop minidlna
sudo systemctl disable minidlna

It would be ideal to tie enabling/starting with a switch to graphical user interface (sudo systemctl set-default graphical) and then disable when you go back to multiuser mode. I’m pretty sure that’s possible, but I’m not facile enough with systemd configurations to be able to tell you exactly how to do that.

I had a closer look at systemd-analyze critical-chain. While a previous configuration had display-manager.service in the top of critical chain it’s gone with the new configuration. Thus users logging in actually need not wait for minidlna.service.

Please be aware that, there are two things which should be considered when configuring the Wicked “wait for interfaces” time:

  1. The time for the interface(s) to initialise: "kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
    "; 1. The time DHCP needs to assign at least an IPv4 address to the interface(s): "wickedd-dhcp4[1290]: eth0: Committed DHCPv4 lease with address 192.168.178.22 (lease time 864000 sec, renew in 432000 sec, rebind in 756000 sec)
    ".

Please be aware that, the Global IPv6 address will usually be available first after more than a few seconds.
DHCP and Avahi normally assign a “link” IPv6 address parallel to the IPv4 address assignment.

The interface setup takes some time regardless of the setting. However boot will not wait for completion but continue while setup is in progress:

hofkirchen:~ # journalctl -b -u wicked --output short-iso-precise 
-- Logs begin at Tue 2016-10-25 15:09:12 CEST, end at Mon 2018-04-09 11:45:52 CEST. --
2018-04-08T20:14:12.870431+0200 hofkirchen systemd[1]: Starting wicked managed network interfaces...
2018-04-08T20:14:13.907195+0200 hofkirchen wicked[1173]: lo              setup-in-progress
2018-04-08T20:14:13.907195+0200 hofkirchen wicked[1173]: enp0s25         enslaved
2018-04-08T20:14:13.907195+0200 hofkirchen wicked[1173]: br0             setup-in-progress
2018-04-08T20:14:13.908879+0200 hofkirchen systemd[1]: Started wicked managed network interfaces.
hofkirchen:~ # 

This works well on my machine.

Yes, yes, but, things such as the network services (Apache, Samba, & Co.) need the DHCP results before they can initialise.
The worst case I have is, the Samba nmd service – if it doesn’t have at least an IPv4 address available, it initially uses the loopback address and then blocks the smb service for 5 seconds before continuing …


 > systemd-analyze blame | grep -iE 'nmb|smb'
           406ms smb.service
           222ms nmb.service
 >