Blocking.pm "Process died prematurely"

[DS_Starter]

Hallo Rudi, @all,

mit der aktuellen, korrigierten Version von heute, bekomme ich nun häufig abortFn-Aufrufe in DbLog im asynchronen Mode der ja Blocking nutzt.

Um zu sehen ob es sich um normale timeouts handelt habe ich DbLog erweitert um das mitgebene zweite abortFn Argument auszuwerten.
Dabei habe ich festgestellt dass es sich dabei ausschließlich um "Process died prematurely" -Abbrüche handelt.

Da es bisher mit der alten Blocking-Version problemlos lief, kann ich mir nicht vorstellen wieso nunmehr der Test kill(0, $h->{pid}) häufig einen Fehler wirft der zum (in diesem Fall sehr unschönen) Aufruf von abortFn führt.

Hat jemand dafür eine Erklärung ?

EDIT: Ich muß ergänzen dass ich diese Abbrüche bislang auf meiner Entwicklungsmaschine habe auf der vier DbLog-instanzen laufen, für jede unterstützte Datenbank zum entwickleln und testen. Auf der Prod nutze ich noch das alte Blocking.pm

Grüße
Heiko

[DS_Starter]

Jetzt habe ich im Blocking die Prüfung geändert in:

Code Auswählen Erweitern


if(!kill(-0, $h->{pid})) {
...


Nun scheint Ruhe zu sein und alles läuft wieder.
Morgen schaue ich nochmal ins Log ob es so geblieben ist.

LG
Heiko

[rudolfkoenig]

Wie haeufig wird BlockingCall in deinem Fall aufgerufen (ich meine eine Zahl/Sekunde).
Welche Version von Blocking.pm verwendest du? Aktuell ist SVN 15200.
Wg "kill -0": Kannst du mir bitte sagen, woher du diese Idee mit -0 hast?

[DS_Starter]

Guten Morgen Rudi,

vorab, meine Änderung im Blocking gestern Abend hat leider doch keinen Erfolg gebracht.
Es kommen immer mal wieder:

Code Auswählen Erweitern


2017.10.06 00:18:39.579 2: DbLog LogDB1 -> DbLog_PushAsync Process died prematurely
2017.10.06 01:26:53.469 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 01:29:10.252 2: DbLog LogDB1 -> DbLog_PushAsync Process died prematurely
2017.10.06 01:29:53.506 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 01:30:38.519 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 01:33:38.562 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 01:37:23.615 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 01:41:08.665 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 01:41:53.677 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 01:44:53.716 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 01:46:23.739 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 02:29:10.581 2: DbLog LogDB1 -> DbLog_PushAsync Process died prematurely
.................
2017.10.06 05:24:41.809 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 05:28:26.863 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 05:32:56.932 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 05:37:26.993 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 05:38:12.005 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 05:42:42.065 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 05:44:57.099 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 05:56:12.255 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 05:56:57.267 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 06:03:42.364 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 06:11:57.476 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely
2017.10.06 06:22:27.612 2: DbLog LogSQLITE -> DbLog_PushAsync Process died prematurely


Ich habe jetzt auf das Blocking auf die Version vom 24.9.2017 zurück gesetzt und vom Update ausgeschlossen.
Jetzt läuft alles wieder rund.

Wie haeufig wird BlockingCall in deinem Fall aufgerufen (ich meine eine Zahl/Sekunde).

Es sind zwischen 45 und 70 Sekunden (unterschiedlich auf den DbLog-Devices. Habe damit auch etwas rumgespielt ohne Erfolg.
Mit der "alten" Version konnte ich die Aufruffrequenz bis auf 1! Sekunde runtersetzen und alles läuft weiterhin fluffig.

Welche Version von Blocking.pm verwendest du? Aktuell ist SVN 15200.

Hatte die Version 15172 2017-10-02 drin. HAbe jetzt auf die 15200 upgedated und teste erneut. Allerdings hat sich an der besagten Teststelle nichts geändert wenn ich mich nicht verguckt habe.

Wg "kill -0": Kannst du mir bitte sagen, woher du diese Idee mit -0 hast?

Habe gestern Abend ein bisschen rumgegoogelt und bin auf einen solchen Hinweis gestoßen. Hat aber offensichtlich nicht als hilfreich erweisen.
Vielleicht finde ich den Link wieder, dann poste ich ihn mal.

LG
Heiko

[rudolfkoenig]

Es sind zwischen 45 und 70 Sekunden

Ist das zu lesen als "alle 45 bis 70 Sekunden wird ein Prozess gestartet, also 1/45 Hz"?

Hatte die Version 15172 2017-10-02 drin

Diese Version hat ziemlich sicher noch einen Bug enthalten, wo abortFn grundlos mit "died prematurely" ausgeloest wurde, wenn mehrere BlockingCalls gleichzeitig beendet wurden. Dieses Problem wird mit 15200 gefixt.

Ich habe jetzt auf das Blocking auf die Version vom 24.9.2017 zurück gesetzt und vom Update ausgeschlossen.
Jetzt läuft alles wieder rund.

Klar, da wird das Problem noch nicht gemeldet. Bist Du sicher, dass die Meldung grundlos ist?

[DS_Starter]

Ist das zu lesen als "alle 45 bis 70 Sekunden wird ein Prozess gestartet, also 1/45 Hz"?

Das wird durch die Einstellung von "Interval" in DbLog festgelegt. Erst nach dem Ablauf der eingestellten Sekunden wird das Schreiben in die DB bzw. implizit der Aufruf von Blocking ausgelöst.

Diese Version hat ziemlich sicher noch einen Bug enthalten, wo abortFn grundlos mit "died prematurely" ausgeloest wurde, wenn mehrere BlockingCalls gleichzeitig beendet wurden. Dieses Problem wird mit 15200 gefixt.

Das liest sich doch gut .... schauen wir mal ....

Klar, da wird das Problem noch nicht gemeldet. Bist Du sicher, dass die Meldung grundlos ist?

Da bin ich mir ziemlich sicher. Den Technik läuft ja nun schon seit etlichen Monaten in dieser Form sehr zuverlässig und ohne Datenverlust beim Schreiben in die DB.
Wenn es "ab und an" gemeldet würde, wäre ich auch nicht stutzig geworden. Aber da es in so massiver Form auftrat kam ich dann ins grübeln.

Bis jetzt läuft die 15200 auf der Testmaschine ohne Fehlermeldungen ... ich beobachte das weiter.

[rudolfkoenig]

Da bin ich mir ziemlich sicher. Den Technik läuft ja nun schon seit etlichen Monaten in dieser Form sehr zuverlässig und ohne Datenverlust beim Schreiben in die DB.

Das ist noch kein Beweis. Wenn ein BlockingCall seine Aufgabe richtig erledigt, und dann stirbt (d.h. exit selbst aufruft), ohne "bin fertig" zu melden, dann ist es aus Sicht von BlockingCall "died prematurely". Wenn das ordentliche Beenden jemanden nicht interessiert, dann braucht man kein abortFn zu setzen, oder man muss "died prematurely" ignorieren. Oder noch besser: exit nicht selbst aufrufen.

[DS_Starter]

Das ist noch kein Beweis. Wenn ein BlockingCall seine Aufgabe richtig erledigt, und dann stirbt (d.h. exit selbst aufruft), ohne "bin fertig" zu melden, dann ist es aus Sicht von BlockingCall "died prematurely".

Das stimmt natürlich.  Ich bin von der beobachteten Indizienlage ausgegangen.

Bis jetzt läuft die 15200 einwandfrei. Selbst mit einem Worst-Case-Scenario -> alle 4 DbLog-Devices auf Interval 1s gestellt, d.h. paralleler Blocking und schreiben in die jeweiligen Datenbanken jede Sekunde läuft es stabil.   

Sehr schön, danke Rudi !
Werde mich aber trotzdem abschließend nochmal (heute Abend) melden wenn das Ganze noch ein paar Stunden mehr gelaufen ist.

LG
Heiko

[DS_Starter]

Hallo Rudi,

jetzt ist mein Worst-Case Scenario etliche Stunden gelaufen und es nicht ein einziger Timeout bzw. "died prematurely"-Fehler passiert !

Ich hatte die Bedingungen noch verschärft.
Die Devices für die Auslesung der PV-Anlage (SMAEM bzw. SMAInverter) habe ich alle Events generieren lassen und auch bei diesen Devices das Interval auf 1s reduziert.

Diese Devs hatte ich auch auf Blocking umgestellt und riefen so neben den vier DbLog-Devices jede Sekunde ebenfalls Blocking auf und erzeugten entsprechend Eventlast.
D.h. mit den DbLog-Devices wurde jede Sekunde 6 Blockingprozesse aufgerufen. Dazu kamen dann noch diverse DbReps die regelmäßig Auswertungen aus den Datenbanken anfertigen (ebenfalls mit Blocking).

Es wurden durchschnittlich 5700 Events pro Minute parallel in die Datenbanken gepumpt (2 MariaDB, 1 PostgreSQL, 1 SQLite). Alles asynchron.

Das ganze Scenario läuft absolut fehlerfrei und im FHEM selbst merkt man überhaupt nichts davon, alles läuft gewohnt flüssig. Der NUC leistet natürlich entsprechendes.

Aber TOP,  ich bin absolut begeistert ! 

LG
Heiko