93_DbLog contrib v5.12.0 - SVG Datenlieferung über SubProzess zum Testen

[DS_Starter]

Schon längere Zeit arbeitete ich an einer Lösung um die Datenlieferung für SVG Plots über den vorhandenenen SubProzess
realisieren zu können.
Zur Zeit werden mit FHEMWEB plotfork=0 die Daten synchron immer wieder von der Datenbank abgefragt was suboptimal ist und zu Verzögerungen/Blockierungen führenkann.
Mit plotfork=1 wird dieser Nachteil beseitigt, allerdings wird der Vorteil mit dem Nachteil des (temporären) Speichermehrverbrauchs durch Perl fork erkauft.
Die Version 5.12.0 bietet sowohl den Vorteil einer größtenteils von der DB entkoppelten unverzögerten Datenlieferung
und vermeidet den Nachteil der forkens durch die Nutzung des verbundenen SubProzesses.

Das DbLog Modul besitzt in der neuen Version das Attribut plotCacheLifetime. Per default ist es mit "0" nicht aktiviert und DbLog verhält
sich bezüglich SVG Datenlieferung wie bisher.

Mit Setzen plotCacheLifetime > 0 wird ein SVG-Cache innerhalb DbLog und eine veränderte SVG-Datenlieferung aktiviert.

plotCacheLifetime <Sekunden>

    Cacht die an SVG-Plots gelieferten Daten für die angegebene Zeit. Eine identische Anfrage innerhalb dieser Zeit wird direkt aus dem Cache beantwortet. Nach Ablauf wird der veraltete Wert noch einmal ausgeliefert, während im Hintergrund über den DbLog-SubProzess aktualisiert wird (stale-while-revalidate).
    Erfordert das Attribut plotfork=0 im/den betreffenden FHEMWEB-Device(s) - der Cache ist für geforkte Kindprozesse nicht sichtbar.
    Siehe auch plotCacheKeepalive.
    (default: 0 - deaktiviert)


    ### Aktivierung SVG-Datenlieferung via SubProzess (Attribut 'plotCacheLifetime')
   
   Ablauf SVG → DbLog → SubProzess → DbLog → SVG

    1. **SVG** ruft wie bisher unverändert 'get <DbLog> - INT <from> <to> <readings...>' auf.

    2. **DbLog** ('_DbLog_plotData') prüft zuerst den Cache ('$hash->{HELPER}{PLOTCACHE}', Schlüssel
       aus Zeitraum/Device/Readings/Tabelle):
       - **frischer Treffer** (jünger als 'plotCacheLifetime'): sofortige Rückgabe, kein DB-Zugriff.
       
       - **veralteter Treffer**: der alte Wert wird sofort zurückgegeben (keine Blockierung),
         zusätzlich wird im Hintergrund ein Refresh angestoßen.
         
       - **kein Treffer** (Signatur nie gesehen): synchroner Fetch mit Cache-Befüllung.

    3. **SubProzess** ('_DbLog_SBP_onRun_plotRefresh', Operation 'refreshplotdata'): baut die
       SQL-Statements über dieselben Funktionen wie der synchrone Pfad ('DbLog_plotBuildSqlSpec',
       'DbLog_plotBuildStm', 'DbLog_plotParseReadings' - kein Codeduplikat), führt sie über die
       eigene, langlebige DB-Verbindung aus und schickt die Rohzeilen zurück.

    4. **DbLog** ('DbLog_SBP_Read') empfängt die Rohzeilen und ruft '_DbLog_plotData' im
       **Replay-Modus** ('prefetched') auf: exakt dieselbe Verarbeitungslogik (delta-h/delta-d,
       RegExp, Aggregation) wie im synchronen Pfad, nur mit vorab gelieferten Zeilen statt
       Live-DB-Zugriff. Läuft außerhalb eines HTTP-Requests, blockiert also nicht. Das Ergebnis wird
       im Cache abgelegt.

    5. **SVG** erhält beim nächsten Aufruf den nun aktualisierten, frischen Cache-Eintrag.

    ### Aktivierung proaktiver Hintergrund-Refresh (Attribut 'plotCacheKeepalive')

   Ohne weitere Änderung aktualisiert sich ein Cache-Eintrag erst dann, wenn ein neuer Plot-Aufruf
   auf einen veralteten Eintrag trifft (Schritt 2, "veralteter Treffer") - das führt beim erneuten
   Öffnen eines länger nicht angesehenen Plots kurzzeitig zu "erst alt, dann aktuell". Mit
   'plotCacheKeepalive' läuft stattdessen ein selbstverwaltender 'InternalTimer'
   ('DbLog_plotCacheAutoRefresh') alle 'plotCacheLifetime' Sekunden und stößt für jede Signatur,
   die innerhalb von 'plotCacheKeepalive' Sekunden tatsächlich angefragt wurde (Feld 'lastreq' im
   Cache-Eintrag, getrennt vom reinen Aktualisierungszeitpunkt 'ts'), proaktiv denselben
   Hintergrund-Refresh wie in Schritt 3/4 an - unabhängig von eingehenden Plot-Requests. Wird eine
   Signatur länger als 'plotCacheKeepalive' nicht mehr angefragt, wird sie verworfen und die
   Aktualisierung dafür eingestellt; der Timer stoppt sich dann selbst und startet beim nächsten
   Cache-Zugriff automatisch neu.

    ### Live-Updates über 'longpollSVG' (Attribut 'plotCacheLifetime' + 'longpollSVG=1' + 'plotEmbed=1')

   'longpollSVG' löst weiterhin korrekt einen Browser-Reload des betroffenen '<embed>'-Plots aus
   (unverändert in 'svg.js'), sobald sich eines seiner Readings ändert. Ohne Zusatzmaßnahme könnte
   dieser Reload aber auf einen noch gültigen, aber veralteten Cache-Eintrag treffen. Deshalb
   invalidiert '__DbLog_plotCacheInvalidateForEvents' bei jedem Schreibzyklus gezielt die
   Cache-Einträge, deren Signatur eines der soeben geloggten Device:Reading-Paare enthält - der
   nächste Request bekommt dadurch garantiert frische Daten. Diese Invalidierung läuft nur, wenn
   '__DbLog_longpollSVGactive' mindestens ein FHEMWEB-Device mit 'longpollSVG=1' **und**
   'plotEmbed=1' findet (exakt die Kombination, die 'longpollSVG' überhaupt wirksam macht) - ohne
   diese Kombination bleibt der Cache unangetastet, um unnötige synchrone Fetches zu vermeiden.

    ### Voraussetzung: 'plotfork=0'

   Der Cache lebt im Geräte-Hash von DbLog und ist für einen von 'plotfork' abgespaltenen
   Kindprozess nicht sichtbar - dortige Schreibzugriffe gehen beim Beenden des Kindprozesses
   verloren. Ist 'plotCacheLifetime' gesetzt, aber 'plotfork=1' in einem FHEMWEB-Device aktiv, wird
   das zur Laufzeit einmalig geloggt und zusätzlich im 'configCheck' als Fehlkonfiguration
   ausgewiesen.


LG,
Heiko

[betateilchen]

Bis jetzt unauffällig.

Code Auswählen Erweitern

Result of version check

Used Perl version: 5.40.1
Used DBI (Database independent interface) version: 1.647
Used DBD (Database driver) version MariaDB: 1.22
Used DbLog version: 5.12.0

Was mich aber (optisch) irritiert, ist das Datum in diesem Internal:

Code Auswählen Erweitern

FVERSION 93_DbLog.pm:v5.12.0-s29401/2024-12-05

[DS_Starter]

Danke für deine Rückmeldung.
Das Datum hatte ich noch nicht geändert, wird vor/beim checkin dann aktualisiert.

[betateilchen]

Gefühlt würde ich sagen, dass manchmal die SVG plots unvollständig sind.

Plot aufgerufen um ca. 14 Uhr - alles ok.
Plot das nächste Mal aufgerufen um ca. 22 Uhr - der angezeigte plot endet um 14 Uhr.
Plot direkt noch mal aufgerufen - aktuelle Daten vorhanden.

Dass der Caching Mechanismus so funktionieren soll, kann ich mir kaum vorstellen.

[DS_Starter]

Dieses Verhalten folgt vermutlich aus:

Erklärung wäre:

Code Auswählen Erweitern

Damit der Cache nicht unkontrolliert wächst, werden gecachte Daten mit TTL=60 Minuten gelöscht.

D.h. wenn der Plot lange nicht aufgerufen wird, veraltet er und die Daten werden nach einem Alter TTL=60 Minuten aus dem Cache gelöscht.Die 60 Minuten sind ein erster Ansatz von mir um speichersparend zu arbeiten. Vllt. kann man TTL auch deutlich erhöhen.

Vllt. liegt auch ein Logikfehler vor, der die Daten TTL>60 Minuten nicht gelöscht hat und genau deswegen die stark veralteten und nicht gelöschten Daten ausgeliefert hat. Muss ich mir anschauen ob das zutrifft.

In jedem Fall wird im Hintergrund ein Cash Refresh ausgeführt, weswegen der 2. Aufruf die komplett aktuellen Daten ausliefert -> Schritt 3 in dem Ablauf.

[betateilchen]

Naja, es werden ja nicht veraltete Daten ausgeliefert, sondern für die Zeit von 14-22 Uhr einfach gar keine Daten. Der plot hört dann beim ersten Aufruf einfach um 14 Uhr auf.

plotCacheLifetime steht bei mir übrigens auf 60 (Sekunden)

[DS_Starter]

Ah, das habe ich vermutlich falsch verstanden. Mach gerne mal einen Screenshot von dem Plot um mein Verständnis zu verifizieren.

[betateilchen]

Im ersten Screenshot ist es 10:58:03 Uhr,

Du darfst diesen Dateianhang nicht ansehen.

die gelbe Linie im plot endet aber um kurz nach 10 Uhr, da hatte ich den plot zuletzt aufgerufen.


Im zweiten Screenshot ist es 10:58:51 Uhr, darin geht die gelbe Linie bis zum aktuellen Zeitpunkt.

Du darfst diesen Dateianhang nicht ansehen.

• dass die gelbe Linie waagerecht verläuft, ist am Wochenende normal, da kommen keine neuen Werte. Es werden nur Werte per addLog geschrieben.
• die violette Linie stammt als Darstellung eines Festwertes aus logProxy.

Idee: kann es sein, dass das Problem generell mit der Verwendung von logProxy zusammenhängt?



--

[enno]

Moin Heiko,

auch bei mir bis jetzt unauffällig. Läuft seit gestern Abend.

Gruss
  Enno

[DS_Starter]

Danke Enno für die Rückinfo.

@betateilchen, das ist der aktuelle Cachingmechanismus. Du hattest den Plot kurz nach 10:00 aufgerufen. Zu diesem Zeitpunkt wurden die Daten im Hintergrund zum letzten mal von der DB gelesen und in den Cache gelegt.
Der nächste Aufruf des Plot 10:58:03 liefert der Cache genau diese zuletzt gecachten Daten und fordert parallel im Hintergrund eine Aktualisierung via Subprozess an. 10:58:51 siehst du dann die inzwischen aktualisierzen Daten.
Hättest du den Plot kurz nach 10 aufgerufen und das nächste Mal erst mit einem Abstand von >60 Minuten, wären die gecachten Daten bereits aus dem Cache gelöscht (fester TTL=60) und DbLog hätte versucht die Daten wieder direkt von der DB zu lesen.

Daraus ergeben sich ein paar Hebel für mich, die ich mal durchdenken muss.
Der Cache Refresh ist aktuell an das wiederholte Aufrufen des Plots gekoppelt und könnte evtl. etwas komfortabler gestaltet werden. Der feste TTL der gecachten Daten könnte evtl. vergrössert werden. Es ist nur ein Schutz vor Speicherwachstum durch nicht mehr benötigte Daten die entfernt werden können.

[betateilchen]

Hättest du den Plot kurz nach 10 aufgerufen und das nächste Mal erst mit einem Abstand von >60 Minuten, wären die gecachten Daten bereits aus dem Cache gelöscht (fester TTL=60) und DbLog hätte versucht die Daten wieder direkt von der DB zu lesen.

Gestern waren zwischen dem Aufruf um 14 Uhr und dem nächsten Aufruf um 22 Uhr immerhin 8 Stunden vergangen.
Das spricht für mich ein bisschen gegen Deine Erklärung.

[DS_Starter]

Absolut richtig, diesen Fall sehe ich mir auch nochmal mit an.
Das wäre dann ein Implementierungsfehler meinerseits der den modellierten Ablaufprozess nicht korrekt abbildet.

[DS_Starter]

Hallo @all,

die Version 5.12.0 in meinem contrib habe ich upgedated und den Prozessablauf nochmal verbessert.
Damit sollten die von betateilchen gegebenen Hinweise erledigt sein.

Im ersten Beitrag habe ich den Ablauf neu verfasst um den Gesamtprozess zu verdeutlichen.Beachtet bitte das Attr plotCacheKeepalive.

Hier in Kurzform wie nun die SVG-Datenlieferung inklusive Caching mit Autorefreh aktiviert wird:

- Attr plotCacheLifetime=X und plotfork=0 im Web Device setzen -> aktiviert die Datenlieferung via SubProzess + Caching (wie in der vorherigen contrib-Version)
- Attr plotCacheKeepalive=X setzen -> den automatischen SVG-Cashrefresh aktivieren
- Attr 'longpollSVG=1' + 'plotEmbed=1' im Web Device wie üblich für den automatischen SVG Webrefresh verwenden (falls gewünscht)


VG,
Heiko

[betateilchen]

Das heißt, ich sollte jetzt zwei Attribute plotCacheLifetiime und plotCacheKeepalive im DbLog device setzen?
Oder sind das "entweder - oder" Attribute?

[DS_Starter]

Die zwei Attr plotCacheLifetiime und plotCacheKeepalive setzen.
Das zweite Attr plotCacheKeepalive ist für den automatischen Refresh des Cache zuständig. Dieser Refresh vermeidet das von dir beobachtete Verhalten, dass bei einem Folgeaufruf des SVG zunächst kurz ein veralteter Stand angezeigt wird bevor über den SubPozess die Aktualisierung erfolgte.
Muß man nicht setzen, dient aber der beschriebenen Vermeidung wenn man das möchte.