(gelöst) Trigger im JS verzögert - Unifi ist schuld

[ldittmar]

JavaScript: 8.3.1
JS-Controller: 5.0.19
Node.JS: 8.13.0
Unifi: 0.7.0

Ich habe ein komisches Problem der sich durch alle Blocklys erstreckt. Hier ein Beispiel:

Wenn ich mein Skript speichere und ausführe, dann funktioniert mein Trigger einwandfrei und ich bekomme das hier als Ergebnis im Log: (Ich logge den Zeitstempel des Klicks und dann die aktuelle Zeit)

2024-06-26 06:59:13.240 - info: javascript.0 (2719822) script.js.Schlafzimmer.Beleuchtung: 19900 04:59:13
2024-06-26 06:59:13.240 - info: javascript.0 (2719822) script.js.Schlafzimmer.Beleuchtung: 19900 04:59:13

Nach einiger Zeit verändert sich aber mein Ergebnis:

2024-06-26 20:51:29.695 - info: javascript.0 (2719822) script.js.Schlafzimmer.Beleuchtung: 19900 18:51:15
2024-06-26 20:51:29.695 - info: javascript.0 (2719822) script.js.Schlafzimmer.Beleuchtung: 19900 18:51:29

Wenn ich dann mein Script wieder neu Starte, dann funktioniert alles wie gewohnt. Es kommt auch vor, dass nach einer gewissen Zeit alles wieder nochmal funktioniert. Ich muss mal weiter forschen. Mit der Version, die ich davor hatte, war es nicht so. Leider weiß ich nicht mehr welche das war.

[ldittmar]

Hab mir jetzt die Daten vom Javascript Adapter angeschaut, aber noch nichts gefunden. Gestern Nacht hatte ich wieder die Verzögerung:

2024-06-29 01:13:06.510 - info: javascript.0 (2760319) script.js.Schlafzimmer.Beleuchtung: 19902 01:12:48
2024-06-29 01:13:06.510 - info: javascript.0 (2760319) script.js.Schlafzimmer.Beleuchtung: 19902 01:13:06

2024-06-29 01:13:16.441 - info: javascript.0 (2760319) script.js.Schlafzimmer.Beleuchtung: 19902 01:13:00
2024-06-29 01:13:16.441 - info: javascript.0 (2760319) script.js.Schlafzimmer.Beleuchtung: 19902 01:13:16

2024-06-29 01:18:48.280 - info: javascript.0 (2760319) script.js.Schlafzimmer.Beleuchtung: 19902 01:18:30
2024-06-29 01:18:48.281 - info: javascript.0 (2760319) script.js.Schlafzimmer.Beleuchtung: 19902 01:18:48

Heute Morgen sah es dann wieder gut aus:

2024-06-29 08:54:46.815 - info: javascript.0 (2760319) script.js.Schlafzimmer.Beleuchtung: 19903 08:54:46
2024-06-29 08:54:46.816 - info: javascript.0 (2760319) script.js.Schlafzimmer.Beleuchtung: 19903 08:54:46

2024-06-29 08:54:48.785 - info: javascript.0 (2760319) script.js.Schlafzimmer.Beleuchtung: 19903 08:54:48
2024-06-29 08:54:48.785 - info: javascript.0 (2760319) script.js.Schlafzimmer.Beleuchtung: 19903 08:54:48

Im Log fand ich nichts was das Verhalten erklären konnte. system.adapter.javascript.0.alive und system.adapter.javascript.0.connected waren die ganze Zeit auf true.

Die system.adapter.javascript.0.cpu hat sich so verhalten:

system.adapter.javascript.0.inputCount so:

Ein echt komisches Verhalten...

[ldittmar]

Habt ihr beim javascript Adapter auch solche CPU Ausschläge?

system.adapter.javascript.0.cpu

Diese Verzögerungen beim Trigger kommen immer wenn die CPU so stark belastet wird. Diese CPU Last tritt immer um 0:00, 5:00, 10:00, 15:00, 20:00 uhr und dauert etwa 1,5h...

[MartinP]

@ldittmar

JavaScript: 8.3.1
JS-Controller: 5.0.19
Node.JS: 8.13.0

Ist der Eintrag bei Node.JS ein Tippfehler?

Bei mir läuft der iobroker in einem LXC Container unter Proxmox, und zeigt keine Auffälligkeiten. (um ca 2:15 läuft das tägliche Backup)

[haus-automatisierung]

@ldittmar sagte in JavaScript Adapter 8.3.1 - Trigger reagiert verzögert:

Die system.adapter.javascript.0.cpu hat sich so verhalten:

Laufen denn um die Zeit irgendwelche rechenintensiven Aufgaben? Ist ja schon ein Muster zu erkennen.

[ldittmar]

@haus-automatisierung Genau so sieht es aus, aber ich kann mich nicht erinnern was gemacht zu haben. Hab auch jetzt alles Skripte ausgeschaltet, die ein bisschen mehr als Licht an/aus machen. Ich habe keiner Ahnung was das sein kann...

Welche Möglichkeiten habe ich zu erkennen was alle 5 Stunden im System passiert?

[OliverIO]

@ldittmar

es muss auch nicht immer iobroker sein, je nachdem für was der rechner noch genutzt wird, kann es der ein oder andere cron job sein.
wie oft machst du backup?
nutzt du eine datenbank?
ich weiß nicht wie oft jsonl/redis sich reorganisiert, aber ich glaube nicht in so großen abständen.

ansonsten kann man für linux mit sysstat werte zur prozessornutzung je prozess aufzeichnen und mit sar auswerten/ausgeben
https://wiki.debian.org/sysstat

wenn man den prozess weiß, der da für viel auslastung sorgt, schaut man dann weiter.
bei iobroker läuft jeder adapter in einem eigenen prozess.
beim javascript adapter mit vielen skripten wirds dann etwas schwieriger.

[ldittmar]

Ahh... jetzt habe ich ein Erfolgserlebnis. Hab fast alle Adapter ausgeschaltet und siehe da:

Um 20 Uhr war nichts mehr zu sehen... ich werde jetzt mal alle Adapter successiv einschalten und schauen was die hohe CPU Last produziert hat.

Bin mal gespannt was für ein Adapter der Übertäter ist. Was glaubt ihr?

Adapter    "admin"        : 6.17.14  , installed 6.17.14
Adapter    "alexa-shoppinglist": 0.1.5, installed 0.1.5
Adapter    "alexa2"       : 3.26.5   , installed 3.26.5
Adapter    "alias-manager": 1.2.6    , installed 1.2.6
Adapter    "awtrix-light" : 1.2.0    , installed 1.2.0
Adapter    "backitup"     : 2.11.0   , installed 2.11.0
Adapter    "ble"          : 0.14.0   , installed 0.14.0
Adapter    "bluelink"     : 2.3.6    , installed 2.3.6
Adapter    "broadlink2"   : 2.3.0    , installed 2.3.0
Adapter    "cloud"        : 5.0.1    , installed 5.0.1
Adapter    "daswetter"    : 3.1.15   , installed 3.1.15
Adapter    "devices"      : 1.1.5    , installed 1.1.5
Adapter    "discovergy"   : 0.5.13   , installed 0.5.13
Adapter    "discovery"    : 4.5.0    , installed 4.5.0
Adapter    "dwd"          : 2.8.5    , installed 2.8.5
Adapter    "echarts"      : 1.7.2    , installed 1.7.2
Adapter    "energiefluss" : 3.6.0    , installed 3.6.0
Adapter    "fahrplan"     : 1.2.3    , installed 1.2.3
Adapter    "fullybrowser" : 3.0.12   , installed 3.0.12
Adapter    "ham"          : 5.3.1    , installed 5.3.1
Adapter    "hm-rega"      : 4.0.0    , installed 4.0.0
Adapter    "hm-rpc"       : 1.17.0   , installed 1.17.0
Adapter    "homeconnect"  : 1.4.0    , installed 1.4.0
Adapter    "hue"          : 3.11.0   , installed 3.11.0
Adapter    "ical"         : 1.15.0   , installed 1.15.0
Adapter    "influxdb"     : 4.0.2    , installed 4.0.2
Adapter    "iot"          : 3.3.0    , installed 3.3.0
Adapter    "iqontrol"     : 2.3.0    , installed 2.3.0
Adapter    "javascript"   : 8.3.1    , installed 8.3.1
Controller "js-controller": 5.0.19   , installed 5.0.19
Adapter    "kecontact"    : 2.2.0    , installed 2.2.0
Adapter    "klf200"       : 1.2.0    , installed 1.2.0
Adapter    "logparser"    : 2.2.2    , installed 2.2.2
Adapter    "material"     : 1.3.1    , installed 1.3.1
Adapter    "mihome-vacuum": 4.2.0    , installed 4.2.0
Adapter    "modbus"       : 6.1.0    , installed 6.1.0
Adapter    "mqtt"         : 5.2.0    , installed 5.2.0
Adapter    "notification-manager": 1.1.2, installed 1.1.2
Adapter    "nut"          : 1.6.0    , installed 1.6.0
Adapter    "operating-hours": 1.0.6  , installed 1.0.6
Adapter    "philips-tv"   : 0.5.3    , installed 0.5.3
Adapter    "ping"         : 1.6.2    , installed 1.6.2
Adapter    "proxy"        : 1.3.2    , installed 1.3.2
Adapter    "radar-trap"   : 2.2.0    , installed 2.2.0
Adapter    "reolink"      : 1.1.0    , installed 1.1.0
Adapter    "ring"         : 5.0.10   , installed 5.0.10
Adapter    "roborock"     : 0.6.4    , installed 0.6.4
Adapter    "rpi2"         : 1.3.2    , installed 1.3.2
Adapter    "rssfeed"      : 2.9.7    , installed 2.9.7
Adapter    "simple-api"   : 2.8.0    , installed 2.8.0
Adapter    "smartthings"  : 0.0.4    , installed 0.0.4
Adapter    "snmp"         : 3.2.0    , installed 3.2.0
Adapter    "socketio"     : 6.7.0    , installed 6.7.0
Adapter    "sonos"        : 3.0.0    , installed 3.0.0
Adapter    "spotify-premium": 1.5.0  , installed 1.5.0
Adapter    "tado"         : 0.5.4    , installed 0.5.4
Adapter    "tankerkoenig" : 3.4.0    , installed 3.4.0
Adapter    "telegram"     : 3.3.2    , installed 3.3.2
Adapter    "tr-064"       : 4.3.0    , installed 4.3.0
Adapter    "tvspielfilm"  : 2.1.0    , installed 2.1.0
Adapter    "unifi"        : 0.7.0    , installed 0.7.0
Adapter    "vis"          : 1.5.6    , installed 1.5.6
Adapter    "vis-2"        : 2.9.32   , installed 2.9.32
Adapter    "vis-2-widgets-material": 1.3.32, installed 1.3.32
Adapter    "vis-2-widgets-radar-trap": 2.0.0, installed 2.0.0
Adapter    "web"          : 6.2.5    , installed 6.2.5
Adapter    "withings"     : 0.0.13   , installed 0.0.13
Adapter    "worx"         : 3.0.2    , installed 3.0.2
Adapter    "ws"           : 2.6.1    , installed 2.6.1
Adapter    "zigbee"       : 1.10.3   , installed 1.10.5

Admin, hm-raga, hm-rpc, influxdb, javascript, vis-2, web und zigbee kann ich schon mal ausschließen.

Nur Zur Info:

Platform       : linux
os             : linux
Architecture   : x64
CPUs           : 8
Speed          : 2804 MHz
Model          : 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz
RAM            : 62.4 GB
System uptime  : 197d. 07:02:00
Node.js        : v20.15.0
NPM            : 10.7.0
adapters count : 538
Disk size      : 914.4 GiB
Disk free      : 894.1 GiB

[OliverIO]

@ldittmar

javascript
wenn es einer der anderen wäre, gäb es bereits viel mehr beschwerden.
bei javascript kann der nutzer viel mehr falsch machen.
du kannst ja mal parallel die skripte durchschauen, die auf so einen zeitrythmus triggern

[Lucky_ESA]

@ldittmar Welchen Intervall hast du beim ical?
Eigentlich habe ich gedacht das ich Javascript an die Leistungsgrenze bringe aber deine Charts sehen nicht gut aus.
Liege bei inputCount im Durchschnitt bei 700. Nach jedem Start bekomme ich die üblichen Warnmeldungen von über 100 subscriptions und 8 Blocklys benötigen 6 Sekunden Ladezeit bis diese sichtvar werden.

Gruß//Lucky

[arteck]

@lucky_esa 700..phö

das ist mein Durchschnitt..

[ldittmar]

@OliverIO
Ich habe inzwischen alle Skripte angeschaut und getestet. Die waren auch fast alle aus und trotzdem kam diese periodische Auslastung.

@Lucky_ESA
Ich habe jetzt mal den ical eingeschaltet. Ich habe 5 Instanzen laufen. 3 davon holen die Daten nur einmal am Tag und 2 alle 3 Stunden. Bis jetzt verhält sich alles ruhig. Ich werte mit dem Javascript auch die Daten vom Kalender aus, aber scheinbar ist das nicht der Grund.

@arteck
Bei dir geht es aber richtig ab

So sieht es bei mir zur Zeit aus:

Man erkennt die deutlich, dass die Events weniger wurden....

[ldittmar]

@arteck @haus-automatisierung @Lucky_ESA @MartinP @OliverIO
Soo... ich habe den Übeltäter gefunden!!!

Zunächst meine aktuelle Grafik:

Wie man sieht langweilt sich die CPU jetzt. Keine extreme Ausschläge mehr.

Die Events sind natürlich mit der Anzahl an laufenden Instanzen gewachsen. Inzwischen sind alle Instanzen wieder an. Bis auf die eine... Sobald ich diese einschalte, springt meine CPU auf über 200% und das periodische Verhalten kommt wieder. Es geht um den Unifi-Adapter. Er überlastet mein NUC. Die Frage ist aber warum und wie der Unifi Adapter den Javascript Adapter lahm legt. Andere Adapter reagieren gar nicht drauf. Der JS-Controller geht auf 80% CPU Auslastung... aber der Javascript Adapt gleich auf 200%!!

Das Verhalten hatte ich früher definitiv nicht und am Unifi Adapter hat sich ja nichts geändert. Hab auch die alte Version probiert und es kommt das gleiche raus. Ist der JavaScript Adapter vielleicht "empfidlicher" geworden?

[OliverIO]

@ldittmar

verwendest du datenpunkte von den unifi geräten und lässt darauf im javascript triggern?
evtl senden die nun öfters daten und das javascript wird häufiger aufgerufen.
wenn da mehrere events pro sekunde kommen, dann könnte das schon passieren.
Je nachdem auch was da im javascript dann geprüft wird.

[ldittmar]

@oliverio ich habe ein Skript der Daten von Unifi nutzt, aber ich hatte es ausgeschaltet und trotzdem reagiert der Javascript Adapter total allergisch auf den Unifi Adapter. Ich schaue mir mal die Programmierung bei Gelegenheit an. Werde auf jedem Fall auch noch ein Ticket auf GitHub anlegen.

[ldittmar]

Sooo.... jetzt weiß ich warum der Adapter alle 5 Stunden auf 200% hoch geht. Eigentlich geht er nur so hoch beim ersten Start. Leider hat der Adapter immer wieder Probleme gemacht und nach einem Neustart, hat es wieder normal funktioniert. Also habe ich es alle 5 Stunden automatisch neu starten lassen.