93_DbLog - Überlegungen zur Optimierung (RPI und andere Systeme)

[DS_Starter]

OK, habe ich jetzt eingeschaltet. Klappt schon besser, aber es ist trotzdem noch ein Fehler dabei...

Ja, das ist in dem Fall in Ordnung. SQLite sperrt die history-Tabelle gegen weiter Schreibzugriffe wenn das delete läuft.
FHEM wirft dann diesen Fehler sobald vom DB-Interface ein Problem gemeldet wird, in diesem Fall kein  Schreiben in die DB (execute_array) .

Wenn du die DB im Synchronmode betreibst, ist zwar der deleteOldDaysNbl durch den BlockingCall nicht blockierend, aber die FHEM Hauptschleife bleibt beim history-Zugriff hängen.

Im asynchronen Modus wird dieser Zustand durch die Applikation abgefangen. Der Fehler wird durch die DB weiterhin gemeldet,aber FHEM speichert die Log-Daten solange im Cache (listCache) bis die DB wieder verfügbar ist. Das ist auch in anderen Situationen wie DB-Crash oder Backup der Fall. Die Daten werden wieder in die DB geschrieben wenn der Zugriff wieder funktioniwert.
Dadurch blockiert FHEM nicht und auch die Daten gehen nicht verloren.

Mit dem Attr syncInterval kannst du festlegen alle wieviel Sekunden der Cache in die DB geschrieben werden soll. Wenn du diesen Wert vor dem deleteOldDaysNbl  auf einen deutlich höheren Wert setzt als normalerweise deleteOldDaysNbl  dauert, wirst du diese Meldung nicht mehr bekommen weil kein Schreibzugriff stattfindet.

MySQL, die ich benutze, reagiert bei parallelen Zugriffen deutlich entspannter. Da gibt es solche Meldungen (im Normalbetrieb) nicht.

viele Grüße
Heiko

[HCS]

Vielen Dank für die Erläuterung.

Das klappt trotzdem nicht ohne Fehlermedung.

asyncMode ist  1
syncInterval ist 180

Code Auswählen Erweitern

*01:30:00 {
  fhem ("set commonLog commitCache");
  fhem ("set commonLog deleteOldDaysNbl 30");
}

Code Auswählen Erweitern

2017.06.01 20:07:15 3: DbLog commonLog -> Deletion of records older than 30 days in database /opt/fhem/dbLog/commonLog.db requested
2017.06.01 20:08:13 3: DbLog commonLog -> deleteOldDays finished. 0 entries of database /opt/fhem/dbLog/commonLog.db deleted.
2017.06.01 20:08:13 2: DbLog commonLog -> Error table history - DBD::SQLite::st execute_array failed: executing 323 generated 1 errors at ./FHEM/93_DbLog.pm line 1787.

Nach knapp einer Minute ist der deleteOldDaysNbl durch.
Direkt drauf kommt der Fehler
Aber es dürfte doch eigentlich erst 20:10:15 wieder in die DB schreiben?

[DS_Starter]

Aber es dürfte doch eigentlich erst 20:10:15 wieder in die DB schreiben?

Da hast du recht. Es sei denn dass inzwischen der Wert des Attr "cacheLimit" erreicht ist. Wenn also hinreichend viel Daten in der Zwischenzeit aufgelaufen sind. Wenn cacheLimit erreicht ist wird versucht zu schreiben egal ob syncInterval erreicht ist.
Ansonsten kann ich mir gerade nicht vorstellen weswegen die Schreibroutine angesprungen werden sollte.

[DS_Starter]

Jetzt habe ich mal auf meiner SQLite 3  Test-DB alle Datensaätze älter als 50 Tage löschen lassen.

Code Auswählen Erweitern


2017.06.01 23:00:13.806 3: DbLog LogSQLITE -> Deletion of records older than 50 days in database /opt/fhem/fhem.db requested
2017.06.01 23:01:30.032 3: DbLog LogSQLITE -> deleteOldDays finished. 2908707 entries of database /opt/fhem/fhem.db deleted.


Das System hat innerhalb von rund 2:20  die Daten gelöscht. syncInterval habe ich auf 45 s stehen.
Ich habe weder während es Laufs noch hinterher eine Fehlermitteilung wie du erhalten.

[HCS]

Spannende Sache.

deleteOldDaysNbl benötigt in meinem Fall recht genau eine Minute
cacheLimit ist 500, das wird in einer Minute definitiv nicht erreicht.
syncInterval ist aktuell 120
SQLite Version 3.7.13

Das kann ich beides sicher reproduzieren:

1. Wenn ich den Start von deleteOldDaysNbl so lege, dass es vor "NextSync" fertig ist, dann gibt es keinen Fehler.

2. Wenn ich deleteOldDaysNbl so starte, dass während der Ausführung "NextSync" erreicht wird, passiert folgendes:
- Wenn "NextSync" erreicht ist, geht CacheUsage auf 0
- Zu diesem Zeitpunkt wird kein Fehler geloggt
- CacheUsage steigt dann wieder an
- Wenn deleteOldDaysNbl fertig ist, endet es mit dem Fehler:

Code Auswählen Erweitern

2017.06.02 09:41:58 3: DbLog commonLog -> deleteOldDays finished. 0 entries of database /opt/fhem/dbLog/commonLog.db deleted.
2017.06.02 09:41:58 2: DbLog commonLog -> Error table history - DBD::SQLite::st execute_array failed: executing 152 generated 1 errors at ./FHEM/93_DbLog.pm line 1787.

Der Fehler kommt immmer nur am Ende, auch dann, wenn ich syncInterval sehr kurz mache, z.B. 10 Sekunden.
In dem Fall passiert folgendes:
- deleteOldDaysNbl gestartet
- Wenn "NextSync" das erste mal erreicht ist, geht CacheUsage auf 0 und state bleibt "connected"
- Wenn "NextSync" das zweite mal erreicht ist, zählt CacheUsage weiter hoch und state wird "Commit already running - resync at NextSync"
- Das geht so weiter, bis deleteOldDaysNbl fertig ist
- Dann kommt am Ende der Fehler

Hier die Konfiguration vom device:

Code Auswählen Erweitern

Internals:
   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
   CONFIGURATION ./dbLog/commonLog.conf
   DBMODEL    SQLITE
   DEF        ./dbLog/commonLog.conf .*:.*
   MODE       asynchronous
   NAME       commonLog
   NR         246
   NTFY_ORDER 50-commonLog
   PID        32203
   REGEXP     .*:.*
   STATE      connected
   TYPE       DbLog
   VERSION    2.16.10
   dbconn     SQLite:dbname=/opt/fhem/dbLog/commonLog.db
   dbuser
   Helper:
     COLSET     1
     DELDAYS    30
     DEVICECOL  64
     EVENTCOL   512
     READINGCOL 64
     TYPECOL    64
     UNITCOL    32
     VALUECOL   128
   Readings:
     2017-06-02 09:52:08   CacheUsage      54
     2017-06-02 09:51:24   NextSync        2017-06-02 09:53:24 or if CacheUsage 500 reached
     2017-05-20 11:51:35   countCurrent    22
     2017-05-20 11:51:35   countHistory    3126176
     2017-06-02 09:41:58   lastRowsDeleted 0
     2017-06-02 09:51:25   state           connected
   Cache:
     index      6670
     Memcache:
       6617       2017-06-02 09:51:25|EC3000_7AE4|EC3000|power: 0.2|power|0.2|
       6618       2017-06-02 09:51:26|EC3000_7CA8|EC3000|consumption: 11.948|consumption|11.948|
       6619       2017-06-02 09:51:26|EC3000_7CA8|EC3000|power: 0.2|power|0.2|
       6620       2017-06-02 09:51:27|EC3000_HCS|EC3000|power: 4.7|power|4.7|
       6621       2017-06-02 09:51:28|EC3000_Cubie|EC3000|power: 14.1|power|14.1|
       6622       2017-06-02 09:51:28|EC3000_7E43|EC3000|power: 0.3|power|0.3|
       6623       2017-06-02 09:51:30|EC3000_7AE4|EC3000|power: 0.2|power|0.2|
       6624       2017-06-02 09:51:31|EC3000_7CA8|EC3000|consumption: 11.948|consumption|11.948|
       6625       2017-06-02 09:51:31|EC3000_7CA8|EC3000|power: 0.2|power|0.2|
       6626       2017-06-02 09:51:32|EC3000_HCS|EC3000|power: 4.5|power|4.5|
       6627       2017-06-02 09:51:33|EC3000_Cubie|EC3000|power: 13.6|power|13.6|
       6628       2017-06-02 09:51:33|EC3000_7E43|EC3000|power: 0.2|power|0.2|
       6629       2017-06-02 09:51:35|EC3000_7AE4|EC3000|power: 0.2|power|0.2|
       6630       2017-06-02 09:51:36|EC3000_7CA8|EC3000|consumption: 11.948|consumption|11.948|
       6631       2017-06-02 09:51:36|EC3000_7CA8|EC3000|power: 0.2|power|0.2|
       6632       2017-06-02 09:51:37|EC3000_HCS|EC3000|power: 4.5|power|4.5|
       6633       2017-06-02 09:51:38|EC3000_Cubie|EC3000|power: 13.7|power|13.7|
       6634       2017-06-02 09:51:38|EC3000_7E43|EC3000|power: 0.3|power|0.3|
       6635       2017-06-02 09:51:40|EC3000_7AE4|EC3000|power: 0.2|power|0.2|
       6636       2017-06-02 09:51:41|EC3000_7CA8|EC3000|consumption: 11.948|consumption|11.948|
       6637       2017-06-02 09:51:41|EC3000_7CA8|EC3000|power: 0.3|power|0.3|
       6638       2017-06-02 09:51:42|EC3000_HCS|EC3000|power: 4.5|power|4.5|
       6639       2017-06-02 09:51:43|EC3000_Cubie|EC3000|power: 13.5|power|13.5|
       6640       2017-06-02 09:51:43|EC3000_7E43|EC3000|power: 0.2|power|0.2|
       6641       2017-06-02 09:51:45|EC3000_7AE4|EC3000|power: 0.2|power|0.2|
       6642       2017-06-02 09:51:46|EC3000_7CA8|EC3000|consumption: 11.948|consumption|11.948|
       6643       2017-06-02 09:51:46|EC3000_7CA8|EC3000|power: 0.4|power|0.4|
       6644       2017-06-02 09:51:47|EC3000_HCS|EC3000|power: 4.5|power|4.5|
       6645       2017-06-02 09:51:48|EC3000_Cubie|EC3000|power: 13.6|power|13.6|
       6646       2017-06-02 09:51:48|EC3000_7E43|EC3000|power: 0.3|power|0.3|
       6647       2017-06-02 09:51:50|EC3000_7AE4|EC3000|power: 0.2|power|0.2|
       6648       2017-06-02 09:51:51|EC3000_7CA8|EC3000|consumption: 11.948|consumption|11.948|
       6649       2017-06-02 09:51:51|EC3000_7CA8|EC3000|power: 0|power|0|
       6650       2017-06-02 09:51:52|EC3000_HCS|EC3000|power: 4.6|power|4.6|
       6651       2017-06-02 09:51:53|EC3000_Cubie|EC3000|power: 13.5|power|13.5|
       6652       2017-06-02 09:51:53|EC3000_7E43|EC3000|power: 0.3|power|0.3|
       6653       2017-06-02 09:51:55|EC3000_7AE4|EC3000|power: 0.2|power|0.2|
       6654       2017-06-02 09:51:56|EC3000_7CA8|EC3000|consumption: 11.948|consumption|11.948|
       6655       2017-06-02 09:51:56|EC3000_7CA8|EC3000|power: 0.2|power|0.2|
       6656       2017-06-02 09:51:57|EC3000_HCS|EC3000|power: 4.5|power|4.5|
       6657       2017-06-02 09:51:58|EC3000_Cubie|EC3000|power: 13.6|power|13.6|
       6658       2017-06-02 09:51:58|EC3000_7E43|EC3000|power: 0.3|power|0.3|
       6659       2017-06-02 09:52:00|EC3000_7AE4|EC3000|power: 0.2|power|0.2|
       6660       2017-06-02 09:52:01|EC3000_7CA8|EC3000|consumption: 11.948|consumption|11.948|
       6661       2017-06-02 09:52:01|EC3000_7CA8|EC3000|power: 0.5|power|0.5|
       6662       2017-06-02 09:52:02|EC3000_HCS|EC3000|power: 4.5|power|4.5|
       6663       2017-06-02 09:52:03|EC3000_Cubie|EC3000|power: 13.5|power|13.5|
       6664       2017-06-02 09:52:03|EC3000_7E43|EC3000|power: 0.2|power|0.2|
       6665       2017-06-02 09:52:05|EC3000_7AE4|EC3000|power: 0.2|power|0.2|
       6666       2017-06-02 09:52:06|EC3000_7CA8|EC3000|consumption: 11.948|consumption|11.948|
       6667       2017-06-02 09:52:06|EC3000_7CA8|EC3000|power: 0.2|power|0.2|
       6668       2017-06-02 09:52:07|EC3000_HCS|EC3000|power: 4.5|power|4.5|
       6669       2017-06-02 09:52:08|EC3000_Cubie|EC3000|power: 13.7|power|13.7|
       6670       2017-06-02 09:52:08|EC3000_7E43|EC3000|power: 0.2|power|0.2|
Attributes:
   DbLogSelectionMode Include
   DbLogType  Current/History
   asyncMode  1
   cacheLimit 500
   disable    0
   group      CommonLog
   room       System
   syncInterval 120
   verbose    3

In der Variante "blocking" gibt es keinerlei Fehler, außer den an anderen Stellen durch das Blockieren erzeugten halt.

[DS_Starter]

@HCS , das ist wirklich spannend. Dank deiner ausführlichen Beschreibung ist mir jetzt noch eine Idee gekommen die ich mal checken muss. So ganz passt das Verhalten nicht zu meiner Theorie. Ich melde mich wieder zu dem Thema.

@Joe, das Thema Backup kannst du von der ToDo Liste nehmen​. Für MySql habe es jetzt im DbRep umgesetzt. Läuft nicht blockierend, online im laufenden Betrieb. Ich muss noch ein bisschen feilen und testen . Wenn ich fertig bin Stelle ich die Version im DbRep Forum zur Verfügung. Für die anderen DB Typen würde die Anwendung auch im DbRep angesiedelt.

Grüße
Heiko

[JoeALLb]

@Joe, das Thema Backup kannst du von der ToDo Liste nehmen​.

Erledigt!

[DS_Starter]

Hallo HCS, @all,

denke den Grund für das auf den ersten Blick seltsame Verhalten gefunden zu haben. Der erste Synclauf geht in den Hintergrund und bleibt dort, für FHEM natürlich nicht merkbar, dort "hängen". Deswegen kommt erst beim zweiten Synclauf "Commit already running - resync at NextSync", dann solange bis der deleteOldDays durch ist.
Sobald die Tabellensperre durch deleteOldDays nicht mehr existiert, versucht der in dem Hintergrund auf die Freigabe wartende Prozess die Daten zu schreiben. Wenn es in diesem Schreibprozess zu einem Fehler kommt, wird ein Fehler im Log generiert und die Daten an den Cache zurückgegeben (Works as designed). Daten gehen dadurch nicht verloren die übergebenen Daten in einer Transaktion geschrieben werden.

Nun habe ich DbLog für SQLite so abgeändert, dass bereits innerhalb der Applikation eine Sperre für das Logging gesetzt wird, wenn eine andere schreibende Aktivität (deleteOldDaysNbl, reduceLogNbl) aktiv ist. Auch die Ausgabe in state habe ich etwas angeändert.

Bitte testet bei euch (SQLite), insbesondere HCS, die angehängte Version 2.16.11.
Bei mir habe ich keine Fehlermeldungen provozieren können.

schöne Pfingsgrüße
Heiko

[HCS]

Bitte testet bei euch (SQLite), insbesondere HCS, die angehängte Version 2.16.11.

Habe es mehrfach getestet und es funktioniert mit der 2.16.11 ohne Fehler am Ende und ohne die "erstaunlichen" Verhaltensweisen (CacheUsage geht auf 0) usw.
Vielen Dank für den Bugfix.
Ich beobachte DbLog mal noch etwas genauer im sonstigen Betrieb aber ich denke, dass ich aus SQLite-Sicht eine Freigabe für's Repository empfehlen könnte.

[DS_Starter]

Ich beobachte DbLog mal noch etwas genauer im sonstigen Betrieb aber ich denke, dass ich aus SQLite-Sicht eine Freigabe für's Repository empfehlen könnte.

Danke für die Rückmeldung. Ich werde es auch noch etwas laufen lassen und beobachten und wenn nichts mehr auffällt einchecken.

Grüße
Heiko

[DS_Starter]

Hallo zusammen,

für die Interessenten ....
die DbRep -Version mit dem integrierten Dump/Backup für MySQL-DB ist nun hier https://forum.fhem.de/index.php/topic,53584.msg643931.html#msg643931 beschrieben und zum Test verfügbar.

Grüße
Heiko

[DS_Starter]

Habe soeben Version 2.16.11 eingecheckt.

VG
Heiko

[DS_Starter]

Hallo zusammen,

wegen der hier https://forum.fhem.de/index.php/topic,73114.0.html gestellten Frage zu Abspeicherung von "°C" als "°C"  habe ich mich mal mit dem Thema beschäftigt und eine Version 2.17.0 erstellt,  die UTF8 von MySQL unterstützt. Im DBD-Treiber von MySQL ist UTF8 per default nicht eingeschaltet.

Um die UTF8-Unterstützung einzuschalten, ist ein utf8- Eintrag in der db.conf hinzuzufügen:

Code Auswählen Erweitern


%dbconfig= (
connection => "mysql:database=fhemtest;host=<Host>;port=3306",
user => "<DB-User>",
password => "<PW>",
utf8 => 1,   # enable(1) / disable(0) UTF-8 support of MySQL
);


Danach "set ... rereadcfg". Beim fhem-Start zieht es natürlich gleich.
Ich habe es erst über ein Attribut probiert. Das hat sich allerdings als ungünstig erwiesen weil zum Zeitpunkt der DB-Handle-Erstellung die Attribute noch nicht eingelesen sind und so einfach besser handhabbar ist.
Das Ganze ist rückwärtskompatibel, d.h. wenn der utf-Eintrag ncht gesetzt ist, ist es gleichbedeutend mit "utf8 => 0" (so wie bisher).

Wenn der utf-Eintrag auf "1" gesetzt ist, wird "°C" auch als "°C" abgeseichert, sofern mit dem verwendeten Characterset der DB übereinstimmend.

Probierts mal aus und gebt mir bitte Rückinfo wie ihr die Vorgehensweise findet.

Grüße
Heiko

[DS_Starter]

Hallo zusammen,

habe mit der Version 2.17.1 zwei kleine Unschönheiten gefixt die mir aufgefallen sind. Außerdem ist die Commandref um den Aufbau des Konfigurationsfiles für DbLog ergänzt. Damit hat man das gleich zur Verfügung.

* wenn SVG's in einem room abgearbeitet wurden, gab es es Einträge "UTF8 support enabled" im Log mit verbose 3. Die sollen nur einmal beim Start 
   bzw.  rereadcfg kommen.

* UTF8 Untersützung ist noch für die get-Funktion eingebaut, also wenn man im FHEMWEB eine manuelle Abfrage der Art
  "get LogDB - all 2017-06-18 2017-06-19 MyWetter:temperature" aufruft, werden die Ausgaben bzgl. UNIT ebenfalls korrigiert.

Grüße
Heiko

[JoeALLb]

Ich habe die erste Seite aktualisiert. Testen kann ich das nicht, da ich meine Tabellen aus Performancegründen nicht in UTF8 erstellt habe.
"°C" korrigiere ich im Moment über valueFn.