[gelöst] e1000e karte kommt erst hoch nachdem der networking.service schon gestartet ist

[reox]

Seit einiger Zeit braucht meine Workstation länger als gewohnt zum hochfahren. systemd-analyze zeigt, dass der networking.service ganze 17s braucht.
Der log dazu:

Code: Alles auswählen

# journalctl -u networking.service
-- Logs begin at Fri 2019-12-27 12:08:46 CET, end at Fri 2019-12-27 12:16:28 CET. --
Dez 27 12:08:47 helios systemd[1]: Starting Raise network interfaces...
Dez 27 12:08:47 helios dhclient[992]: Internet Systems Consortium DHCP Client 4.4.1
Dez 27 12:08:47 helios dhclient[992]: Copyright 2004-2018 Internet Systems Consortium.
Dez 27 12:08:47 helios dhclient[992]: All rights reserved.
Dez 27 12:08:47 helios dhclient[992]: For info, please visit https://www.isc.org/software/dhcp/
Dez 27 12:08:47 helios dhclient[992]: 
Dez 27 12:08:48 helios dhclient[992]: Listening on LPF/eth0/e8:40:f2:xx:xx:xx
Dez 27 12:08:48 helios dhclient[992]: Sending on   LPF/eth0/e8:40:f2:xx:xx:xx
Dez 27 12:08:48 helios dhclient[992]: Sending on   Socket/fallback
Dez 27 12:08:48 helios dhclient[992]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 5
Dez 27 12:08:53 helios dhclient[992]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 10
Dez 27 12:09:03 helios dhclient[992]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 12
Dez 27 12:09:04 helios dhclient[992]: DHCPOFFER of 172.16.23.136 from 172.16.23.1
Dez 27 12:09:04 helios dhclient[992]: DHCPREQUEST for 172.16.23.136 on eth0 to 255.255.255.255 port 67
Dez 27 12:09:04 helios dhclient[992]: DHCPACK of 172.16.23.136 from 172.16.23.1
Dez 27 12:09:05 helios dhclient[992]: bound to 172.16.23.136 -- renewal in 3467 seconds.
Dez 27 12:09:05 helios systemd[1]: Started Raise network interfaces.

Wenn ich dazu am DHCP server den log ausgeben lasse sehe ich aber folgendes:

Code: Alles auswählen

Dec 27 12:09:06 router dhcpd[1195]: DHCPDISCOVER from e8:40:f2:xx:xx:xx via br0
Dec 27 12:09:07 router dhcpd[1195]: DHCPOFFER on 172.16.23.136 to e8:40:f2:xx:xx:xx (helios) via br0
Dec 27 12:09:07 router dhcpd[1195]: DHCPREQUEST for 172.16.23.136 (172.16.23.1) from e8:40:f2:xx:xx:xx (helios) via br0
Dec 27 12:09:07 router dhcpd[1195]: DHCPACK on 172.16.23.136 to e8:40:f2:xx:xx:xx (helios) via br0

Mal abgesehen von dem 3s Zeitunterschied wird offenbar erst der Request von 12:09:03 vom DHCP server überhaupt ins log geschrieben. Die anderen tauchen dort gar nicht auf.
Auch mit tcpdump auf dem router sehe ich diese ersten paar DISCOVER ebenfalls nicht.
Dort sehe ich immer genau ein DISCOVER paket (das letzte), gefolgt von einem OFFER.

Meine Vermutung ist nun, dass die Netzwerkkarte zwar meldet, dass sie online ist aber die ersten beiden DISCOVER im nirvana verschwinden. Denn wenn ich ein dhclient starte, macht der genau einen DISCOVER und hat eine Adresse.
Zwischen der workstation und dem router hängt ein passiver Switch und es gibt keine VLANs oder sonst was, das da reinpfuschen würde.

Wenn ich den gesamten boot log anschaue, dann sehe ich da auch noch etwas anderes, was diese These erhärten würde (achtung, das ist ein anderer boot).
Der Netzwerktreiber wird um 13:19:58 geladen aber erst um 13:20:06 meldet der treiber, dass die karte "Up" ist. Der erste DISCOVER wird aber schon um 13:20:00 gesendet.
Und der erste DISCOVER nachdem die Karte oben ist erhält sofort das OFFER:

Code: Alles auswählen

Dez 27 13:19:58 helios kernel: e1000e: Intel(R) PRO/1000 Network Driver - 3.2.6-k
Dez 27 13:19:58 helios kernel: e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
Dez 27 13:19:58 helios kernel: e1000e 0000:00:19.0: Interrupt Throttling Rate (ints/sec) set to dynamic conservative mode
[...]
Dez 27 13:20:00 helios ifup[1060]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 5
[...]
Dez 27 13:20:06 helios kernel: e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
[...]
Dez 27 13:20:16 helios ifup[1060]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 17
Dez 27 13:20:17 helios ifup[1060]: DHCPOFFER of 172.16.23.136 from 172.16.23.1

Das problem ist aber offenbar, dass die ersten DISCOVERs durch das upscaling des intervals die zeit sehr lange nach hinten verzögern. Wenn zB kurz vor dem hochfahren der Karte noch ein DISCOVER gesendet wird, dann verzögert es das nächste um viele Sekunden.

Subjektiv kommt es mir so vor, als ob das früher nicht so war. Die Kiste war schon mal in weniger als 5s vom kernel bis lightdm oben... Ein offensichtlicher workaround ist, einfach eine statische addresse zu vergeben, was ich aber eher vermeiden wollte.
Sinnvoller wäre aber wohl, wenn systemd den networking.service erst startet, wenn die karte einen link hat. Dann sollte es zB in diesem Fall ganze 10s schneller gehen.
Ich hätte eigentlich erwartet, dass systemd das automatisch checkt oder zumindest ifupdown darauf rücksicht nimmt. Oder was genau ist bei meinem setup falsch?

Die Karte:

Code: Alles auswählen

       description: Ethernet interface
       product: 82579V Gigabit Network Connection
       vendor: Intel Corporation
       physical id: 19
       bus info: pci@0000:00:19.0
       logical name: eth0
       version: 04
       serial: e8:40:f2:xx:xx:xx
       size: 1Gbit/s
       capacity: 1Gbit/s
       width: 32 bits
       clock: 33MHz
       capabilities: pm msi bus_master cap_list ethernet physical tp 10bt 10bt-fd 100bt 100bt-fd 1000bt-fd autonegotiation
       configuration: autonegotiation=on broadcast=yes driver=e1000e driverversion=3.2.6-k duplex=full firmware=0.13-5 ip=172.16.23.136 latency=0 link=yes multicast=yes port=twisted pair speed=1Gbit/s
       resources: irq:28 memory:f7300000-f731ffff memory:f7339000-f7339fff ioport:f040(size=32)

[mat6937]

Seit einiger Zeit braucht meine Workstation länger als gewohnt zum hochfahren. systemd-analyze zeigt, dass der networking.service ganze 17s braucht.

Teste mal mit dem dhcp-Client aus systemd-networkd, statt mit dem dhclient.

[reox]

ja danke, offenbar klappt das besser:

Code: Alles auswählen

# cat /etc/systemd/network/80-dhcp.network 
[Match]            
Name=eth0
[Network]
DHCP=yes

# systemctl enable systemd-networkd

Das netzwerk braucht zwar immer noch ~20s bis es online ist (systemd-networkd-wait-online.service (20.207s)) aber immerhin kann er den window manager gleichzeitig laden.

Mir scheint irgendwo wurde da mal der ifupdown code verpfuscht - weil das hat ja eigentlich auch solche wait units.

[mat6937]

ja danke, offenbar klappt das besser:

Code: Alles auswählen

# cat /etc/systemd/network/80-dhcp.network 
[Match]            
Name=eth0
[Network]
DHCP=yes

# systemctl enable systemd-networkd

Das netzwerk braucht zwar immer noch ~20s bis es online ist (systemd-networkd-wait-online.service (20.207s)) aber immerhin kann er den window manager gleichzeitig laden.

Versuch mal auch mit einer [Link]-Section in deiner *.network-Datei:

Code: Alles auswählen

# cat /etc/systemd/network/80-dhcp.network 
[Match]            
Name=eth0
[LINK]
MACAddress=<MAC-Adresse-Interface>
RequiredForOnline=no
[Network]
DHCP=yes

(MAC-Adresse-Interface anpassen und ohne spitze Klammern).

RequiredForOnline=
Takes a boolean. When "yes", the network is deemed required when determining whether the system is online
when running "systemd-networkd-wait-online". When "no", the network is ignored when checking for online
state. Defaults to "yes".

The network will be brought up normally in all cases, but in the event that there is no address being
assigned by DHCP or the cable is not plugged in, the link will simply remain offline and be skipped
automatically by "systemd-networkd-wait-online" if "RequiredForOnline=no".

[reox]

Welchen genauen vorteil bringt das noch, außer das ich die zeit "verschleiere" bis die karte oben ist?
Ich denke mal, dass diese Einstellung eher für hosts gedacht ist wo tatsächlich nicht gewartet werden soll.
Es macht ja durchaus sinn, dass bestimmte dienste erst dann gestartet werden wenn netzwerk da ist ist.

[mat6937]

Es macht ja durchaus sinn, dass bestimmte dienste erst dann gestartet werden wenn netzwerk da ist ist.

Naja, es kommt drauf an. Man kann z. B. auch dann Dienste starten, die _nur_ an einem (W)LAN-Interface lauschen sollen, dem aber zum Zeitpunkt des Starts noch keine IP-Adresse zugewiesen ist bzw. zugewiesen werden kann. Das geht z. B. mit:

Code: Alles auswählen

net.ipv4.ip_nonlocal_bind = 1

in der "/etc/sysctl.conf"-Datei (oder gleichwertig).