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