DbLog - Umstellung Betrieb auf SubProcess -> Tester gesucht

[DS_Starter]

Moin,

Jetzt wird deutlicher dass an irgendeiner Stelle die zu speichernden Daten problematisch sind.
Die Speichermodi arbeiten unterschiedlich. Deswegen ist der Array Modus der Standard.
Er ist langsamer bei Mengendaten, aber behandelt Daten und Fehler anders.

Vllt. bekommen wir die Ursache noch heraus.

Lg

[DS_Starter]

Hi Hanjo,

ich habe im I-net einen Hinweis gefunden den versuche ich heute Abend einzubauen. Ggf gibt es ein Update.

[Hanjo]

Hi Heiko,

na das hört sich ja schon mal gut an 

Im Log habe ich folgendes gefunden, die Meldung dort ist ein bisschen anders als im State Reading:

Code Auswählen Erweitern

2023.01.10 04:26:15 3: DbLog logdb - SubProcess connected to fhem
2023.01.10 04:26:15 2: DbLog logdb - Error table history - DBD::mysql::st execute failed: MySQL server has gone away [for Statement "INSERT IGNORE INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (...)"] at ./FHEM/93_DbLog.pm line 2714.

2023.01.10 04:26:15 2: DbLog logdb - Error - DBD::mysql::db rollback failed: Turning on AutoCommit failed at ./FHEM/93_DbLog.pm line 4129.

2023.01.10 04:26:16 1: PERL WARNING: (in cleanup) DBD::mysql::db DESTROY failed: MySQL server has gone away at ./FHEM/93_DbLog.pm line 2436.
2023.01.10 04:26:16 2: DbLog logdb - Error table history - DBD::mysql::st execute failed: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '' at line 1 [for Statement "INSERT IGNORE INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES"] at ./FHEM/93_DbLog.pm line 2714.

2023.01.10 04:26:31 2: DbLog logdb - Error table history - DBD::mysql::st execute failed: MySQL server has gone away [for Statement "INSERT IGNORE INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (...)"] at ./FHEM/93_DbLog.pm line 2714.

2023.01.10 04:26:31 2: DbLog logdb - Error - DBD::mysql::db rollback failed: Turning on AutoCommit failed at ./FHEM/93_DbLog.pm line 4129.


"MySQL server has gone away", das hatten wir auch schon mal in einem der vorherigen Logs, also habe ich jetzt mal eine Test-Tabelle angelegt und das vollständige SQL Statement aus dem Logfile versucht manuell einzufügen:

Code Auswählen Erweitern

$ mysql -u root -p
Enter password:
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 776
Server version: 10.3.32-MariaDB Source distribution

Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> use fhem;
Database changed
MariaDB [fhem]> source /volume1/Temp/fhem-tmp.sql;
ERROR 2006 (HY000) at line 1 in file: '/volume1/Temp/fhem-tmp.sql': MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    777
Current database: fhem

ERROR 2006 (HY000) at line 1 in file: '/volume1/Temp/fhem-tmp.sql': MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    778
Current database: fhem

ERROR 2006 (HY000) at line 1 in file: '/volume1/Temp/fhem-tmp.sql': MySQL server has gone away

Scheinbar liegt der Fehler an der Konfiguration meines Servers, oder vielmehr an einer unglücklichen Kombination aus Serverkonfiguration und extrem großen Inserts mit mehreren Zehntausend Einträgen. Ist z.B. hier beschrieben:
https://stackoverflow.com/questions/10474922/error-2006-hy000-mysql-server-has-gone-away

Also mal max_allowed_packet erhöhen und neuer Versuch:

Code Auswählen Erweitern

MariaDB [fhem]> set global max_allowed_packet=64*1024*1024;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    779
Current database: fhem

Query OK, 0 rows affected (0.001 sec)

MariaDB [fhem]> source /volume1/Temp/fhem-tmp.sql;
Query OK, 15110 rows affected (1.344 sec)
Records: 15110  Duplicates: 0  Warnings: 0

Tada...

Also gibt es zwei Möglichkeiten:

• Entweder der doofe User (ich) muss den Wert dauerhaft in seiner my.cnf ändern, oder
• Das Modul muss auch bei "Bulk" den Insert bei Überschreiten der kritischen Größe in mehrere kleinere Inserts aufteilen...

Scheinbar habe ich hier einen außergewöhnlichen Fall entdeckt. Komisch nur, dass es mit der alten Version des Moduls kein Problem gab.

Deine Gedanken?

Grüße
Hanjo

[DS_Starter]

Hallo Hanjo,

Code Auswählen Erweitern


Tada... :)

Also gibt es zwei Möglichkeiten:

    Entweder der doofe User (ich) muss den Wert dauerhaft in seiner my.cnf ändern, oder
    Das Modul muss auch bei "Bulk" den Insert bei Überschreiten der kritischen Größe in mehrere kleinere Inserts aufteilen...


Genau das habe ich gerade (als Nebenbei-Effekt) getan. Dadurch verschlechtert sich die Performance des BulkInsert ein ganz klein wenig, aber da wir ohnehin nur noch non-blocking mit dem Subprozess unterwegs sind, ist das nicht der Rede wert.

Die Version liegt im Contrib.

Grüße,
Heiko

[Hanjo]

Ja super, großartig, danke!

Ich habe die Version installiert und bulkInsert wieder auf 1 gesetzt. Werde morgen früh berichten

Gruß
Hanjo

[Hanjo]

Guten Morgen,

heute Nacht ging alles glatt, keine Probleme mehr 

Vielen Dank für deine Unterstützung!

Grüße
Hanjo

[DS_Starter]

Moin,

das hört sich gut an.
Ich werde die Version finalisieren und vermutlich heute Abend einchecken. Es sind jetzt viele Lösungen für gemeldetete Issues eingeflossen.
Das Attr bulkInsert werde ich zukünftig wohl (automatisiert) umbenennen. Durch die Änderungen ist es kein wirklicher BulkInsert mehr.
Der Begriff "insertMode" trifft es dann allgemeiner/besser.

LG

[DS_Starter]

@all,

die neue Version ist als V 5.6.0 eingescheckt.

Die Version enthält alle bisher gemeldeten und gelösten Issues sowie Verbesserungen.
Die für den User sichtbarste Änderung ist

* die Umbenennung des Attributs 'bulkInsert' zu 'insertMode'

Die Umbenennung des Attributs erfolgt automatisch. Der Nutzer muß nicht aktiv werden.

Im Log erscheint beim Start die Meldung:

Code Auswählen Erweitern


..... 2: DbLog <Name> - Subprocess >4631< initialized ... ready for non-blocking operation
..... 3: WARNING: <Name> attribute bulkInsert was renamed to insertMode


LG

[DS_Starter]

Hallo miteinander,

es gibt wieder eine neue Version im contrib.
Wegen dem hier aufgefallenen Issue habe ich die Ausgaben in das Logfile komplett überarbeitet.
Außerdem gibt es einige neue get-Kommandos um "auf die Schnelle" Werte aus der DB ziehen und wenn benötigt Variablen
zuordnen zu können.
Auszug aus der Commandref:

         get <name> ReadingsMaxVal[Timestamp] <Device> <Reading> <default>

        Ermittelt den Datensatz mit dem größten Wert der angegebenen Device / Reading Kombination aus der history Tabelle.
        Zurück gegeben wird nur der Wert oder die Kombination aus Wert und Timestamp als String "<Wert> , <Timestamp>".
        <default> gibt einen definierten Rückgabewert an, wenn kein Wert ermittelt werden kann.

   
   
• get <name> ReadingsMinVal[Timestamp] <Device> <Reading> <default>
  
  
  
        
  • Ermittelt den Datensatz mit dem kleinsten Wert der angegebenen Device / Reading Kombination aus der history Tabelle.
    Zurück gegeben wird nur der Wert oder die Kombination aus Wert und Timestamp als String "<Wert> , <Timestamp>".
    <default> gibt einen definierten Rückgabewert an, wenn kein Wert ermittelt werden kann.
    

   
   
• get <name> ReadingsAvgVal <Device> <Reading> <default>
  
  
  
        
  • Ermittelt den Durchschnittswert der angegebenen Device / Reading Kombination aus der history Tabelle.
    Zurück gegeben wird der einfache arithmetische Durchschnittswert.
    <default> gibt einen definierten Rückgabewert an, wenn kein Wert ermittelt werden kann.
    

   
   
• get <name> ReadingsVal[Timestamp] <Device> <Reading> <default>
  
  
  
        
  • Liest den letzten (neuesten) in der history Tabelle gespeicherten Datensatz der angegebenen Device / Reading Kombination.
    Zurück gegeben wird nur der Wert oder die Kombination aus Wert und Timestamp als String "<Wert> , <Timestamp>".
    <default> gibt einen definierten Rückgabewert an, wenn kein Wert ermittelt werden kann.

   
• get <name> ReadingsTimestamp <Device> <Reading> <default>
         
           Liest den Zeitstempel des letzten (neuesten) in der history Tabelle gespeicherten Datensatzes der angegebenen
           Device/Reading Kombination und gibt diesen Wert zurück.

        <default> gibt einen definierten Rückgabewert an, wenn kein Wert in der Datenbank gefunden wird.


Zu beachten ist, dass alle die Kommandos blockierend arbeiten.

Die Version liegt wieder zunächst in meinem contrib.

[betateilchen]

Super, danke! Werde ich in den nächsten Tagen testen.

[DS_Starter]

Ich habe DbLog noch ein Get-Menü spendiert.
Damit ist es nun für den User leichter eine schnelle Abfrage der DB über die vorderfinierten Getter auszuführen.
Es ist auch ein leichter Vorgriff weil ich noch Ideen habe die Get-Möglichkeiten zu erweitern.

Liegt im contrib zum Test.

Frage zu webchart und Tabell Frontend hat sich erledigt. Habe weiter recherchiert und alle Infos dazu gefunden soweit.

[thburkhart]

kann es sein, dass es nun mit dblogreduce der Probleme gibt.

Dies trat heute Nacht erstmals auf:

Code Auswählen Erweitern

2023.01.27 02:00:05 3: DbRep Reduce_Daily - Initial data information retrieved - total time used: 5.7753 seconds
2023.01.27 02:00:06 3: DbRep Reduce_Daily - Connectiontest to db mysql:database=fhem;host=localhost;port=3306 successful
2023.01.27 02:00:06 3: DbRep Reduce_Daily - reduce data older than: 2022-12-28 23:59:59, newer than: 2022-12-26 00:00:00
2023.01.27 02:00:06 3: DbRep Reduce_Daily - reduceLog requested with options:
average=day
INCLUDE -> Devs: % Readings: %
2023.01.27 02:00:17 3: DbRep Reduce_Daily - reduceLog (daily-average) updating 250, deleting 4426 records of day: 2022-12-26
2023.01.27 02:01:21 2: DbLog dblog_THB - ERROR table history - DBD::mysql::st execute failed: Lock wait timeout exceeded; try restarting transaction [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)" with ParamValues: 0='2023-01-27 02:00:01', 1='TX29DTH_16', 2='LACROSSE', 3='state: T: 19.8 H: 26', 4='state', 5='T: 19.8 H: 26', 6=undef] at ./FHEM/93_DbLog.pm line 2769.

2023.01.27 02:01:21 2: DbLog dblog_THB - Transaction is switched off. Transferred data is lost.
2023.01.27 02:02:21 2: DbLog dblog_THB - ERROR table history - DBD::mysql::st execute failed: Lock wait timeout exceeded; try restarting transaction [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)" with ParamValues: 0='2023-01-27 02:00:31', 1='MAX_BAD_HT', 2='MAX', 3='valveposition: 47', 4='valveposition', 5='47', 6='%'] at ./FHEM/93_DbLog.pm line 2769.

und noch viele, viele weitere bis 8:00



ich hatte es daran bemerkt, dass ich in den Gplots seit 2:00 nichts mehr angezeigt wurde.
Nach shutdown restart wurde danach wieder korrekt in die DB geschrieben.

das ist wohl das zugrundeliegende DEF:

Code Auswählen Erweitern

[code]define Reduce_Daily DbRep dblog_THB
attr Reduce_Daily room DBLog
attr Reduce_Daily showproctime 1
attr Reduce_Daily timeDiffToNow d:32
attr Reduce_Daily timeOlderThan d:30
#   DATABASE   fhem
#   DEF        dblog_THB
#   FUUID      63b06a6d-f33f-fd5f-cbee-933b87fab6caca0d
#   FVERSION   93_DbRep.pm:v8.51.3-s27102/2023-01-22
#   LASTCMD    initial database connect stopped due to attribute 'fastStart'
#   MODEL      Client
#   NAME       Reduce_Daily
#   NOTIFYDEV  global,Reduce_Daily
#   NR         121
#   NTFY_ORDER 50-Reduce_Daily
#   ROLE       Client
#   STATE      initialized
#   TYPE       DbRep
#   UTF8       0
#   HELPER:
#     DBLOGDEVICE dblog_THB
#     IDRETRIES  3
#     PACKAGE    main
#     VERSION    8.51.3
#   READINGS:
#     2023-01-27 14:33:39   state           initialized
#
setstate Reduce_Daily initialized
setstate Reduce_Daily 2023-01-27 14:33:39 state initialized

[/code]

[DS_Starter]

kann es sein, dass es nun mit dblogreduce der Probleme gibt.

Eher nicht.

Das liegt daran dass die Tabelle history während des reducelog gesperrt ist.
Der DbLog Prozess läuft dann irgendwann auf einen Timeout ->

DbLog dblog_THB - ERROR table history - DBD::mysql::st execute failed: Lock wait timeout exceeded;

wenn reducelog bzw. die Tabellensperre zu lange dauert.

Um das Problem zu verhindern bietet sich an im DbRep Attr executeBeforeProc vor dem reducelog DbLog zu "pausieren"

Code Auswählen Erweitern


executeBeforeProc  set <DbLog> reopen 86400


und im Attr executeAfterProc  wieder zu starten:

Code Auswählen Erweitern


executeAfterProc  set <DbLog> reopen


[thburkhart]

Eher nicht.

Das liegt daran dass die Tabelle history während des reducelog gesperrt ist.
Der DbLog Prozess läuft dann irgendwann auf einen Timeout ->

wenn reducelog bzw. die Tabellensperre zu lange dauert.

Um das Problem zu verhindern bietet sich an im DbRep Attr executeBeforeProc vor dem reducelog DbLog zu "pausieren"

Code Auswählen Erweitern


executeBeforeProc  set <DbLog> reopen 86400


und im Attr executeAfterProc  wieder zu starten:

Code Auswählen Erweitern


executeAfterProc  set <DbLog> reopen


oh danke

wo baue ich das genauer ein:

das findet vorher statt:

Code Auswählen Erweitern

2023.01.27 00:18:39 3: DbRep ReportDbLog_THB - 2084126 records inserted (size of backupfile: 418.90 MB)
2023.01.27 00:18:39 3: DbRep ReportDbLog_THB - Deleting old dumpfile 'fhem_2023_01_24_00_10.sql'
2023.01.27 00:18:39 3: DbRep ReportDbLog_THB - Finished backup of database fhem - total time used (hh:mm:ss): 00:08:39
2023.01.27 00:18:40 3: DbRep ReportDbLog_THB - Database dump finished successfully.
2023.01.27 01:08:36 1: PERL WARNING: Use of uninitialized value $type in hash element at ./FHEM/14_CUL_MAX.pm line 821.
2023.01.27 01:08:36 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/14_CUL_MAX.pm line 821.
2023.01.27 01:08:36 1: PERL WARNING: Use of uninitialized value $testresult in concatenation (.) or string at ./FHEM/14_CUL_MAX.pm line 821.
2023.01.27 01:08:36 1: PERL WARNING: Use of uninitialized value $serial in concatenation (.) or string at ./FHEM/14_CUL_MAX.pm line 821.
2023.01.27 01:30:00 3: DbLog dblog_THB - Reopen requested
2023.01.27 01:30:00 3: set dblog_THB reopen : Reopen executed.
2023.01.27 01:30:00 3: DbLog_reopen: Reopen executed.
2023.01.27 01:30:00 3: DbLog dblog_THB - Database disconnected by request.
2023.01.27 01:30:00 3: DbLog dblog_THB - SubProcess connected to fhem
2023.01.27 02:00:00 3: DbRep Reduce_Daily - ################################################################
2023.01.27 02:00:00 3: DbRep Reduce_Daily - ###                    new reduceLog run                     ###
2023.01.27 02:00:00 3: DbRep Reduce_Daily - ################################################################
2023.01.27 02:00:00 3: DbRep Reduce_Daily - get initial structure information of database "fhem", remaining attempts: 3
2023.01.27 02:00:00 3: DbRep Reduce_Daily - Connectiontest to database mysql:database=fhem;host=localhost;port=3306 with user fhemuser

der automatisierte dump wurde also korrekt abgeschlossen.
Dann erfolgt ebenso automatisiert um 1:30 ein reopen ; also genau zu falschen Zeit vorher statt nachher?

wie genauer baue ich also die "Verhinderungsbefehle" ein?

[DS_Starter]

wie genauer baue ich also die "Verhinderungsbefehle" ein?

In deinem DbRep Reduce_Daily setzt du

Code Auswählen Erweitern

attr Reduce_Daily  executeBeforeProc  set dblog_THB reopen 86400

und

Code Auswählen Erweitern

attr Reduce_Daily  executeAfterProc  set dblog_THB reopen