[Gelöst] DBLog SQLite Problem: st execute_array failed

Begonnen von Elektrofreak, 08 März 2017, 09:35:05

Vorheriges Thema - Nächstes Thema

DS_Starter

#15
ZitatWas mir jetzt nach der Arbeit aber erst auffiel ist, dass es ohne commitMode=basic_ta:off nicht funktioniert.
Dieses Attribut hilft allerdings nur die Wirkung zu beseitigen und nicht die Ursache selbst.

ZitatAlso wieder aktiviert und dann hat er jetzt erstmal alle Cache Einträge wieder übertragen.

Hattest du gestern noch das Cachefile importiert und hat das geklappt ?
Wird wirklich der gesamte Cache auf 0 geleert oder bleiben alte Datensätze enthalten ?

Wie sieht denn der Cachinhalt aus, kurz (ca. 1Min.) nachdem du "commitMode=basic_ta:off" gelöscht hast ?
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

Bond246

Das Cache-File wurde importiert, ohne Probleme.
Und wenn ich jetzt nach dem setzen des commitMode in den Cache schaue, wird der auch abgebaut.

Heute ist es allerdings so, dass sich nach ein paar Minuten immer mal wieder 1-2000 Meldungen aufstauen, die dann nicht wie geplant nach 2min in der Datenbank gespeichert werden, sondern vielleicht erst nach 5-10min.
Also der Datenbank-Output ist entweder langsam oder vorrübergehend gar nicht möglich.

DS_Starter

Das sieht mir auch nach Performance-Problem aus.

Setze dir im DbLog noch die Attribute


showproctime = 1
showNotifyTime = 1
cacheEvents = 2


Das hilft uns bessere Aussagen darüber zu treffen. Bei so vielen Meldungen ist es aber auch nicht einfach den "Schuldigen" zu finden.
Aber ich bin immer noch der Überzeugung dass es ein bestimmter Event ist der die Probleme verursacht. Auch wenn es vllt. nicht der MAX ist.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

Bond246

Hier mit den neuen Attributen nochmal die Internals und Readings:
Internals:
   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
   CONFIGURATION ./db.conf
   DEF        ./db.conf .*:.*
   MODE       asynchronous
   MODEL      MYSQL
   NAME       Logdb
   NR         17
   NTFY_ORDER 50-Logdb
   PID        23112
   REGEXP     .*:.*
   STATE      Commit already running - resync at NextSync
   TYPE       DbLog
   UTF8       1
   VERSION    3.12.2
   dbconn     mysql:database=fhem;host=diskstation;port=3307
   dbuser     fhemuser
   HELPER:
     COLSET     1
     DEVICECOL  64
     EVENTCOL   512
     LASTLIMITRUNTIME 1539190439.75544
     OLDSTATE   Commit already running - resync at NextSync
     READINGCOL 64
     TYPECOL    64
     UNITCOL    32
     VALUECOL   128
   READINGS:
     2018-10-10 18:57:29   CacheUsage      81
     2018-10-10 18:57:29   NextSync        2018-10-10 18:57:59 or if CacheUsage 500 reached
     2018-10-10 18:53:57   background_processing_time 446.4368
     2018-10-10 00:04:16   lastCachefile   ./log/cache_Logdb_2018-10-09_23-18-11 import successful
     2018-10-10 18:57:21   notify_processing_time 0.0097
     2018-10-10 03:02:03   reduceLogState  reduceLogNbl finished. Rows processed: 264204, deleted: 26997, updated: 556, time: 123.00sec
     2018-10-10 18:53:57   sql_processing_time 445.7042
     2018-10-10 18:57:29   state           Commit already running - resync at NextSync
   cache:
     index      5663566
Attributes:
   DbLogExclude .*
   DbLogSelectionMode Exclude/Include
   DbLogType  Current/History
   asyncMode  1
   cacheEvents 2
   commitMode basic_ta:off
   room       Logs
   showNotifyTime 1
   showproctime 1
   shutdownWait 2
   useCharfilter 1


Zwischenzeitlich übrigens Caches bis 13/14.000

DS_Starter

Ziemlich eindeutig


sql_processing_time  -> 445.7042


Heißt, deine DB braucht 445 Sekunden um die, sagen wir 2000 Datensätze wegzuschreiben.
Die kommt schlicht nicht mehr hinterher.

Frage ist natürlich warum ?
Hast du auf Syno neue Pakete installiert die die DB nutzen / verlangsamen ?

Bin mir noch unsicher, aber du könntest versuchen mal auf den Synchmode umzuschalten. Aber sei vorsichtig, es kann passieren dass dein FHEM dann nicht mehr reagiert weil deine DB nicht so reagiert wie sie soll.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

Bond246

das ist es eben, ich hab eigentlich gar nichts gemacht in den letzten Tagen.
Weder Updates, noch neue Pakete installiert.

Ich überlege, einfach mal den Ort der Datenbank zu meinem Web-Anbieter all-inkl. zu wechseln.
Allerdings will ich das eigentlich nicht dauerthaft.

Auf dem RasPi wollte ich die Datenbank eigentlich auch nicht mehr haben, um etwas mehr Datensicherheit und gleichzeitig aber auch um mehr Performance zu haben.

Wenn ich die Möglichkeit hätte, würde ich die Datenbank in einen Docker auf der Synology selbst zu installieren. Aber meine ist nicht Docker-fähig.

Ich hab über HeidiSQL auch schon nen Datenbank Repair und nen Optimizing probiert - ohne Erfolg.

DS_Starter

Die DB läuft auf der Syno normalerweise auch einwandfrei, habe ich auch so. Du warst bisher ja auch glücklich, nur irgendwas spuckt gerade etwas in die Suppe.

Wenn so viele Events in so kurzer Zeit auflaufen werden die fehlerhaften Sätze wahrschein kumuliert.
Versuche mal verbose 4 im Dblog einzuschalten und den Output zu posten.

Leider habe ich heute nicht mehr so viel Zeit, vllt. später wieder.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

Bond246

Ich fasse mal die letzten Änderungen der letzten Wochen zusammen:

Ich habe mir einen holiday Plan "brandenburg" angelegt, um Feiertage in die $we Variable rein zu bekommen.
Das habe ich dann in meinen Heating_Controll Devices eingeplant. Da steht jetzt also statt 06|Uhrzeit|Temp => $we|Uhrzeit|Temp.

Und mit erstaunen stelle ich fest, dass es das auch schon war. Außerdem ist mit einem der letzten Updates noch die neue UI hinzugekommen und damit ein paar optische Anpassungen der Web-Oberfläche.

Ich hatte erst gedacht, vielleicht habe ich irgendwo ein DbLogExclud vergessen. Dem ist aber nicht so. Ich hab die wöchentlichen Backups der letzten Wochen vergleichen. Die sind bis auf die genannten Änderungen identsich.

Als nächstes hab ich mit DbRep mal einen 15min Datensatz aus der Datenbank gezählt und in csv exportiert. Je einmal mit Daten von vor einem Monat und von heute. Es sind ungefähr 3x so viele Daten, die in 15min angefallen sind. Zum einen 326 und zum anderen 1077.
Und beim Durchsehen der einzelnen Devices, die ich mir in Excel dann gefiltert habe, fällt mir auf, dass pro Zeitstempel z.T. bis zu 5x das gleiche Event mit den gleichen Werten gespeichert wurde. Wenn dann z.B. bis zu 6 verschiedenen Events gespeichert werden und die jeweils dann 5x, dann sind das schon 30 Logs.
Üblicherweise habe ich bei meinen Devices aber ein event-min-interval von 90 oder 120sek. Der wird zwar eingehalten aber es werden eben mehr Daten geschrieben.

Von vorgestern hab ich auch noch einen csv-Datensatz gezogen. Da bestand das Problem noch nicht. Da gibt es auch noch keine multible Datenhaltung.

Bond246

Hier noch der Log-Output mit verbose=4
2018.10.10 22:29:09 2: DbLog Logdb -> Error table history - DBD::mysql::st execute_array failed: executing 17227 generated 1408 errors at ./FHEM/93_DbLog.pm line 2063.

2018.10.10 22:34:31 4: DbLog Logdb -> ################################################################
2018.10.10 22:34:31 4: DbLog Logdb -> ###              start of new Logcycle                       ###
2018.10.10 22:34:31 4: DbLog Logdb -> ################################################################
2018.10.10 22:34:31 4: DbLog Logdb -> number of events received: 1 for device: mqtt
2018.10.10 22:34:31 4: DbLog Logdb -> check Device: mqtt , Event: connection: active
2018.10.10 22:34:37 4: DbLog Logdb -> ################################################################
2018.10.10 22:34:37 4: DbLog Logdb -> ###              start of new Logcycle                       ###
2018.10.10 22:34:37 4: DbLog Logdb -> ################################################################
2018.10.10 22:34:37 4: DbLog Logdb -> number of events received: 4 for device: Thermometer.Bad
2018.10.10 22:34:37 4: DbLog Logdb -> check Device: Thermometer.Bad , Event: battery: ok
2018.10.10 22:34:37 4: DbLog Logdb -> check Device: Thermometer.Bad , Event: temperature: 22.6
2018.10.10 22:34:37 4: DbLog Logdb -> added event - Timestamp: 2018-10-10 22:34:37, Device: Thermometer.Bad, Type: LACROSSE, Event: temperature: 22.6, Reading: temperature, Value: 22.6, Unit: °C
2018.10.10 22:34:37 4: DbLog Logdb -> Number of cache entries reached cachelimit 500 - start database sync.
2018.10.10 22:34:37 4: DbLog Logdb -> ################################################################
2018.10.10 22:34:37 4: DbLog Logdb -> ###              start of new Logcycle                       ###
2018.10.10 22:34:37 4: DbLog Logdb -> ################################################################
2018.10.10 22:34:37 4: DbLog Logdb -> number of events received: 1 for device: Logdb
2018.10.10 22:34:37 4: DbLog Logdb -> check Device: Logdb , Event: CacheUsage: 17382
2018.10.10 22:34:37 4: DbLog Logdb -> ################################################################
2018.10.10 22:34:37 4: DbLog Logdb -> ###      New database processing cycle - asynchronous        ###
2018.10.10 22:34:37 4: DbLog Logdb -> ################################################################
2018.10.10 22:34:37 4: DbLog Logdb -> MemCache contains 17382 entries to process
2018.10.10 22:34:37 4: DbLog Logdb -> DbLogType is: Current/History
2018.10.10 22:34:38 4: DbLog Logdb -> AutoCommit mode: ON, Transaction mode: OFF
2018.10.10 22:39:45 2: DbLog Logdb -> Error table history - DBD::mysql::st execute_array failed: executing 17382 generated 1427 errors at ./FHEM/93_DbLog.pm line 2063.

2018.10.10 22:45:14 4: DbLog Logdb -> ################################################################
2018.10.10 22:45:14 4: DbLog Logdb -> ###              start of new Logcycle                       ###
2018.10.10 22:45:14 4: DbLog Logdb -> ################################################################
2018.10.10 22:45:14 4: DbLog Logdb -> number of events received: 8 for device: PID.Bad
2018.10.10 22:45:14 4: DbLog Logdb -> check Device: PID.Bad , Event: desired: 24.0
2018.10.10 22:45:14 4: DbLog Logdb -> added event - Timestamp: 2018-10-10 22:45:14, Device: PID.Bad, Type: PID20, Event: desired: 24.0, Reading: desired, Value: 24.0, Unit:
2018.10.10 22:45:14 4: DbLog Logdb -> Number of cache entries reached cachelimit 500 - start database sync.
2018.10.10 22:45:14 4: DbLog Logdb -> ################################################################
2018.10.10 22:45:14 4: DbLog Logdb -> ###              start of new Logcycle                       ###
2018.10.10 22:45:14 4: DbLog Logdb -> ################################################################
2018.10.10 22:45:14 4: DbLog Logdb -> number of events received: 1 for device: Logdb
2018.10.10 22:45:14 4: DbLog Logdb -> check Device: Logdb , Event: CacheUsage: 17518
2018.10.10 22:45:14 4: DbLog Logdb -> ################################################################
2018.10.10 22:45:14 4: DbLog Logdb -> ###      New database processing cycle - asynchronous        ###
2018.10.10 22:45:14 4: DbLog Logdb -> ################################################################
2018.10.10 22:45:14 4: DbLog Logdb -> MemCache contains 17518 entries to process
2018.10.10 22:45:14 4: DbLog Logdb -> DbLogType is: Current/History
2018.10.10 22:45:14 4: DbLog Logdb -> AutoCommit mode: ON, Transaction mode: OFF

DS_Starter

ZitatUnd mit erstaunen stelle ich fest, dass es das auch schon war.
Du meinst der Grund für das Problem ?

ZitatVon vorgestern hab ich auch noch einen csv-Datensatz gezogen. Da bestand das Problem noch nicht. Da gibt es auch noch keine multible Datenhaltung.
Das mehrfache Speichern eines Datensatzes kann eine Nebenwirkung mit der speziellen Einstellung "commitMode=basic_ta:off" sein.
In diesem Support-Mode werden trotz fehlerhafter Datensätze die nicht fehlerhaften in der DB gespeichert (sonst nicht wegen des Transaktionsmodus). Dennoch wird das übergebene Array zurück geführt.

Das Verhalten ist nicht gewünscht und habe es korrigiert. Du kannst die Version von DbLog hier herunter laden:

https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

Lade dir mal bitte die Version mit dem Download-Button auf der Seite nach ./FHEM und "reload 93_DbLog".
Wie gesagt, es korrigiert nur das beschriebene Verhalten für die spezielle commitMode-Einstellung die man ja nur im Supportfall einschalten soll.

Ganz nebenbei der Hinweis, dass man generell doppelte Datensätze in der DB verhindern kann indem man einen Primary Key (PK) setzt. DbLog unterstützt einen solchen Key. Aber das hat nichts mit dem Problem an sich zu tun.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

Bond246

ok, jetzt rödelt die Synology schonmal deutlich weniger.
Die Processing_times sind auch deutlich zurück gegangen:
   READINGS:
     2018-10-10 23:07:54   CacheUsage      0
     2018-10-10 23:07:53   NextSync        2018-10-10 23:08:23 or if CacheUsage 500 reached
     2018-10-10 23:07:54   background_processing_time 0.3661
     2018-10-10 00:04:16   lastCachefile   ./log/cache_Logdb_2018-10-09_23-18-11 import successful
     2018-10-10 23:07:36   notify_processing_time 0.0058
     2018-10-10 03:02:03   reduceLogState  reduceLogNbl finished. Rows processed: 264204, deleted: 26997, updated: 556, time: 123.00sec
     2018-10-10 23:07:54   sql_processing_time 0.3378
     2018-10-10 23:07:54   state           connected
   cache:
     index      137


Der Fehler besteht aber noch  :P
2018.10.10 23:06:53 2: DbLog Logdb -> Error table history - DBD::mysql::st execute_array failed: executing 11 generated 3 errors at ./FHEM/93_DbLog.pm line 2065.

DS_Starter

Ja, aber mit 11 zu prozessierenden DAtensätzen kann man noch umgehen. ;-)
Die DbLog Version ist drin und "commitMode=basic_ta:off" gesetzt ?



ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

DS_Starter

Aber ich muss für heute Schluss machen, muß morgen früh raus.
Kannst ja noch etwas forschen. Stell mal bitte verbose 5 im dblog ein und poste dann einen Ausschnitt von einem "New database processing cycle - asynchronous" komplett.
Schaue ich morgen an ...

Grüße
Heiko
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

Bond246

#28
Zitat von: DS_Starter am 10 Oktober 2018, 23:13:32
Die DbLog Version ist drin und "commitMode=basic_ta:off" gesetzt ?
Jo, commitMode gesetzt und die neue DbLog Version ist auch installiert. Ich denke die neue Version ist der ausschlaggebende Punkt, dass er nicht mehr so viele Daten verarbeiten muss :-)

Zitat von: DS_Starter am 10 Oktober 2018, 23:18:21
Aber ich muss für heute Schluss machen, muß morgen früh raus.
Kannst ja noch etwas forschen. Stell mal bitte verbose 5 im dblog ein und poste dann einen Ausschnitt von einem "New database processing cycle - asynchronous" komplett.
Schaue ich morgen an ...

Grüße
Heiko

Kein Problem. Ich mach dann jetzt auch gleich Schluss für heute.
Der processing cycle ist anbei.

In diesem Sinne gute Nacht und vielen vielen Dank für die Hilfe!

DS_Starter

Der Logausschnitt ist genau der richtige. Aber leider zu kurz. Das war wie im Film ... gerade als es spannend wurde kam die Werbung bzw. hier das Ende  ;)

Kannst du das bitte nochmal machen ?
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter