DBLog Problem - cache export

[erwin]

Ich hatte heute, genau zwischen 00:00:00 und 01:00:00 Uhr folgende Log-msgs:

Code Auswählen Erweitern

2021.10.31 00:04:33.028 2: DbLog myDbLog -> WARNING - Cache is exported to file instead of logging it to database
2021.10.31 00:04:33.038 3: DbLog myDbLog: 1071 cache rows exported to ./log/cache_myDbLog_2021-10-31_00-04-33.
2021.10.31 00:04:33.041 3: DbLog myDbLog: Cache purged after exporting rows to ./log/cache_myDbLog_2021-10-31_00-04-33.
2021.10.31 00:04:33.058 2: DbLog myDbLog -> WARNING - Cache is exported to file instead of logging it to database
2021.10.31 00:04:33.070 3: DbLog myDbLog: 1 cache rows exported to ./log/cache_myDbLog_2021-10-31_00-04-33.
2021.10.31 00:04:33.080 3: DbLog myDbLog: Cache purged after exporting rows to ./log/cache_myDbLog_2021-10-31_00-04-33.
...
...
2021.10.31 00:57:25.029 2: DbLog myDbLog -> WARNING - Cache is exported to file instead of logging it to database
2021.10.31 00:57:25.039 3: DbLog myDbLog: 1106 cache rows exported to ./log/cache_myDbLog_2021-10-31_00-57-25.
2021.10.31 00:57:25.042 3: DbLog myDbLog: Cache purged after exporting rows to ./log/cache_myDbLog_2021-10-31_00-57-25.
2021.10.31 00:57:25.053 2: DbLog myDbLog -> WARNING - Cache is exported to file instead of logging it to database
2021.10.31 00:57:25.062 3: DbLog myDbLog: 1 cache rows exported to ./log/cache_myDbLog_2021-10-31_00-57-25.
2021.10.31 00:57:25.069 3: DbLog myDbLog: Cache purged after exporting rows to ./log/cache_myDbLog_2021-10-31_00-57-25.

und das alle 4 Minuten! Nach 01:00:00 Uhr läuft alles ganz normal weiter, allerdings sind die Einträge in den log -files überschrieben.....
weil:
00:57:25.039 3: DbLog myDbLog: 1106 cache rows exported to ./log/cache_myDbLog_2021-10-31_00-57-25. gleicher filename wie:
00:57:25.062 3: DbLog myDbLog: 1 cache rows exported to ./log/cache_myDbLog_2021-10-31_00-57-25.
2 ideen zur Lösung:
1) erweitern des dateinames um millisekunden.
2) statt ein dblog write auzulösen, mit den events, die von dblog selbst ausgelöst werden - diese events in den cache schreiben und beim nächsten cycle in die DB schreiben.

Beispiel der 1zeiligen export datei:

Code Auswählen Erweitern

2021-10-31 00:04:33|myDbLog|DBLOG|CacheOverflowLastNum: 70|CacheOverflowLastNum|70|

List dblog-device:

Code Auswählen Erweitern

Internals:
   .FhemMetaInternals 1
   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
   CONFIGURATION ./fhem_cldb.cfg
   DEF        ./fhem_cldb.cfg .*:.*
   FUUID      5c7ceaf9-f33f-5c4d-3dd8-e4f0c81d772a9ed6
   FVERSION   93_DbLog.pm:v4.12.3-s24440/2021-05-15
   MODE       asynchronous
   MODEL      MYSQL
   NAME       myDbLog
   NR         25
   NTFY_ORDER 50-myDbLog
   PID        11647
   REGEXP     .*:.*
   STATE      connected
   TYPE       DbLog
   UTF8       1
   dbconn     mysql:database=fhem;host=192.168.x.y;port=3306
   dbuser     xxxxxxxxxx
   .attraggr:
   .attrminint:
   HELPER:
     COLSET     1
     DEVICECOL  64
     EVENTCOL   512
     OLDSTATE   connected
     PACKAGE    main
     READINGCOL 64
     TC         current
     TH         history
     TYPECOL    64
     UNITCOL    32
     VALUECOL   128
     VERSION    4.12.3
   Helper:
     DBLOG:
       CacheOverflowLastNum:
         myDbLog:
           TIME       1635661817.33955
           VALUE      0
       CacheUsage:
         myDbLog:
           TIME       1635663258.14745
           VALUE      24
       background_processing_time:
         myDbLog:
           TIME       1635663258.57845
           VALUE      0.3295
       lastCachefile:
         myDbLog:
       sql_processing_time:
         myDbLog:
           TIME       1635663258.57845
           VALUE      0.1183
       state:
         myDbLog:
           TIME       1635634802.6827
           VALUE      connected
   READINGS:
     2021-10-31 07:54:18   CacheOverflowLastNum 0
     2021-10-31 00:58:26   CacheOverflowLastState normal
     2021-10-31 07:56:01   CacheUsage      33
     2021-10-31 07:54:18   NextSync        2021-10-31 07:56:18 or if CacheUsage 200 reached
     2021-10-31 07:54:18   background_processing_time 0.3295
     2021-08-30 11:55:12   countCurrent    62
     2021-08-30 11:55:12   countHistory    19468961
     2021-10-31 00:57:25   lastCachefile   ./log/cache_myDbLog_2021-10-31_00-57-25 (1 cache rows exported)
     2017-03-02 16:39:36   lastRowsDeleted 96882
     2019-01-30 10:14:01   reduceLogState  DBD::mysql::st execute failed: Error writing file '/tmp/MYMZePMF' (Errcode: 28) at ./FHEM/93_DbLog.pm line 4291.

     2021-10-31 07:54:18   sql_processing_time 0.1183
     2021-10-31 07:54:18   state           connected
   helper:
     bm:
       DbLog_Get:
         cnt        1
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        31.10. 02:06:03
         max        8.98838043212891e-05
         tot        8.98838043212891e-05
         mAr:
           HASH(0x12e3968)
           myDbLog
           ?
       DbLog_Log:
         cnt        60379
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        31.10. 01:00:11
         max        0.12580394744873
         tot        224.584052801132
         mAr:
           HASH(0x12e3968)
           HASH(0x27abab0)
       DbLog_Set:
         cnt        8692
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        31.10. 00:04:33
         max        0.0217399597167969
         tot        10.9626753330231
         mAr:
           HASH(0x12e3968)
           myDbLog
           exportCache
           purgecache
Attributes:
   DbLogExclude NextSync,last.*,reduce.*,.*:1800
   DbLogSelectionMode Exclude/Include
   DbLogType  History
   addStateEvent 1
   asyncMode  1
   bulkInsert 1
   cacheEvents 2
   cacheLimit 200
   cacheOverflowThreshold 1000
   excludeDevs global
   room       Global
   showNotifyTime 0
   showproctime 1
   syncInterval 120
   timeout    86400
   valueFn    {($IGNORE,$TIMESTAMP,$DEVICE,$DEVICETYPE,$READING,$VALUE,$UNIT) = myValueFn($TIMESTAMP, $DEVICE, $DEVICETYPE, $READING, $VALUE, $UNIT)}
Warum dblog nicht schreiben konnte, ist mr nicht ganz klar, weil es sonst keine Fehlermeldungen gibt, ich vermute stark, dass es mit:
https://forum.fhem.de/index.php/topic,115255.0.html zusammen hängt . nachdem nachher alles wieder ganz normal läuft!!!
Error msg gibts von anderen Modulen unmittelbar nach 01:00:00 Uhr, - reconnects (z.b. MQTT2), usw, deutet darauf hin dass in der Zeit die Kommunictation sehr gestört war!

l.g. erwin

[DS_Starter]

Hallo erwin,

warum nicht in die DB geschrieben werden konnte wäre natürlich herauszubekommen.
Aber den Dateinamen um Millisekunden zu erweitern halte ich für unnötig. Das beschriebene Verhalten ist völig untypisch den Cache Export mit einer Frequenz kleiner 1 Sekunde auszuführen.

Es gibt folgende Optimierungen:

1.  stelle das Attr cacheOverflowThreshold auf z.B. 5000. Dann wird der Schreibvorgang in das File nur ausgelöst wenn >= 5000 Events im Cache liegen. Das passiert dann sicherlich nicht < 1 Sek. Wundere mich natürlich dass mehr als 1000 Events pro Sekunde auflaufen ?

2. von DbLog selbst erzeugte Events kann man vom Logging komplett ausschließen mit attr <device> excludeDevs global,TYPE=DbLog

statt ein dblog write auzulösen, mit den events, die von dblog selbst ausgelöst werden - diese events in den cache schreiben und beim nächsten cycle in die DB schreiben.

es wird nie (im Asynch Mode) ein direktes Schreiben in die DB ausgelöst. Es erfolgt immer zunächst ein Insert in den Cache. Der cycle wird nur in Abhängigkeit der Attribute cacheLimit, syncInterval in die DB gestartet.
Nur wenn attr cacheOverflowThreshold überschritten wird, erfolgt das Schreiben in ein File.

Grüße,
Heiko

[erwin]

Hallo Heiko,
warum nicht in die db geschrieben werden konnte, ist mit höchster Wahrscheinlichkeit klar. - siehe meinen link zum Astro thread. Alles was mit Internal Timer zu tun hatte ging nicht!

Da geb ich dir nicht recht .. (ob jetzt ein direktes write oder unmittelbar ein cache write lasse ich jetzt mal offen):

es wird nie (im Asynch Mode) ein direktes Schreiben in die DB ausgelöst

sie dir mal die Timestamps an, da sind 30ms zwischen den WARNINGS msgs - und das obwohl das cache-overflow auf 1000 steht und cache limit auf 200 und sync-interval auf 120 - Dennoch wird ein write ausgelöst, mit genau einem event! und dieser event - vom DbLog-Modul -(weil in der gleichen sekunde) überschreibt die 30ms vorher geschriebene file!
Wie es zu den 1000 events kommt, ist mir auch nicht klar, jedenfalls nicht innerhalb einer sekunde, üblicherweise hab ich 30-60 events innerhalb 120 sekunden im cache...
Ich hatte schon die Situation, das die db down (Netzwerk) war, das hat das immer bestens funktioniert - da wurden logs geschrieben mit knapp über 1000 lines! 1000 lines entsprechen etwa einer stunde keine DB, kann ich bei Bedarf liefern 

Die events vom dblog möchte ich nicht ausschließen... die machen absolut Sinn!
l.g. erwin

[DS_Starter]

Da geb ich dir nicht recht .. (ob jetzt ein direktes write oder unmittelbar ein cache write lasse ich jetzt mal offen):

Ich habe mich nochmal im Code versichert. Es gibt außerhalb der DbLog_execmemcache Routine keinen Absprung zu DbLog_writeFileIfCacheOverflow in der das Schreiben ins File stattfindet.
DbLog_execmemcache  selbst wird ausschließlich zeitgesteuert, oder bei bestimmten Aktionen die nicht eventabhängig sind, ausgeführt.

Aber du bist ja selbst Dev, falls du eine verdächtige Stelle findest bin ich da offen. Habe selbst noch keine gefunden.

Ich hatte schon die Situation, das die db down (Netzwerk) war, das hat das immer bestens funktioniert - da wurden logs geschrieben mit knapp über 1000 lines! 1000 lines entsprechen etwa einer stunde keine DB, kann ich bei Bedarf liefern 

Ich hatte schon deutlich mehr im Cache liegen die in die DB geschrieben werden mussten ... klappt auch bei mir einwandfrei. 

LG,
Heiko

[DS_Starter]

Jetzt fällt mir auf ...

warum nicht in die db geschrieben werden konnte, ist mit höchster Wahrscheinlichkeit klar. - siehe meinen link zum Astro thread. Alles was mit Internal Timer zu tun hatte ging nicht!

Die Cache-Steuerung und damit das evtl. Schreiben der Files ist auch von der InternalTimer-Funktion abhängig. Wenn die versagt wird DbLog davon natürlich beeinflusst. Vielleicht hängt es damit zusammen.

[erwin]

Wie es zu den 1000 events kommt....

ist mir mittlerweile auch klar. Das Astro-Modul hat ca. 100 readings. - jedes wurde 1* pro Sekunde getriggert....
l.g. erwin