Gelöst: iobroker-CT unter Proxmox stetiger Anstieg CPU-Last

[Wildbill]

Hi,

ich bräuchte mal einen Vorschlag oder Idee, wo ich noch suchen könnte. Ich habe iobroker als CT unter Proxmox (problemlos!) laufen. Alles funktioniert, schön und gut. Nur sehe ich in Proxmox, dass die CPU-Last des CT im Verlauf immer weiter zunimmt. Und ich kann es exakt am Javascript-Adapter festmachen. Starte ich den einmal neu, beginne ich wieder am unteren Ende und über die Tage/Wochen geht es wieder hoch. Hier mal ein Verlauf über den Monat. Da wo es runter geht, habe ich den JS-Adapter jeweils mal neu gestartet.

Betrachtet man das wochenweise, so sieht man, dass es täglich eine Hochphase gibt, die abends dann wieder runter geht, aber minimal höher bleibt, als vorher, so schaukelt es sich langsam hoch:

Die Zeiten sind jeweils exakt von 06:00 bis 20:00. Ich habe keine Scripte, die zu diesen Zeiten irgendetwas tun!

Was habe ich schon gecheckt:
Neustart des JS-Adapters setzt die CPU-Last sofort wieder auf den tiefsten Wert, es geht dann über Tage Wochen nach oben.
Skripte alle mal angehalten und neu gestartet, ohne den JS-Adapter neu zu starten: Der Wert bleibt oben, also scheint es nicht an irgendeinem Script zu liegen

Hat der JS-Adapter da ein Leak? Es läuft Version 4.8.4, die aktuelle aus dem Stable. Was macht der JS-Adaper oder iobroker von 06:00-20:00, dass die Last ansteigt, obwohl da nicht mehr Skripte laufen als nachts, schon gar nicht so exakt zeitlich gestartet. Im Container ist nur iobroker, die Screenshots zeigen direkt die CPU-Last des Containers, nicht des gesamten Proxmox-NUC. Zugewiesen sind 2 CPU-Core mit cpulimit=1 und 5GB an RAM.

Wo kann ich weiter ansetzen, um dem auf die Spur zu kommen. Es läuft alles perfekt und bis mein NUC deswegen an die Grenzen kommt würde es wohl eher Jahre dauern, aber irgendwas passt ja anscheinend nicht, und das nervt mich...
Alle anderen CT und VM auf diesem und einem weiteren mit Proxmox zeigen kein solches Verhalten, nur der eine mit iobroker und da scheint es der JS-Adapter zu sein.
Gruss, Jürgen

[UncleSam]

@Wildbill Wow, danke für die sehr detaillierte Analyse! Kannst du bitte für die Adapter-Entwickler ein Issue auf GitHub erfassen? https://github.com/ioBroker/ioBroker.javascript/issues

Mit NodeJS kann man CPU und RAM Profile erstellen und diese Auswerten. Ich denke, die Entwickler werden nicht darum herum kommen, sich das anzuschauen.

Aber noch eine Frage: hast du in deinem gesamten ioBroker (oder der gesamten Hausautomation) etwas, das von 6 bis 20 Uhr läuft? Es könnte nämlich auch sein, dass gewisse State Changes zu erhöhtem CPU-Bedarf führen.

Interessant wäre, wenn du mit History und Flot (oder anderem Diagramm-Adapter) mal eine Grafik des JavaScript Adapters machen könntest.
Diese zwei Werte wären vor allem von Interesse:

Um die Werte zu sehen, musst du auf Experten-Modus wechseln:

[Wildbill]

@UncleSam Danke für den Vorschlag. Ich lasse die beiden Datenpunkte (aktuell 492 bei in und 11 bei out) mal in influx loggen und schaue mal, wie sich das bis morgen so über 24 Stunden verhält. Dann schreibe ich es mal hier und mache in Issue bei Github auf.
Ansonsten habe ich (zumindest bewusst) nichts Laufen, was speziell in diesem Zeitraum läuft. Es gibt zwar den heatingcontrol-Adapter der heute um 6 die Heizkörper hoch fuhr. Aber der läuft erst seit ein paar Wochen, das "Problem" hatte ich schon länger beobachtet. Zudem passiert es auch an Wochenenden zu den gleichen Zeiten, und da fährt die Heizung später an. Ich beobachte und melde mich wieder.

Gruss, Jürgen

[Wildbill]

@UncleSam So, der Fall scheint irgendwie klar. Hier mal der Flot-Chart mit inputCount, outputCount und CPU:

Ich habe zumindest jetzt eine Vermutung, was hinter den täglichen Anstiegen morgens und dem Abfallen abends steckt. Das konnte ich jetzt eben live beobachten, als die ersten Spikes auftauchten. Ich habe einen Homematic-Helligkeitssensor. Der sendet so alle 3 Minuten einen Wert (wenn die Helligkeit sich ändert, also nicht nachts) an Pivccu und von da an iobroker. Dann habe ich zwei Skripte, die mit dem Wert was machen. Das erste schreibt ihn in eine lokale Datei, die dann ein Cron-Job außerhalb iobroker an einen anderen Rechner mit weewx sendet. Das Skript scheint für mich korrekt:

Spoiler

var fs = require('fs');                           // enable write

// neu
on({id: 'hm-rpc.0.OEQ2282208.1.LUX', change: "ne"}, function (obj) {

//function Illuminance_Schreiben () 

//{

var currIllu = getState("hm-rpc.0.OEQ2282208.1.LUX").val;    // Lese aktuelle Illuminance


var string = " ";



// erzeuge Excel String

   string = currIllu +  "\n";



// Füge Satz in Datei ein

fs.writeFileSync("/home/major/illuminance.txt", string);   



});



// jeden Tag um 12:00 "0 12 * * *"  

//schedule("* * * * *" , Illuminance_Schreiben); // alle 5 Minuten zur vollen Minute

//Illuminance_Schreiben(); // bei Scriptstart

Das zweite ist ein Blockly-Skript, welches den Wert in einen Datenpunkt schreibt, um den alten Wert zu haben. sowie ihn synchron mit einem eigenen Datenpunkt hält. Hier das Blockly als JS-Export:

Spoiler

on({id: 'hm-rpc.0.OEQ2282208.1.LUX', change: "ne"}, function (obj) {
 var value = obj.state.val;
 var oldValue = obj.oldState.val;
 setStateDelayed("javascript.0.Zustand.Lichtsensor-alt"/*Lichtsensor-alt*/, (obj.state ? obj.state.val : ""), 120000, false);
 on({id: 'hm-rpc.0.OEQ2282208.1.LUX', change: "ne"}, function (obj) {
   setState('javascript.0.Zustand.Beleuchtungsstärke', obj.state.val);
 });});

Die Fragen sind nun:
Warum wird durch diese zwei Skripte (damit scheint es ja 1:1 irgendwie zusammenzuhängen) so viel input- und outputCount erzeugt. Ist das normal oder habe ich da einen Fehler drin?
Kann der CPU-Anstieg über Tage Wochen damit zusammenhängen, oder sind hier zwei Probleme überlagert und der JS-Controller hat doch einen BUG/LEAK und ich sollte in Issue aufmachen, aber dann mit welchen Werten?

Gruss, Jürgen

[UncleSam]

@Wildbill Ich würde sagen, das sind zwei unterschiedliche Probleme. Für den stetigen Anstieg würde ich ein Issue eröffnen. Das andere muss ich mir nächste Woche mal in Ruhe anschauen, wenn ich wieder am PC bin.

[AlCalzone]

@Wildbill sagte in iobroker-CT unter Proxmox stetiger Anstieg CPU-Last:

Neustart des JS-Adapters setzt die CPU-Last sofort wieder auf den tiefsten Wert, es geht dann über Tage Wochen nach oben.
Skripte alle mal angehalten und neu gestartet, ohne den JS-Adapter neu zu starten: Der Wert bleibt oben, also scheint es nicht an irgendeinem Script zu liegen

Ein paar Ideen:

1. Erstellst du in deinem Skripten dynamisch Trigger/Schedules/etc.? Z.B. als Reaktion auf bestimmte Events des Tages
2. Startest und stoppst du Skripte per scriptEnabled-States?

zu 1.: Wenn das nicht sauber passiert, kann es sein, dass mit der Zeit mehrfache Trigger für die gleichen States existieren. Bei jedem Auslösen wird dann mit der Zeit immer mehr Arbeit verrichtet, sprich die CPU-Last steigt.
Solche "vergessenen" Trigger werden dann u.u. beim Neustart der Skripte nicht sauber entfernt - wohl aber beim Neustart des Adapters.

zu 2.: Sollte man grundsätzlich nicht machen und hat in der Vergangenheit schon oft zu Problemen geführt. Gerade in Kombination mit 1. könnte es das Problem noch verstärken.

[AlCalzone]

@Wildbill Und mit deinem zweiten Skript hast du meine Vermutung bestätigt:

on({id: 'hm-rpc.0.OEQ2282208.1.LUX', change: "ne"}, function (obj) {

 var value = obj.state.val;

 var oldValue = obj.oldState.val;

 setStateDelayed("javascript.0.Zustand.Lichtsensor-alt"/*Lichtsensor-alt*/, (obj.state ? obj.state.val : ""), 120000, false);

 on({id: 'hm-rpc.0.OEQ2282208.1.LUX', change: "ne"}, function (obj) {

   setState('javascript.0.Zustand.Beleuchtungsstärke', obj.state.val);

 });});

Das ist ein Trigger im Trigger. Jeder Auslöser des Äußeren (Zeile 1) erstellt eine neue Kopie des inneren (Zeile 9). Mit jedem Auslösen des States hm-rpc.0.OEQ2282208.1.LUX wird setState('javascript.0.Zustand.Beleuchtungsstärke', obj.state.val); 1x mehr ausgeführt als beim letzten Mal.

Wenn alle 3 Minuten ein neuer Wert kommt, wird schon nach 24h das setState 480x schnell hintereinander ausgeführt. Nach einer Woche über 3000 mal!

Das bedeutet dann auch, dass alle Trigger, die auf javascript.0.Zustand.Beleuchtungsstärke reagieren und nicht auf change: "ne" prüfen, infolgedessen auch 3000x ausgeführt werden.

[Wildbill]

@AlCalzone @UncleSam
Ja, das zweite Script ist der Übeltäter für den Anstieg tagsüber. Fragt mich mal, warum ich da bind genommen habe, anstatt einfach den State zu setzen. Im Blockly sieht man da gar nicht, dass es Trigger im Trigger ist, erst im Javascript hab ich es jetzt auch gesehen. Vermutlich irgendwann mal aus einem alten Scipt so rein kopiert und nie drauf geachtet. Das werde ich gleich mal ändern. Mit anhalten des Scripts ist zumindest sofort inputCount und outputCount wieder runter. Nachts bleibt der Wert bei 0, dann steht das ja quasi eh.
Vermutlich war das dann auch das Problem mit dem Anstieg über Tage/Wochen, das beobachte ich mal weiter, bevor ich ein Issue erstelle.

Zu den Fragen:
1.: Ist ja quasi beantwortet, das wird es wohl sein
2.: Nein, alle Scripte laufen immer durch und werden rein durch Trigger gesteuert. Mit scriptEnabled habe ich nie gearbeitet.

Ich beobachte und gebe so in ein zwei Wochen mal Rückmeldung. Aber Danke Euch zwei fürs Schubbsen in die richtige Richtung, wonach ich suchen muss, und verutlich auch für die Lösung des Problems.

Gruss, Jürgen

EDIT: So sieht das zweite Script jetzt aus, sollte wohl passen:

Spoiler

on({id: 'hm-rpc.0.OEQ2282208.1.LUX', change: "ne"}, function (obj) {
 var value = obj.state.val;
 var oldValue = obj.oldState.val;
 setStateDelayed("javascript.0.Zustand.Lichtsensor-alt"/*Lichtsensor-alt*/, (obj.state ? obj.state.val : ""), true, 120000, true);
 setState("javascript.0.Zustand.Beleuchtungsstärke"/*Beleuchtungsstärke*/, (obj.state ? obj.state.val : ""), true);
});

[AlCalzone]

@Wildbill sagte in iobroker-CT unter Proxmox stetiger Anstieg CPU-Last:

Im Blockly sieht man da gar nicht, dass es Trigger im Trigger ist

An der Farbe erkennst du es. Trigger sind pink.

[Wildbill]

@AlCalzone
Nicht so, wie ich es hatte.
Das Blockly als Javascript sah so aus (Datenpunkte jetzt nur pro forma):

Spoiler

on({id: 'default', change: "ne"}, function (obj) {
var value = obj.state.val;
var oldValue = obj.oldState.val;
on({id: 'Object ID 1', change: "ne"}, function (obj) {
  setState('Object ID 2', obj.state.val);
});});

Als Blockly sieht es so aus:

Also nicht pink/lila, sondern wie ein Steuere/Aktualisiere. Deshalb fiel es mir nicht auf.
Man lernt nie aus. Danke.

Gruss, Jürgen

[AlCalzone]

@Wildbill Oh! Das ist natürlich ungünstig.

[Wildbill]

@AlCalzone @UncleSam
Ich setzte das Thema jetzt auf gelöst und mache bezüglich des JS-Adapters auch kein Issue auf. Über eine Woche hat sich der CPU-Wert des Containers jetzt kein Stück nach oben bewegt, von den Spikes, wenn es kurz mal etwas mehr zu tun gibt, abgesehen. Aber danach ist er wieder auf den "Startwert" von vor einer Woche zurückgefallen.

Danke Euch beiden nochmal. Ohne Euch wäre ich wohl immer noch am suchen...

Gruss, Jürgen