Ich hatte heute, genau zwischen 00:00:00 und 01:00:00 Uhr folgende Log-msgs:
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:
2021-10-31 00:04:33|myDbLog|DBLOG|CacheOverflowLastNum: 70|CacheOverflowLastNum|70|
List dblog-device:
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 (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
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
Zitat
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
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):
Zitates 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 ;D
Die events vom dblog möchte ich nicht ausschließen... die machen absolut Sinn!
l.g. erwin
ZitatDa 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.
ZitatIch 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 ;D
Ich hatte schon deutlich mehr im Cache liegen die in die DB geschrieben werden mussten ... klappt auch bei mir einwandfrei. :)
LG,
Heiko
Jetzt fällt mir auf ...
Zitat
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.
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