Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

wicked is slow to start up at boot #681

Open
rombert opened this issue Nov 23, 2016 · 9 comments
Open

wicked is slow to start up at boot #681

rombert opened this issue Nov 23, 2016 · 9 comments

Comments

@rombert
Copy link

rombert commented Nov 23, 2016

Running on openSUSE Tumbleweed x86_64

$ rpm -q wicked
wicked-0.6.39-1.1.x86_64

Booting up is quite slow, and systemd-analyze points to wicked

# systemd-analyze blame | head -n 3
     16.792s wicked.service
      2.081s logrotate.service
      1.163s apparmor.service

The journal does not say much, pasting below the output. There is a large gap between "Committed DHCPv4 lease" and "Notified neighbours about IP address" though:


# journalctl -b | grep wicked
Nov 23 22:52:16 mars systemd[1]: Starting wicked AutoIPv4 supplicant service...
Nov 23 22:52:16 mars systemd[1]: Starting wicked DHCPv4 supplicant service...
Nov 23 22:52:16 mars systemd[1]: Starting wicked DHCPv6 supplicant service...
Nov 23 22:52:16 mars audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=wickedd-dhcp6 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 23 22:52:16 mars systemd[1]: Started wicked DHCPv6 supplicant service.
Nov 23 22:52:16 mars audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=wickedd-dhcp4 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 23 22:52:16 mars systemd[1]: Started wicked DHCPv4 supplicant service.
Nov 23 22:52:16 mars audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=wickedd-auto4 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 23 22:52:16 mars systemd[1]: Started wicked AutoIPv4 supplicant service.
Nov 23 22:52:16 mars systemd[1]: Starting wicked network management service daemon...
Nov 23 22:52:16 mars systemd[1]: Started wicked network management service daemon.
Nov 23 22:52:16 mars audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=wickedd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 23 22:52:16 mars systemd[1]: Starting wicked network nanny service...
Nov 23 22:52:16 mars systemd[1]: Started wicked network nanny service.
Nov 23 22:52:16 mars audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=wickedd-nanny comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 23 22:52:16 mars systemd[1]: Starting wicked managed network interfaces...
Nov 23 22:52:18 mars wickedd-dhcp4[1108]: enp6s0: Request to acquire DHCPv4 lease with UUID 80013658-de5f-0800-6904-000005000000
Nov 23 22:52:18 mars wickedd-dhcp6[1109]: enp6s0: Request to acquire DHCPv6 lease with UUID 80013658-de5f-0800-6904-000006000000 in mode auto
Nov 23 22:52:19 mars wickedd-dhcp4[1108]: enp6s0: Committed DHCPv4 lease with address 192.168.1.52 (lease time 86400 sec, renew in 43200 sec, rebind in 75600 sec)
Nov 23 22:52:19 mars wickedd[1129]: enp6s0: Notified neighbours about IP address 192.168.1.52
Nov 23 22:52:33 mars wicked[1147]: lo              up
Nov 23 22:52:33 mars wicked[1147]: enp6s0          up
Nov 23 22:52:33 mars systemd[1]: Started wicked managed network interfaces.
Nov 23 22:52:33 mars audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=wicked comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success
@okirch
Copy link
Contributor

okirch commented Nov 24, 2016 via email

@rombert
Copy link
Author

rombert commented Nov 24, 2016

Hi Olaf,

IPv6 is the key here, indeed. It is disabled on my router, but perhaps it's bugged. Enabling it in the router did not help, as there was still a long delay and I did not get an IPv6 address. But disabling it for my machine reduced the time greatly

# systemd-analyze blame | head -n 3
          3.370s wicked.service
          1.132s apparmor.service
          1.031s postfix.service

Not sure if this can be reduced more, but it's a great improvement. Can I somehow debug the IPv6 situation? I am not using IPv6 but perhaps there is something more to uncover here.

Thanks,

Robert

@mtomaschewski
Copy link
Member

mtomaschewski commented Nov 25, 2016 •
edited
Loading

Without the config, IPv6 RA dump and debug logs, I cannot say much about.

When you want to use DHCP4 only, use BOOTPROTO=dhcp4, when DHCP6 only BOOTPROTO=dhcp6. A BOOTPROTO=dhcp waits the time specified in DHCLIENT_WAIT_AT_BOOT and DHCLIENT6_WAIT_AT_BOOT (15sec) for both.
The DHCLIENT6_MODE=managed (or info) setting overrides the IPv6 RA settings sent by the router and causes that wickedd-dhcp6 does not wait for the RA but just starts to send dhcp6 requests once link-address (fe80::...) is ready to use.
There is also a kernel fix at this place I made, the packages are scheduled to be released
in next update run as I hope...

To tell you more what is going on, please first zypper install radvd and then open 3 root
terminals and start the following commands in them:

  1. radvdump | logger -s -t radvdump
  2. ip monitor all | | logger -s -t radvdump
  3. cursor=$(journalctl -n 1 -o export | grep ^__CURSOR=) ; cursor=${cursor#__CURSOR=}
    wicked ifdown all; ip link set up lo ; ip link set up eth0
    Adopt the eth0. Please wait until radvdump provides some output, then you can abort the
    running commands using Ctrl-C and then call journalctl -c "$cursor" -o short-precise > logs1.txt
    in terminal 3 to save the logs to logs1.txt.
    When ip monitor all fails (some versions do), use ip monitor help with list of all working objects.

Next step is to enable debug logging in wicked: perl -i -lpe 's{^(WICKED_DEBUG)=.*}{$1=all};s{^(WICKED_LOG_LEVEL)=.*}{$1=debug2}' /etc/sysconfig/network/config and reboot.
Using rcwickedd restart ; wicked ifup all will show different results that at boot, because the
HW is already initialized and the kernel is caching the IPv6 related settings on the devices.

After reboot, please collect the logs using journalctl -b -o short-precise > logs2.txt and the
wicked config using wicked show-config > config.txt and provide logs1.txt, logs2.txt and
config.txt to me somehow (by mail, paste url to them, ... attach in bugzilla.suse.com).
Please don't forget to XXXX-out everything you consider private in the logs.

@mtomaschewski
Copy link
Member

There is a large gap between "Committed DHCPv4 lease" and "Notified neighbours about IP address"
[...]
Nov 23 22:52:19 mars wickedd-dhcp4[1108]: enp6s0: Committed DHCPv4 lease with address 192.168.1.52 (lease time 86400 sec, renew in 43200 sec, rebind in 75600 sec)
Nov 23 22:52:19 mars wickedd[1129]: enp6s0: Notified neighbours about IP address 192.168.1.52

I can't see any, but "Committed" means, lease gets sent from wickedd-dhcp6 to wickedd, which receives it, verifies the address (duplicate address detection), sets the address on the device and announces it on the network (notify message).

After the address (and routes) are set, the lease is sent it to netconfig to update dns, nis and ntp. With DHCLIENT_SET_HOSTNAME=yes there is quite often (when dhcp server does not provide any) also a DNS reverse lookup of the IP address to hostname and set it in the system.

Finally, wickedd reports that this lease has been applied to nanny and wicked ifup and waits the remaining time of the 15sec for the another (dhcp6) lease to get applied before wicked ifup returns (wicked.service finishes).

@mtomaschewski
Copy link
Member

BTW: The DHCLIENT(6)_WAIT_AT_BOOT defaults cannot be lowered, because there may be e.g.:

  • primary dhcp server may be currently down and backup dhcp server answers with e.g. 5sec delay
  • some devices do not forward packets immediately after they reported a detected carrier, but perform e.g. STP internally or another things (or simply lie) and the initial packets may arrive on the IPv6 router and/or dhcp server for some time.

mtomaschewski added a commit to mtomaschewski/wicked that referenced this issue Nov 25, 2016
@mtomaschewski
dhcp6: defer on prefix event if RA flags are unset
469fee0 
When a RA prefix event arrives and the managed/other-config
RA flags are not set (dhcp not used on the network), send a
defer event to stop waiting for the lease in ifup.
[openSUSE#681]
@mtomaschewski mtomaschewski mentioned this issue Nov 25, 2016
Closed
@mtomaschewski
Copy link
Member

Test RPMs with pull #682 applied will appear at
http://download.opensuse.org/repositories/network:/wicked:/testing/
It should cause to stop waiting for dhcp6 in ifup when RA does not have managed/other-config
flag enabled (pure stateless autoconf aka auto6) but the ifcfg-file contains BOOTPROTO=dhcp.
But generally, the ifcfg file should contain e.g. BOOTPROTO=dhcp4 (if you want dhcp4)...

@fosspill
Copy link

I'd like to drop by and say thanks. I had a long, long startup time because wicked was waiting for a ipv6 lease. Disabling ipv6 on my system solved it! :)

@akontsevich
Copy link

I have disabled DHCPv6 in Yast however still have 45 sec timeout on OS start for wicked. What other problem could be, how to solve?

Can't use NetworkManager because of this problem:
https://forums.opensuse.org/showthread.php/538957-Network-sometimes-become-very-slow

@akontsevich
Copy link

Found solution here: https://www.reddit.com/r/openSUSE/comments/cbn0xk/slow_boot_time_because_of_wicked_and/ :

Modified etc/sysconfig/network/config and changed WAIT_FOR_INTERFACES from '30' to '1' solved it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@rombert @fosspill @mtomaschewski @akontsevich @okirch