Mailinglist Archive: opensuse-factory (443 mails)

< Previous Next >
Re: [opensuse-factory] wow
  • From: Marius Tomaschewski <mt@xxxxxxx>
  • Date: Wed, 29 Jan 2014 15:05:16 +0100
  • Message-id: <52E90A9C.80308@suse.de>
Am 28.01.2014 15:58, schrieb Kyrill Detinov:

On Fri, 24 Jan 2014 09:39:42 +0100 Peter Czanik wrote:

$SUBJECT is "wow" because I don't recall openSUSE booting ever so
fast! What was changed?

No "wow" here.

% systemd-analyze blame | head
20.848s wicked.service

This depends on the hardware and configuration. In my case with two intel nics [AFAIR ~3-4s for hw/kernel init] with dhcp4 + dhcp6 + bridge it is:

# systemd-analyze blame | grep wicked.service
13.615s wicked.service

Further, it is the starter service which basically waits (intentionally delays) an amount of time until the nics are configured.


But there is still enough room to improve / tune.

I'd like have hw-init + 3s at the end ... :-)


I've reconfigured my box to use 1 nic and rebooted several times to
see which part is slow:

wicked-1-nic-dhcp4+6.out: 13.370s wicked.service
wicked-1-nic-dhcp4.out: 13.419s wicked.service
wicked-1-nic-dhcp6.out: 7.675s wicked.service
wicked-1-nic-static.out: 3.682s wicked.service
wicked-lo-only.out: 43ms wicked.service


Basically, it is wickedd-dhcp4 which starts to send packets too *early*
[nic not yet ready] and runs into retransmissions with increased timers:

2014-01-29T13:42:51.798106+01:00 wickedd-dhcp4[1005]: sending DHCP4_DISCOVER with xid 0x2584a577
...
2014-01-29T13:43:00.802965+01:00 wickedd-dhcp4[1005]: nic0: retransmit request
2014-01-29T13:43:00.803303+01:00 wickedd-dhcp4[1005]: arming retransmit timer (9000 msec)
2014-01-29T13:43:00.805023+01:00 wickedd-dhcp4[1005]: sending DHCP4_REQUEST with xid 0x2584a578
2014-01-29T13:43:00.804278+01:00 wickedd-dhcp4[1005]: nic0: received DHCP4_OFFER message in state SELECTING
2014-01-29T13:43:00.805023+01:00 wickedd-dhcp4[1005]: sending DHCP4_REQUEST with xid 0x2584a578
2014-01-29T13:43:00.806017+01:00 wickedd-dhcp4[1005]: nic0: received DHCP4_ACK message in state REQUESTING
2014-01-29T13:43:00.811222+01:00 wickedd-dhcp4[1005]: arp_validate: probing for 172.16.20.4
2014-01-29T13:43:01.411374+01:00 wickedd-dhcp4[1005]: successfully validated 172.16.20.4
2014-01-29T13:43:01.417268+01:00 wickedd-dhcp4[1005]: nic0: committing lease

This needs to be addressed to work the right way. Even this, it works
and is not really worser than before.

A "modprobe af_packet" in StartPre of wickedd-dhcp4 should be a fast workaround.


Here some logs from the wickedd-dhcp6:, which shows the times
that the things need, when __almost__ everything is basically fine:

* "ip link set up" send and reported by kernel:

2014-01-29T13:44:13.759304+01:00 wickedd-dhcp6[1010]: nic0[2]: received interface event: device-up


* link goes up in the kernel:

2014-01-29T13:44:17.082206+01:00 kernel: [ 10.420396] IPv6: ADDRCONF(NETDEV_CHANGE): nic0: link becomes ready


* dhcp6 noticed link up event, but ipv6 is not yet ready:

2014-01-29T13:44:17.098535+01:00 wickedd-dhcp6[1010]: nic0: Link-local IPv6 address not (yet) available


* now ipv6 / the fe80... link-local address is ready:

2014-01-29T13:44:19.067329+01:00 wickedd-dhcp6[1010]: nic0: Found usable link-local IPv6 address: fe80::xxxxxxxxxx


* rfc wait [this can be skipped, we already were waiting for fe80,
but as you'll see below, the first packet is still send too early
and we need 1 retransmission ;-]

2014-01-29T13:44:19.069069+01:00 nic0: setting timeout to 1025 msec


* first packet sent out:

2014-01-29T13:44:20.093116+01:00 wickedd-dhcp6[1010]: nic0: SOLICIT message #1, xid 0x690d65 sent with 66 of 66 byte to ff02::1:2


* second packet send out [retransmission]:

2014-01-29T13:44:21.043018+01:00 wickedd-dhcp6[1010]: nic0: SOLICIT message #2, xid 0x690d65 sent with 66 of 66 byte to ff02::1:2


* response from dhcp6 server:

2014-01-29T13:44:21.057165+01:00 nic0: received REPLY message xid 0x690d65 in state SELECTING from fe80::xxxxxxxxxx
...
rapid-commit: enabled -> can commit it


* send lease to wickedd:

2014-01-29T13:44:21.060058+01:00 wickedd-dhcp6[1010]: dhcp6_protocol_event(ev=0, dev=2, uuid=9df7e852-6793-0b00-e403-000002000000)


* address applied to kernel:

2014-01-29T13:44:21.060969+01:00 wickedd[996]: Adding new interface address 2001:XXX:XXXX:XXXX::4/64
2014-01-29T13:44:21.061112+01:00 wickedd[996]: __ni_rtnl_send_newaddr(2001:XXX:XXXX:XXXX::4/64)


* address changed from "tentative" [dupplicate address check]
to "normal", wickedd-dhcp6 noticed this and schedules RENEW:

2014-01-29T13:44:22.170383+01:00 wickedd-dhcp6[1010]: nic0: Reached BOUND state, scheduled RENEW in 3599 sec

Gruesse / Regards,
Marius Tomaschewski <mt@xxxxxxx>, <mt@xxxxxxxx>
--
SUSE LINUX Products GmbH, HRB 16746 (AG Nürnberg),
GF: Jeff Hawn, Jennifer Guild, Felix Imendörffer,
Maxfeldstraße 5, 90409 Nürnberg, Germany
--
To unsubscribe, e-mail: opensuse-factory+unsubscribe@xxxxxxxxxxxx
To contact the owner, e-mail: opensuse-factory+owner@xxxxxxxxxxxx

< Previous Next >