IoBroker stottert

[steinwedel]

Die Überschrift hört sich sich etwas blöd an, beschreibet aber die Situation ganz gut. Alle 40 Sekunden hängt ioBroker und Befehle werden arg verspätet gesendet. Aufgefallen ist mir dies beim Lichtschalter der nicht per Direktverbindung die zugrundeliegende Homematic schaltet, sondern ausschließlich per ioBroker mittels Javascript.

Hier

! Drücke Strg+A und danach Strg+C, um den Inhalt in die Zwischenablage zu kopieren. Klicke irgendwo, um das Fenster zu schliessen.
! hm-rpc-1 2016-07-30 15:43:59.892 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:59.704 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:59.700 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:59.698 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:59.696 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:59.688 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:59.683 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:59.682 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:59.681 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:59.678 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:59.675 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:59.604 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:49.861 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:48.855 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:48.316 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:47.310 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:46.551 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:45.551 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:44.944 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:43.940 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:43.250 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:42.245 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:41.575 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:40.568 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:39.990 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:38.988 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:38.440 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:37.442 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:36.794 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:35.794 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:35.195 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:34.169 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:33.573 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:32.561 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:31.939 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:30.940 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:30.426 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:29.422 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:28.731 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:27.730 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:27.168 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:26.182 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:25.494 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:24.489 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:23.825 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:22.823 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:22.130 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:21.130 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:20.466 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:20.269 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:20.268 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:20.268 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:20.267 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:20.266 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:20.264 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:20.260 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:20.258 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:20.257 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:20.255 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:20.204 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:10.188 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:09.186 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:08.595 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:07.586 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:06.885 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:05.881 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:05.077 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:04.072 info setValue ['IEQ0533837:4','STATE',true] BOOL
! hm-rpc-1 2016-07-30 15:43:03.268 info setValue ['IEQ0533837:4','STATE',false] BOOL
! hm-rpc-1 2016-07-30 15:43:02.266 info setValue ['IEQ0533837:4','STATE',true] BOOL

Bei dem Messvorgang liefen folgende Adapter:

Admin, hm-rpc, vis und web. Das Licht wurde per vis ein/ausgeschaltet. Die CPU Belastung ist zu vernachlässigen: load average: 0,21, 0,24, 0,26. 4 GB freier Hauptspeicher sollten auch reichen.

Als nicht ursächliche Adapter konnte ich Admin, vis und web eliminieren. Habe diese abgeschaltet. Bei vis habe ich dann javascript gestartet und die Schaltvorgänge mittels Taster vorgenommen.

Es sieht so aus, als ob nur hm-rpc übrigbleibt. Auch hier die wichtigen Fakten. Die Lichtschalter sind wired angebunden (HS485d). Sendebeschränkungen können da eigentlich nicht (wie per Funk) auftreten. Wenn ich das Licht direkt über die Homematic-Oberfläche schaltet, tritt das Problem nicht auf.

Das Protokoll XML/Bin hat keinen Einfluss auf das Verhalten. Änderung der Werte bei "Verbindungs-Check Interval(sek)" und "Wiederverbindungs-Interval(sek)" im Adapter haben auch keinen Einfluss. ioBroker/Adapter/CCU2 alle auf dem neuesten Stand.

Bis vor kurzem (ca 1 Woche) hatte ich das Problem nicht.

Ich hoffe, dass noch jemand außer mir das Problem hat. Gerade bei Licht mag man nicht unbedingt bis zu 10s warten, bis der Schaltbefehl umgesetzt wird.

Herzliche Grüße

Gerhard

[steinwedel]

Jetzt wird es spannend. Nachdem ich dem hm-rpc Adapter verdächtigt habe, habe ich das Verhalten auch bei dem Hue-Adapter festgestellt.Das bedeutet der hm-rpc-Adapter ist nicht das Problem. Damit ist es das zugrundeliegende System, das das Problem auslöst. Da ioBroker in einer VM läuft, habe ich jetzt mal die VM verdächtigt. Der Zugriff per SSH hat keine solchen Aussetzer. Auch ein regelmäßiger Ping weißt nicht die Aussetzer auf. Daher gehe ich davon aus, dass die VM nicht die Ursache ist (sie verursachte bislang auch keine Probleme). Damit stellt sich die Frage, was die Aussetzer verursacht.

Vielleicht hat jemand einen Tipp.

[steinwedel]

Hier noch ein interessanter Test, der vielleicht weiterhilft.

Habe folgendes kleines Javascript-Programm geschrieben:

var i=0;
schedule("* * * * * *", function () {
    i++;
    console.log("Counter: "+i);
});

Das Script ruft die Funktion jede Sekunde auf und der Counter wird hochgezählt und jede Sekunde der Counterstand auf der Console ausgegeben. Wie zu erwarten hängt das Script alle 40 Sekunden. Zwei Ergebnisse sind bei der Ausgabe spannend:

1. Die Zahlen sind immer fortlaufend; d.h. es geht kein Ergebnis verloren

2. Was aber richtig verblüffend ist, ist der Umstand, das der Zeitstempel im Log trotz des Stotterns keine Unterbrechungen aufweist.

Ich hätte bei 2 erwartet, dass die Skripte verspätet abgearbeitet werden und sogar der String für das Log erzeugt wird und lediglich die Ausgabe verspätet erscheint. Das heißt, das System läuft, aber nicht alle Prozesse laufen durch. Interessant in diesem Zusammenhang finde ich auch zu erwähnen, dass iobroker.js-controller 25% der CPU-Zeit benötigt (ermittelt mit "ps -eo pcpu,pid,user,args | sort -k 1 -r | head -50"). Vielleicht hilft das weiter.

Noch eine Sache, die ich dabei entdeckt habe:

Die Log-Datei wird immer ohne Stottern geschrieben (Kann man sich mit "tail -f" anschauen).

Ich hoffe, diese Ergebnisse helfen weiter.