Meldung - DbLog_PushAsync Timeout: process terminated

[Rewe2000]

Hallo,

ich beobachte nun schon seit einigen Tagen folgende Meldung im Log, welche von DbLog auftaucht.
Stelle ich jedoch den Loglevel von DbRep () auf verbose 3, erscheint diese "Timeout" Meldung  jedoch nicht mehr.

Um 03:05:55 Uhr starte ich über ein at täglich ein serverseitiges dump:

Code Auswählen Erweitern

*03:05:55 set DBReport dumpMySQL serverSide

Da ich keinerlei Ahnung habe was hier ggf. nicht passen könnte und in welche Richtung ich suchen muss, will ich hier mal nachfragen.
Timeout hört sich für mich grundsätzlich nicht so an, als wie wenn alles passen würde.

Code Auswählen Erweitern

2020.09.11 02:03:33 2: DbLog DBLogging: Connection closed until 03:03:33 (3600 seconds).
2020.09.11 02:04:05 2: DbRep DBReport - command message after reduceLog: "Reopen executed."
2020.09.11 03:05:55 2: DbLog DBLogging -> DbLog_PushAsync Timeout: process terminated
2020.09.11 03:05:55 2: DbLog DBLogging: Connection closed until 04:05:55 (3600 seconds).
2020.09.11 03:06:22 2: DbRep DBReport - command message after dump: "Reopen executed."

Irgendwelche anderen Abweichungen kann ich (bisher) nicht erkennen.
Über eine kurze Nachhilfe zu dieser Meldung wäre ich dankbar.

DbRep mit verbose 3 von heute:

Code Auswählen Erweitern

2020.09.13 02:04:04 2: DbRep DBReport - command message after reduceLog: "Reopen executed."
2020.09.13 03:05:55 3: DbRep DBReport - ################################################################
2020.09.13 03:05:55 3: DbRep DBReport - ###             New database serverSide dump                 ###
2020.09.13 03:05:55 3: DbRep DBReport - ################################################################
2020.09.13 03:05:55 3: DbRep DBReport - execute command before dump: 'set DBLogging reopen 3600'
2020.09.13 03:05:55 2: DbLog DBLogging: Connection closed until 04:05:55 (3600 seconds).
2020.09.13 03:05:55 3: DbRep DBReport - Searching for tables inside database fhem....
2020.09.13 03:05:55 3: DbRep DBReport - Starting dump of database 'fhem', table 'history'
2020.09.13 03:06:21 3: DbRep DBReport - Number of exported datasets: 1856182
2020.09.13 03:06:21 3: DbRep DBReport - Size of backupfile: 166.37 MB
2020.09.13 03:06:21 3: DbRep DBReport - Deleting old dumpfile 'fhem_history_2020_09_05_03_05.csv'
2020.09.13 03:06:21 3: DbRep DBReport - Finished backup of database fhem - total time used (hh:mm:ss): 00:00:26
2020.09.13 03:06:21 2: DbRep DBReport - command message after dump: "Reopen executed."
2020.09.13 03:06:21 3: DbRep DBReport - Database dump finished successfully.
2020.09.13 04:44:44 3: DbRep DBReport_Datensaetze_loeschen - Entries of fhem.history deleted: /--/--1788

Als erste Maßnahme setze ich heute Nacht, ab 03:00:00 Uhr, über ein at verbose bei DbLog auf 3, in der Hoffnung da taucht noch ein wenig mehr auf.

Gruß Reinhard

[DS_Starter]

Moin Reinhard,

im DbLog gibt es ein Attribut timeout. Das ist per default auf 86400 Sek, also ein Tag.
Wie steht der bei dir ?

Ich weiß jetzt nicht wie schnell deine DB ist. Du führst ein reduceLog aus, was 02:04 fertig ist. Während der Zeit werden X Events im Cache gehalten die nach Öffnung der DB 02:04 alle gesichert werden wollen.
Mit Sicherheit passiert das kurz nach 02:04. Um 03:05 kommt der Timeout, also rund 1 h später.

Theorie ... es sollen sehr viele Events aus dem Cache in die DB gesichert werden und deine DB braucht dafür (mehr) als 1 h, sodass der timeout zuschlägt. Das wäre allerdings wirklich sehr sehr sehr langsam für eine DB.

Du könntest mal die Readings CacheUsage, background_processing_time und sql_processing_time Events erzeugen lassen und sie in ein Filelog schreiben. (Attribut cacheEvents auf 2 setzen)
Den Inhalt müßte man sich zu der fraglichen Zeit mal anschauen.

Grüße,
Heiko

[Rewe2000]

Hallo Heiko,

im DbLog gibt es ein Attribut timeout. Das ist per default auf 86400 Sek, also ein Tag.
Wie steht der bei dir ?

Das Timeout Attribut ist bei mir in DbLog nicht gesetzt, deshalb sollte hier die Standardeinstellung (86400 Sek) greifen.

Das reduceLog wird bei mir um 02:03:33 Uhr per at gestartet und ist um 02:04:04 Uhr fertig, ich kann mir nicht vorstellen, dass in den 31 Sekunden der Cache so voll läuft, da ich immer peinlichst Acht gebe, dass nicht zu viele Events von den Devices erzeugt werden und nur die absolut notwendigen davon im DbLog landen.

Ich habe deinen Vorschlag aufgenommen und schreibe die von dir genannten Readings mit. Morgen Vormittag sehen wir mehr.

Ich setze bei DbLog in der fraglichen Zeit den Loglevel auf Verbose 3, in der Hoffnung hier mehr zu sehen.

Danke für die Tipps.

Gruß Reinhard

[DS_Starter]

Hallo Reinhard,

wenn ich das so lese, liege ich mit meiner ersten Theorie mit Sicherheit falsch.
Na mal schauen was das Logging offenbart.

Grüße,
Heiko

[Rewe2000]

Hallo Heiko,

irgendwie seltsam das Ganze bei mir.

Die Timeout Meldung kam bei mir nur am 11. und 12.09.2020. Als ich am 13.09. vom DbRep Verbose 3 gesetzt hatte und auch heute kam absolut nichts abnormales im Log.
Ich lass nun die von dir genannten Readings ins Log schreiben und beobachte das Log, ob nochmals die Timeout Meldungen auftauchen.

Das Einzige was mir ein wenig hoch erscheint ist die Dauer, wie lange bei mir reduceLog läuft, das Reading zeigt:

Code Auswählen Erweitern

reduceLogState
reduceLogNbl finished. Rows processed: 842925, deleted: 16734, updated: 888, time: 705.40sec

Bis dahin betrachte ich es vorersts als Erledigt.
Nochmals Danke für die Tipps zur Eingrenzung des "Fehlers".

Gruß Reinhard

[DS_Starter]

Moin Reinhard,

noch Tipp ...

benutze statt reduceLogNbl im DbLog das reduceLog im DbRep.
Inhaltlich ist es das gleiche (non-blocking), aber im DbRep gibt es zusätzliche Selektionsmöglichkeiten und vor allem ist die Zusammenarbeit zur DB in Bezug auf die Abläufe im DbLog besser steuerbar, z.B. öffnen und schließen der DB über die Attr executeBeforeProc, executeAfterProc.
Das letztere ist mM nach hilfreich für deinen Case.

Grüße,
Heiko

[Rewe2000]

Hallo Heiko,

die Umstellung auf reduceLog im DbRep habe ich schon vor längerer Zeit durchgeführt.

Die beiden Attribute in DbRep verwende ich derzeit wie folgt:

Code Auswählen Erweitern

executeAfterProc set DBLogging reopen
executeBeforeProc set DBLogging reopen 3600

Ich denke das hast du auch gemeint.

Ich beobachte mal die nächsten Tage, wenn was nicht so klappt wie gewünscht, dann melde ich mich sowieso.

Gruß Reinhard

[DS_Starter]

Ich hatte mich nur gewundert weil du geschrieben hast:

reduceLogState
reduceLogNbl finished. Rows processed: 842925, deleted: 16734, updated: 888, time: 705.40sec

reduceLogNbl gibt es im DbRep ja nicht.

[Rewe2000]

Hallo Heiko,

jetzt bin ich aber aufgewacht und der Sache auf den Grund gegangen. Das Reading reduceLogNbl im DbLog Device ist veraltet und hat einen Zeitstempel von Januar 2019, das ist mir beim Schreiben des Beitrags überhaupt nicht aufgefallen. Bei mir war die Umstellung auf reduceLog in DbRep erfolgreich, auch die Suche nach reduceLogNbl in fhem.cfg bringt keine Treffer mehr. Das Reading habe ich jetzt gelöscht, damit es nicht noch mehr Verwirrung stiftet.

Die von dir empfohlenen Readings habe ich in meine Datenbank geschrieben, ich denke die Werte sind bei mir im "normalen" Bereich:

CacheUsage: Durchschnitt 20-40, Maximalwert 175 (wenige Ausreißer)
background_processing_time: Durchschnitt 0.03 - 0.05 s, Maximalwert 0.09 s
sql_processing_time: Durchschnitt 0.006 - 0.009 s, Maximalwert 0.0372

Ich habe jetzt nur den in Frage kommenden Zeitbereich protokolliert und mir nicht die Mühe gemacht die Ausreißer einer SQL-Aktion zuzuordnen, da die Werte nach meiner Auffassung absolut unkritisch sind. Der Timeout Fehler ist auch nicht mehr aufgetaucht.

Sorry für die falsche Fährte.
Gruß Reinhard

[DS_Starter]

Moin Reinhard,

die Werte sehen gut aus. Wenn ich von sehr vielen Werten in CacheUsage spreche, dann würde es um einige Tausend gehen. 
Aber so ist das alles gut was zu sehen ist.

LG,
Heiko