93_DbLog - Umstellung Log-Funktion auf non-blocking

[DS_Starter]

Hallo Tobias, rapster, @all,

ich habe mich mit der Umstellung der Log-Funktion auf eine nichtblockierende Arbeitsweise beschäftigt.

Eine Version von DbLog, die bereits mit positiven Ergebnissen in meiner Installation läuft, möchte ich zum Test und Diskussion
mit euch teilen. Ich benutze MariaDB (MySQL), habe es aber auch schon mit SQLite angetestet.
Speziell die Subroutinen DbLog_Log, DbLog_Push sind abgeändert.

Zusammengefasst ist folgendes verändert:

* DbLog Log-Funktion ist umgestellt auf non-blocking mit Blocking.pm
* Umstellung der NotifyFn (DbLog_Log) auf deviceEvents
* Einführung von NOTIFYDEV um nur Events von Devices vom DbLog-Device auswerten zu lassen die auch in der DEF angegeben wurden
* Angabe der noch offenen Verbuchungen/DB-Updates im state-Reading
* verbose 4: Ausgaben von zu bewertenden bzw. zu verarbeitenden Events im Logfile


Abgeleitet von der DbLog-Definition bzw. Regex wird nun auch NOTIFYDEV aufgebaut. Damit soll gewährleistet werden dass DbLog nur die Events
der Devices verarbeiten muß die auch im Define von DbLog angegeben wurden.

Mit verbose 4 kann gut verfolgt werden welche Events bewertet, der Verarbeitung übergeben wurden und wieviele Event-Verbuchungen noch anstehen.
Hier ein Beispiel:

#################################################

2016.12.18 10:10:06.381 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Bezug_WirkP_Zaehler_Diff: 0.0022
2016.12.18 10:10:06.382 4: SMAEM LogDB -> count of current log gaps: 1
2016.12.18 10:10:06.390 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Bezug_WirkP_Kosten_Diff: 0.0005
2016.12.18 10:10:06.391 4: SMAEM LogDB -> count of current log gaps: 2
2016.12.18 10:10:06.402 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Bezug_WirkP_Zaehler_Diff: 0.0022 , Reading: Bezug_WirkP_Zaehler_Diff , Value: 0.0022 , Unit:
2016.12.18 10:10:06.405 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Einspeisung_WirkP_Zaehler_Diff: 0
2016.12.18 10:10:06.406 4: SMAEM LogDB -> count of current log gaps: 3
2016.12.18 10:10:06.421 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Bezug_WirkP_Kosten_Diff: 0.0005 , Reading: Bezug_WirkP_Kosten_Diff , Value: 0.0005 , Unit:
2016.12.18 10:10:06.429 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Einspeisung_WirkP_Verguet_Diff: 0.0000
2016.12.18 10:10:06.431 4: SMAEM LogDB -> count of current log gaps: 4
2016.12.18 10:10:06.448 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Einspeisung_WirkP_Zaehler_Diff: 0 , Reading: Einspeisung_WirkP_Zaehler_Diff , Value: 0 , Unit:
2016.12.18 10:10:06.455 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: -114.1
2016.12.18 10:10:06.457 4: SMAEM LogDB -> count of current log gaps: 5
2016.12.18 10:10:06.484 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Saldo_Wirkleistung: -114.1
2016.12.18 10:10:06.485 4: SMAEM LogDB -> count of current log gaps: 6
2016.12.18 10:10:06.494 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Einspeisung_WirkP_Verguet_Diff: 0.0000 , Reading: Einspeisung_WirkP_Verguet_Diff , Value: 0.0000 , Unit:
2016.12.18 10:10:06.507 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Bezug_Wirkleistung: 114.1
2016.12.18 10:10:06.508 4: SMAEM LogDB -> count of current log gaps: 7
2016.12.18 10:10:06.513 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: -114.1 , Reading: state , Value: -114.1 , Unit:
2016.12.18 10:10:06.526 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Bezug_Wirkleistung_Zaehler: 1050.5732
2016.12.18 10:10:06.527 4: SMAEM LogDB -> count of current log gaps: 8
2016.12.18 10:10:06.528 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Einspeisung_Wirkleistung: 0.0
2016.12.18 10:10:06.529 4: SMAEM LogDB -> count of current log gaps: 9
2016.12.18 10:10:06.530 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Einspeisung_Wirkleistung_Zaehler: 1485.0672
2016.12.18 10:10:06.530 4: SMAEM LogDB -> count of current log gaps: 10
2016.12.18 10:10:06.544 4: DbLog LogDB -> check Device: Dum.Energy , Event: GridConsumption: 114.1
2016.12.18 10:10:06.549 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Saldo_Wirkleistung: -114.1 , Reading: Saldo_Wirkleistung , Value: -114.1 , Unit:
2016.12.18 10:10:06.598 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Bezug_Wirkleistung: 114.1 , Reading: Bezug_Wirkleistung , Value: 114.1 , Unit:
2016.12.18 10:10:06.606 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Bezug_Wirkleistung_Zaehler: 1050.5732 , Reading: Bezug_Wirkleistung_Zaehler , Value: 1050.5732 , Unit:
2016.12.18 10:10:06.646 4: SMAEM LogDB -> count of current log gaps: 9
2016.12.18 10:10:06.658 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Einspeisung_Wirkleistung: 0.0 , Reading: Einspeisung_Wirkleistung , Value: 0.0 , Unit:
2016.12.18 10:10:06.689 4: SMAEM LogDB -> count of current log gaps: 8
2016.12.18 10:10:06.694 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Einspeisung_Wirkleistung_Zaehler: 1485.0672 , Reading: Einspeisung_Wirkleistung_Zaehler , Value: 1485.0672 , Unit:
2016.12.18 10:10:06.710 4: SMAEM LogDB -> count of current log gaps: 7
2016.12.18 10:10:06.720 4: SMAEM LogDB -> count of current log gaps: 6
2016.12.18 10:10:06.725 4: SMAEM LogDB -> count of current log gaps: 5
2016.12.18 10:10:06.741 4: SMAEM LogDB -> count of current log gaps: 4
2016.12.18 10:10:06.752 4: SMAEM LogDB -> count of current log gaps: 3
2016.12.18 10:10:06.761 4: SMAEM LogDB -> count of current log gaps: 2
2016.12.18 10:10:06.771 4: SMAEM LogDB -> count of current log gaps: 1
2016.12.18 10:10:06.777 4: SMAEM LogDB -> count of current log gaps: 0

#################################################################

Der Eintrag "check Device:.. " beschreibt dass ein Event an das Modul weitergeleitet wurde. Das bedeutet noch nicht dass es auch in die
DB geschrieben wird, sondern dass nun eine Bewertung bzgl. Bedingungen wie DbLogExclude, DbLogInclude, MinIntervall erfolgt.

Ist die Prüfung positiv verlaufen und der Event soll in der DB geloggt werden, wird dies durch den Eintrag "processing Device: ..."
gekennzeichnet, d.h. in diesem Moment erfolgt das eigentliche Logging des Events in der DB.

Informativ ist auch der Eintrag "count of current log gaps:...". Es ist ein Zähler der pro in der DB zu verbuchenden Event um 1 erhöht wird und nach dem erfolgreichen DB-Insert wieder um 1 vermindert wird. In dem obigen Beipiel sieht man recht gut wie insgesamt 10 Events
verarbeitet werden sollen und der Wert bis auf "count of current log gaps: 10" ansteigt um dann entsprechend der Abarbeitung durch die
Hintergrundprozesse wieder auf "count of current log gaps: 0" zu sinken.

Auch im state-Reading wird mit "still to update - <Anzahl der offenen Verbuchungen>" ein Überblick über den Zustand des DbLog gegeben.

State sollte demzufolge nur kurzfristig ungleich "0" sein. Wenn z.B. durch Nichterreichbarkeit der DB oder andere Umstände wie Timeout
ein Event nicht in die DB eingefügt werden konnte, wird z.B. "still to update - 3" angezeigt, sofern 3 Prozesse ihre Daten nicht an die DB
loswurden.
Gleiches gilt für den Logeintrag "count of current log gaps:..." mit verbose 4. Auch dieser würde in diesem Fall "3" im Minimum anzeigen.
Bei jedem Restart von FHEM wird dieser Zähler auf 0 gesetzt.

Das Ganze funktioniert auch gut mit dem global Attribut "blockingCallMax", das seit einiger Zeit gesetzt werden kann um die maximal gleichzeitig
laufenden BlockingCalls zu begrenzen.
Das kann hilfreich sein, wenn man wie ich bereits eine ganze Reihe non-blocking Devices (76_SMAInverter, 77_SMAEM, umfangreiche Anzahl 93_DbRep, 93_DbLog,
42_SYSMON, 98_HMinfo, ....) im Einsatz hat.
Wenn verbose 4 gesetzt ist, kann man sehr schön die Auswirkungen verschieden gesetzter blockingCallMax-Werte verfolgen und so den
individuell günstigen Wert finden. Es soll eine zügige Verarbeitung der Events erfolgen, jedoch andererseits nicht die CPU(s) zu stark
auslasten um nicht die Vorteile der non-blocking Arbeitsweise durch einen Bottleneck hervorgerufen durch eine zu hohe CPU-Auslastung
wieder einzubüßen.

@Tobias, rapster ... ich würde mich freuen wenn die Änderungen nach erfolgreichen Tests durch euch/anderen Usern in das offizielle DbLog
einfließen.

@all ... bitte FHEM auf jeden Fall nach Einspielen des Moduls restarten !

Ich freue mich auf eure Testergebnisse und Rückmeldungen.

viele Grüße
Heiko

[rudolfkoenig]

Ich will anmerken, dass BlockingCall nicht fuer so haeufige Aufrufe gedacht ist. Fuer jede Event-Zeile etliches an Perl-Code, 1*fork(), n*close(), 2*connect, usw. auszufuehren belastet das System deutlich staerker, als mit der aktuellen Implementation. Andererseits freut es mich, wenn bei dir dabei keine Probleme mit BlockingCall aufgefallen sind.

Wenn es nicht blockierend sein soll, dann z.Bsp. beim define ein BlockingCall Prozess anlegen, der ein Serverport oeffnet, mit dem Modul dahin eine Verbindung aufnehmen, und die Daten jeweils diesem zweiten Prozess schicken. Das geht auch nicht-blockierend, z.Bsp. macht FHEMWEB sowas mit addToWritebuffer().

[Markus Bloch]

Dieser Anwendungsfall ist eigentlich ideal für SubProcess.pm

Gruß
Markus

[DS_Starter]

Hallo Rudi und Markus,

danke für eure Hinweise.

@Rudi ... ja, läuft bei mir richtig gut. Mit dieser Testversion komme ich auf durchschnittlich 32 - 190 ms (apptime). Vorher lag ich oftmals bei über 1000ms. Weiß nicht wie so etwas auf einem PI läuft, hab ja ein virtualisiertes Linux, aber die positiven Ergebnisse freuen mich  ... danke für den Hinweis zu FHEMWEB mit addToWritebuffer() ... schaue ich mir auch mal an.

@Markus, SubProcess.pm würde ich mir auch gerne mal dafür anschauen. Kannst du mir einen Tipp geben wo ich ein Beispiel für die Verwendung finde ?

Grüße
Heiko

[Markus Bloch]

Hallo Heiko,

das Modul 88_HMCCU.pm nutzt SubProcess.pm

Es ist leider auch aktuell das einzige. Boris hat SubProcess.pm im Rahmen von https://forum.fhem.de/index.php/topic,34320.0.html erstellt.

Gruß
Markus

[rudolfkoenig]

Falls du fuer ein DB-Insert 1000ms brauchst, dann ist irgendetwas anderes faul, und ich wuerde das zunaechst beheben.

[DS_Starter]

Thx Markus, dann kann ich mich da mal langhangeln.
Bin trotzdem gespannt ob und wenn ja welche Rückmeldungen von Usern kommen ... ich kann bei mir wie gesagt nichts negatives berichten.

Grüße
Heiko

[DS_Starter]

Falls du fuer ein DB-Insert 1000ms brauchst, dann ist irgendetwas anderes faul, und ich wuerde das zunaechst beheben.

Für ein Insert nicht, nur habe ich festgestellt dass wenn viele Events gleichzeitig geloggt werden sollten (z.B. die Werte vom Energymeter wie in dem Beispiel), kam es zu Engpässen bzw. zum Anstieg der apptime Ergebnisse. Aber ich habe auch schon an Parametern der MariaDB geschraubt. Die MariaDB auf meiner Synology beherbergt natürlich nicht nur die FHEM-DB's sondern auch noch etliche weitere für andere Applikationen. Mit diesen hatte ich bislang noch keine Probleme festgestellt, allerdings auch nicht so intensiv untersucht muß ich zugeben ....

[Loredo]

Diese Diskussion ist auch deshalb interessant, weil ich bereits viele User hatte, die sich über eine schlechte Performance des Wunderground Moduls beklagen, wenn sie über DbLog loggen. Da dort regelmäßig mehrere Duzend Readings aktualisiert werden und die User wohl gerne nach dem Motto "was ich hab das hab ich" loggen, wird DbLog entsprechend stark beansprucht und während der Zeit blockiert FHEM dann doch merklich einige Sekunden auf schwächeren Systemen.
Vielleicht eignet sich das Modul deshalb auch ganz gut für einen Benchmark




Gruß
Julian

[justme1968]

zu allem außer Blocking: ich finde die änderungen sehr gut.  und es wäre schöne wenn sie übernommen werden.

zu Blocking: das ist der falsche ansatz. zum einen gibt es datenbanken die nicht multi prozess fähig sind (sqlite) das wäre das ganze kontraproduktiv und würde nicht funktionieren. zum anderen: ich glaube es wäre sinnvoller die db ohne fork asynchron zu betreiben. damit solltest du mindestens die gleiche verbesserung sehen ohne den zusätzlichen overhead durch das forken. unterm
strich sollte es also noch. esser werden.

ich vermute auch das die x prozesse die sich um die db streiten zwar alle vom fhem entkoppelt sind, sich aber eigentlich gegenseitig blockieren weil sie auf die
gleiche tabelle und auch noch an die gleiche stelle zugreifen.

soll heiße wenn man das einfach nach einander und asynchron über die fhem event loop abarbeitet bist du vermutlich mindestens so schnell.

gruss
  andre

ps: warum eine db bei ein paar inserts langsam ist sollte man tatsächlich vorher klären. bei halbwegs adäquater hardware sollten selbst ein paar dutzend readings auf ein mal nicht viel ausmachen.

[rudolfkoenig]

Mehrere Inserts beschleunigt man, indem man precompiled Statements verwendet (d.h. insert mit ?), und alle in eine Transaktion packt. Manche DB-Module (z.Bsp DBD::Oracle) unterstuetzen Bulk-Insert (Stichwort execute_array), das bringt in manchen Faellen nochmal ein Faktor von 10. Vor ca 10 Jahren habe ich mit perl/execute_array etwa 5000 Inserts/sec erreicht, zugegebenermassen war der Rechner aber schneller als ein RPi.

[DS_Starter]

Hallo zusammen,

erstmal vielen Dank für eure Rückmeldungen und Anregungen.

Was ich jetzt mitnehme ist,  dass Blocking.pm  für diesen Einsatzzweck nicht das Mittel der Wahl ist.
Andererseits ist es dennoch ein Thema das DB-Logging von fhem zu entkoppeln (wie ebenfalls Julians Erfahrungen zeigen), auch unter dem Gesichtspunkt dass wahrscheinlich die Mehrzahl der verwendeten DB's nicht optimal getunt sein werden (meine eingeschlossen).

Ich werde es nochmal mit einem neuen Ansatz versuchen umzusetzen, so wie Andre's Vorschlag einer sequentiellen asynchronen Abarbeitung bzw. die Hinweise von Rudi oder Markus gehen wahrscheinlich in eine ähnliche Richtung.
Wahrscheinlich komme ich aber erst irgendwann nach den Feiertagen dazu mich nochmal intensiver mit dieser Thematik zu beschäftigen.

Ein bisschen Off-Topic ... habe im SQL-Client (ohne jegliches fhem) die Schreibgeschwindigeit für einen Insert in die fhem-db gecheckt.
Sie liegt bei 0.0244 Sekunden. Die DB liegt auf einem Synology Hybrid SHR-Raid 5.
Vergleichswerte sind natürlich gerne willkommen auch wenn sie wegen nicht vergleichbarer Hardware nicht so sehr aussagefähig ist. Nur um mal einen Eindruck zu gewinnen wie schnell andere Systeme schreiben.

Grüße
Heiko

[rudolfkoenig]

Fuer eine herkoemmliche (sich drehende) Festplatte sind 40 Einzel-Inserts ein normaler Wert, und hat mehr mit der Rotationsgeschwindigkeit, und weniger mit dem Durchsatz der Platte zu tun. Ein Problem entsteht dann, wenn viele Events kommen und man alle loggen will. Z.Bsp. generiert FBAHAHTTP alle 5 Minuten fuer alle angeschlossenen FBDECT Geraete jeweils 13 Events, das sind bei 10 Geraeten 130 Events auf einmal. Damit waere deine Platte mit der aktuellen Architektur 3+ Sekunden lang ausgelastet. Falls man diese Daten zusammenfasst, dann dauert es sicher unter 0.1s.

Kannst du den Aufwand fuer ein FileLog Aktion messen, um einen Vergleichswert zu haben?

[DS_Starter]

Kannst du den Aufwand fuer ein FileLog Aktion messen, um einen Vergleichswert zu haben?

Wenn ich es richtig interpretiere dauert ein Logfile-Eintrag ca. 0.0253s. Ich habe alle Readings vom SMA-Energymeter (ca. 70) loggen lassen und dann entsprechend geteilt.

EDIT: Verschreiber -> 0.0253s

[justme1968]

das 130 events 3 sekunden dauern glaube ich nicht. jedenfalls nicht als normalfall. da stimmt schon etwas nicht.

eine vernünftig konfigurierte db sollte auch bei einzel inserts und einer einzigen platte mehr als 40 schaffen. zumindest wenn sie in memory caches unterstützt. das zeigt ja auch der 0.0244 wert von oben. raid5 ist beim schreiben höchstens 2-3 mal so schnell wie eine einzelne platte.