Hohe Load mit gluon testing (1.3~20181118) - Mehrfachaufrufe von dhcpv6.script br-client ra-updated

Hallo Forum!

Ich sehe bei meinem Node 64287-tuccity hohe Last, typisch > 0.4, mit Spikes von 1-1.5, auch wenn fastd nicht viel zu tun hat.
Wenn in top/ps dhcpv6.script br-client ra-updated auftaucht, sind das in der Regel gleich 3-8 Instanzen auf einmal, z.B.

 28291  1480 root     S     1340   2%   0% /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
 28289  1480 root     S     1340   2%   0% /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
 28290  1480 root     S     1340   2%   0% /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
 28293  1480 root     S     1340   2%   0% /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
 28292  1480 root     S     1340   2%   0% /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
 28294  1480 root     S     1340   2%   0% /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated

… was ich für die Ursache halte.

Das Ticket #1304 würde dazu passen, aber evtl. spielt auch etwas ffda-spezifisches rein und andere haben ähnliche Beobachtungen gemacht, deshalb das Posting hier.
(In meiner Nachbarschaft hat auch 64287-omnomcaek ähnlich hohe Loads, das ist aber ein 841er.)

Beobachtungen:

  1. Nach einem Downgrade auf beta (1.2.6 / gluon-v2018.1.1-4-g51b7928a) sind mit top/ps ebenfalls mehrere Instanzen sichtbar, Load ist aber im normalen Rahmen (typisch < 0.2). Zum Vergleich der Load-Graph (vom 19.-26.11. lief beta, danach testing).

Wahrscheinlich macht die in #1304 genannte Verringerung des Update-Delays auf 3 Sekunden das Problem einfach offensichtlicher.

  1. Ich hatte in dhcpv6.script einen Holzklotz-Limiter eingebaut, à la: wenn letzter Skript-Aufruf vor < 3 Sekunden => exit.
    Der Load ging zwar etwas runter (s. 15.-18.11. im Graph), es gab aber immer noch mehrere Instanzen. Ich denke, dass das Locking versagt, weil die Skript-Aufrufe quasi gleichzeitig stattfinden.

  2. script_call() in script.c killt bei einem neuen Aufruf das laufende Skript, k.A. was das für Nebenwirkungen hat. Jedenfalls kommen 10-15% der Instanzen, die es bis zum ersten echo "o-" >> test.log schaffen, nicht bis zum Ende des Skripts.

Weiss leider nicht, wie so ein RA-Update aufgebaut ist, oder was odhcp6c genau tut, kommt mir aber vor wie:
Ein Update mit n Einträgen wird geparst, aber im nächsten Schritt wie n einzelne Updates behandelt.
Die schlagen dann gleichzeitig auf, und das 3 Sekunden-Delay wird ausgehebelt.

HTH, Dustin

Firmware: 1.3~20181118 / gluon-v2018.1-127-g601f5df3 (gleiches Problem mit älteren Snapshots)
Geräte-Modell: TP-Link CPE210 v1.0

Wenn das erneut das Problem ist, dann können wir das leicht testen. Mein Vorschlag:

Ich bereite dir mal ein Testimage vor, wo ich den Delay wieder hochsetze. Das lässt du dann ein paar Tage laufen und dann sehen wir, ob das die Ursache der Load war.

Update: Kann man seit https://git.openwrt.org/?p=openwrt/openwrt.git;a=commit;h=05c3647d35bb6fe762b221f36f68d44cce15b963 einfach per UCI setzen. Probier also bitte mal

# uci set network.client.ra_holdoff=30
# uci commit network
# reboot

Hallo hexa,

das sieht schonmal viel besser aus, und reicht erstmal als vorläufiger Fix:

Version                    avg	   max        von - bis
1.2.6 (beta)               0.29    1.08       23.-26.11.
1.3.1 (testing)            0.74    2.58       26.-27.11.
1.3.1, ra_holdoff=30       0.26    1.25       27.-29.11.


Link zum Graphen

Die Mehrfachaufrufe sind immer noch da (aber die gab’s auch schon bei 1.2.6):

-----------------------------------------------------
OpenWrt 18.06-SNAPSHOT, r7391+11-0d549271d3
-----------------------------------------------------
root@64287-tuccity:~# while [ 1 ]; do l=`ps|grep "br-client ra-updated" |grep -v grep`; [ -n "$l" ] && (date; echo "$l") ; sleep 1 ;done > /tmp/ps_raupdated.log
^C
root@64287-tuccity:~# cat /tmp/ps_raupdated.log 
Fri Nov 30 01:36:14 CET 2018
25973 root      1340 R    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
25974 root      1340 R    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
25975 root      1340 R    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
25977 root      1340 R    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
25978 root      1340 R    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
Fri Nov 30 01:36:15 CET 2018
25977 root      1340 S    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
25978 root      1340 S    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
Fri Nov 30 01:36:51 CET 2018
26213 root      1340 R    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
26214 root      1340 R    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
26215 root      1340 R    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
26216 root      1340 R    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
26217 root      1340 R    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
Fri Nov 30 01:36:52 CET 2018
26211 root      1340 R    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
26213 root      1340 S    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
26214 root      1340 S    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
26215 root      1340 S    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
26216 root      1340 S    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
26217 root      1340 S    /bin/sh /lib/netifd/dhcpv6.script br-client ra-updated
Fri Nov 30 01:37:27 CET 2018
[5 Zeilen]
Fri Nov 30 01:37:28 CET 2018
[6 Zeilen]
Fri Nov 30 01:38:08 CET 2018
[6 Zeilen]
Fri Nov 30 01:38:09 CET 2018
[7 Zeilen]
...usw.

In script_call() ist wohl der Wurm drin…

  1. Zeile 400:
    - if (diff > delay)
    + if (diff < delay)
    , sonst ist delay immer <= 0, und der Child-Prozess rennt durch, ohne zu warten.

  2. Zeile 398, kill() fork() usw.
    Das laufende Skript zu killen und neu zu forken verbrennt IMHO unnötig Rechenzeit. Das Problem ist wohl, dass die DHCP-Einträge nur im Parent-Prozess aktualisiert werden, und die Einträge des Childs während des sleep(delay) veralten.
    Evtl. könnte man auf sleep() verzichten, und statt dessen z.B. mit waitpid(.. WNOHANG ..) testen, ob das Skript noch läuft. Falls nein && (now - last_update >= delay): neu forken.
    Trade-off: ein Update während des Delays wird nicht (gleich) umgesetzt.

  3. Anscheinend will man für RA-Updates ein delay von mind. 1 Sekunde (script_accu_delay = 1). Das kann aber schiefgehen, weil mit ganzen Sekunden gerechnet wird.

(4.) 1.-3. erklären wahrscheinlich noch nicht, warum es überhaupt zu mehreren gleichzeitigen(?) Updates kommt. (Soll/muss das so sein?)

Edit: Mein Vorschlag zu 2. taugt nichts. Bin davon ausgegangen, dass nach ein paar Sekunden sowieso das nächste Update kommt, aber es gibt ja auch andere Setups.
Wenn eine hohe Update-Frequenz die Regel und nicht die Ausnahme ist, ist die jetzige Methode sehr ineffizient.

Habe meine Änderung von oben mal in einen Commit für Gluon gefasst. Das Problem sollte daher bis zum Release von v2018.2 (bei uns v1.4.x) gelöst sein.

Das ist erstmal eine echte Verbesserung. Meine Befürchtung war auch, dass das jetzige Gluon-testing Nodes mit kleinerer Hardware ganz ausbremsen würde.

IMHO ist aber eher script_call() das Problem, evtl. auch die Verarbeitungsschritte davor. Bei einer anderen Implementierung wären Intervalle von 3 Sekunden wahrscheinlich unproblematisch.

Ich versuche erstmal, eine Firmware mit der geänderten Zeile 400 zu kompilieren, und schaue, was da rauskommt.
Das kill() müsste den Child-Prozess dann in der Regel schon bei sleep(delay) erwischen, nicht erst nach dem exec(). Das sollte schon jede Menge CPU-Zyklen einsparen.

Das aktuelle testing Release hat die Änderung bekommen.

Wenn du noch was an odhcp6c kritisieren willst würde ich vorschlagen die openwrt-dev Liste aufzusuchen.