93_DbLog - Umstellung Log-Funktion auf non-blocking

JoeALLb · 17 Januar 2017, 17:29:16

Nur zur Info: Tobias hat 2.9.2 eingecheckt, sie wird ab morgen wieder per Update verfügbar sein.

JoeALLb · 18 Januar 2017, 10:29:20

Schön auch, wie der zeitliche Zusammenhang zwischen Speicherzeit (rot) und Anzahl
der Datensätze(grün) im Zusammenhang aussieht.
die Spikes nach oben waren jeweils ein update & Backup von FHEM.

My-FHEM · 18 Januar 2017, 20:56:01

Ich hatte gerade eine FHEM Bendigung mit folgender Meldung im Log:

Code Auswählen


Wide character in subroutine entry at ./FHEM/93_DbLog.pm line 1132.

Irgendeine Idee FHEM ist auf heutigem Update Stand.

VG

Code Auswählen


 CONFIGURATION ./db.conf 
   DBMODEL    MYSQL 
   DEF        ./db.conf .*:.* 
   MODE       asynchronous 
   NAME       myDbLog 
   NR         4 
   NTFY_ORDER 50-myDbLog 
   PID        18474 
   REGEXP     .*:.* 
   STATE      connected 
   TYPE       DbLog 
   VERSION    2.9.2 
   dbconn     mysql:database=fhem;host=localhost;port=3306 
   dbuser     fhemuser 
   Helper: 
   Helper: 
     Dblog: 
       Background_processing_time: 
         Mydblog: 
           TIME       1484769283.62672 
           VALUE      0.3280 
       State: 
         Mydblog: 
           TIME       1484769272.50747 
           VALUE      connected 
   Readings: 
     2017-01-18 20:54:47   CacheUsage      24 
     2017-01-18 20:54:43   NextSync        2017-01-18 20:55:13 
     2017-01-18 20:54:43   background_processing_time 0.3280 
     2015-02-21 14:57:11   countCurrent    3053 
     2015-02-21 14:57:11   countHistory    148316222 
     2017-01-12 21:52:19   lastReduceLogResult Rows processed: 0, deleted: 0, updated: 0, time: 8.00sec 
     2017-01-18 20:54:43   sql_processing_time 0.3240 
     2017-01-18 20:54:43   state           connected 
     2017-01-18 00:05:00   userCommand     select 
				max(to_number(value,'999.999')) - min(to_number(value,'999.999')) as kw 
				from history 
				where device = 'PCA301_K_Media' 
				and reading = 'consumption' 
				and timestamp >= TO_TIMESTAMP('2017-01-17 00:00:00','YYYY-MM-DD HH24:MI:SS') 
				and timestamp <= TO_TIMESTAMP('2017-01-17 23:59:59','YYYY-MM-DD HH24:MI:SS') 
   Cache: 
     index      6800 
     Memcache: 
       6777       2017-01-18 20:54:43|myDbLog|DBLOG|background_processing_time: 0.3280|background_processing_time|0.3280| 
       6778       2017-01-18 20:54:43|HMLAN1|HMLAN|UNKNOWNCODE A0F5586103D84AC0000000A98D70D0A40::-103:HMLAN1|state|UNKNOWNCODE A0F5586103D84AC0000000A98D70D0A40::-103:HMLAN1| 
       6779       2017-01-18 20:54:45|EC3000_3E58|EC3000|consumption: 40.753|consumption|40.753| 
       6780       2017-01-18 20:54:45|EC3000_3E58|EC3000|power: 1.7|power|1.7| 
       6781       2017-01-18 20:54:45|EC3000_3E58|EC3000|powerMax: 1328.6|powerMax|1328.6| 
       6782       2017-01-18 20:54:45|EC3000_3E58|EC3000|on|state|on| 
       6783       2017-01-18 20:54:45|EC3000_3E58|EC3000|Total: 40.753|Total|40.753| 
       6784       2017-01-18 20:54:45|EC3000_476A|EC3000|consumption: 1689.634|consumption|1689.634| 
       6785       2017-01-18 20:54:45|EC3000_476A|EC3000|power: 16.1|power|16.1| 
       6786       2017-01-18 20:54:45|EC3000_476A|EC3000|powerMax: 20.6|powerMax|20.6| 
       6787       2017-01-18 20:54:45|EC3000_476A|EC3000|on|state|on| 
       6788       2017-01-18 20:54:45|EC3000_476A|EC3000|consumptionTotal: 1689.634|consumptionTotal|1689.634| 
       6789       2017-01-18 20:54:46|EC3000_3DDC|EC3000|consumption: 95.332|consumption|95.332| 
       6790       2017-01-18 20:54:46|EC3000_3DDC|EC3000|power: 3|power|3| 
       6791       2017-01-18 20:54:46|EC3000_3DDC|EC3000|powerMax: 112.1|powerMax|112.1| 
       6792       2017-01-18 20:54:46|EC3000_3DDC|EC3000|on|state|on| 
       6793       2017-01-18 20:54:46|EC3000_3DDC|EC3000|consumptionTotal: 95.332|consumptionTotal|95.332| 
       6794       2017-01-18 20:54:47|BMP180_LGW1|LACROSSE|error: 0|error|0| 
       6795       2017-01-18 20:54:47|BMP180_LGW1|LACROSSE|battery: ok|battery|ok| 
       6796       2017-01-18 20:54:47|BMP180_LGW1|LACROSSE|temperature: 23.5|temperature|23.5|°C 
       6797       2017-01-18 20:54:47|BMP180_LGW1|LACROSSE|pressure: 1036|pressure|1036| 
       6798       2017-01-18 20:54:47|Hz.Ku.Th_Weather|CUL_HM|humidity: 37|humidity|37|% 
       6799       2017-01-18 20:54:47|Hz.Ku.Th_Weather|CUL_HM|T: 21.6 H: 37|T|21.6 H|37 
       6800       2017-01-18 20:54:47|Hz.Ku.Th_Weather|CUL_HM|temperature: 21.6|temperature|21.6|°C 
Attributes: 
   DbLogExclude CacheUsage,NextSync,sql_processing_time 
   DbLogType  Current/History 
   asyncMode  1 
   room       db-logs 
   showproctime 1 
   shutdownWait 4 
   verbose    0

DS_Starter · 18 Januar 2017, 22:20:32

ZitatWide character in subroutin

das sagt mir erstmal nichts. ich schau mal ...

VG

DS_Starter · 19 Januar 2017, 00:47:53

Hallo Benni, @all,

in der angehängten Version V2.10 gibt es die Attribute showNotifyTime und cacheLimit.

Die Erweiterung cacheLimit schreibt im asynchronen Mode den Cacheinhalt in die DB wenn das eingestellte Limit (Default 500 Einträge) des Caches erreicht ist. D.h. der Cache wird in die DB geschrieben, wenn entweder das eingestellte syncInterval ODER das eingestellte cacheLimit erreicht wird. In dem Fall wird der interne Synctimer auch neu gesetzt.

Das Attr showNotifyTime dient dazu die verbrauchte Zeit innerhalb der Notify-Funktion DbLog_Log zu messen und anzuzeigen. Es ist für Performanceanalysen gedacht um festzustellen weiche Zeitvorteile die Umschaltung des synchronen in den asychronen Mode bringt.

Anlass dazu war der Beitrag von Benni in #347.
@Benni ... schau mal ob das schon Aufschlüsse gibt. Die SplitFn wird mit erfasst.

Bitte testet die Version (bei Interesse) unter allen Gesichtspunkten (synchron, asynchron usw.)

Grüße
Heiko

JoeALLb · 19 Januar 2017, 10:21:42

Wunsch zur Verdeutlichung in der Doku:

Code Auswählen

    DbLogExclude
attr <device> DbLogExclude regex:MinInterval [regex:MinInterval] ...
[...]
Example
attr MyDevice1 DbLogExclude .* attr MyDevice2 DbLogExclude state,(floorplantext|MyUserReading):300,battery:3600

Ist der Trenner nun ein Leerzeichen (" ") wie die zweite Zeile angibt oder ein Komma (","), wie es das Example und der Text vorgibt?
Da letzeres korrekt ist, bitte ich um eine kleine Korrektur der Commandref beim nächsten Update.

Benni · 19 Januar 2017, 10:24:31

Hallo Heiko,

danke erst mal, dass du mich nicht vergessen hast und so schnell Zeit gefunden hast!

ich hab' die aktuelle Version inzwischen bei mir eingespielt.
Was mir zuerst aufgefallen ist, dass bei cacheEvents=2 anscheinend gar keine events für CacheUsage erzeugt werden.

Leider konnte ich bisher keine signifikanten Zeiten erkennen. Ich lass das mal noch eine weile laufen und poste dann das entsprechende Log und den Plot dazu.

DS_Starter · 19 Januar 2017, 10:39:29

Hallo Joe, Benni,

Versuche an die Commandref mit zu denken.

@Benni .. cacheEvents=2 wirkt nur im asynchmode. Sollte ich wahrscheinlich auch deutlicher in der Commandref schreiben.

VG
Heiko

Benni · 19 Januar 2017, 10:45:52

Zitat von: DS_Starter am 19 Januar 2017, 10:39:29
@Benni .. cacheEvents=2 wirkt nur im asynchmode.

Schon klar

Mein DbLog-Device läuft ja auch im asynchmodus

:

Code Auswählen


Internals: 
   CFGFN 
   CONFIGURATION ./mydblog.conf 
   DBMODEL    MYSQL 
   DEF        ./mydblog.conf .*:.* 
   MODE       asynchronous 
   NAME       logdb 
   NR         390 
   NTFY_ORDER 50-logdb 
   PID        27198 
   REGEXP     .*:.* 
   STATE      connected 
   TYPE       DbLog 
   VERSION    2.10 
   dbconn     mysql:database=fhem;host=localhost;port=3306 
   dbuser     fhem

Benni · 19 Januar 2017, 13:51:23

So, nachdem nun einige Zeit vergangen ist....

im Anhang zum einen die Plots von logDB, so wie das zugehörige Log-File

Die gelben Peaks im Plot sind manuell (per notify) erzeugte Log-Einträge, immer wenn ein update-Zyklus des Wunderground-Devices (wuMain) durchgeführt wird, damit man das in den Plots auch sieht. Der Rest sollte klar sein

Der Auszug aus dem fhem-Log enthält außerdem die relevanten Logeinträge aus dem Fraglichen Zeitraum, sprich die freeze-Meldungen von Perfmon.

Ich habe den Verdacht, dass das nicht wirklich schlauer macht $:-\$

christiang · 19 Januar 2017, 18:35:52

Hab festgestellt, dass durch die Änderungen der reduceLog manchmal nicht mehr funktioniert.

Gibt dann die Fehlermeldung:
2017.01.19 05:00:00 1: DbLog fhemDbLog: DBLog_Set - reduceLog - DB Session dead, try to reopen now !

Passiert sowohl wenn das reduceLog durch ein at oder auch von Hand aufgerufen wird. Manchmal geht es aber auch einwandfrei. Hab eine MySQL db im asynchronous Modus laufen, falls das was ausmacht.

mfg,
Christian

DS_Starter · 19 Januar 2017, 19:36:18

Hallo Christian,

ZitatPassiert sowohl wenn das reduceLog durch ein at oder auch von Hand aufgerufen wird. Manchmal geht es aber auch einwandfrei. Hab eine MySQL db im asynchronous Modus laufen, falls das was ausmacht.

Ja, das ist eine wichtige Information. Ich habe eine Vermutung.
Werde hier eine entsprechend angepasste Version zum Test zur Verfügung stellen.

VG
Heiko

DS_Starter · 19 Januar 2017, 22:32:47

Hallo miteinander,

anbei die Weiterentwicklung V2.10.2.

@Joe, die Commandref ist angepasst.

@Christian, der Start von Reducelog ist stabilisiert ... bitte ausprobieren

@Benni ... bei mir hat cacheEvents=2 Events geworfen, aber ich habe die Abfrage für cacheEvents intern umgestellt. Schau mal ob bei dir nun auch Events generiert werden. Deine SVG shen richtig gut aus.

Allerdings kann ich daran eigentlich auch nur erkennen dass die DbLog_Log Sub max. 100 ms verbraucht. Kann also eigentlich nicht an der SplitFn liegen...

Ansonsten kann DbLog im asynchronen Modus nun auch andere Fehlrzustände als wie bisher die Nichtverfügbarkeit der DB erkennen und den Cacheinhalt erhalten bis der Fehlerzustand der DB beseitigt ist. Testen konnte ich es mit SQLITE und einem provozierten "DBD::SQLite::db prepare failed: disk I/O error". Andere Varianten konnte ich noch nicht austesten.

@stromer-12 ... vielleicht kannst du das Verhalten mit deinem "Database access timeout" testen ob die Weiterentwicklung auch bei diesem Zustand zieht.

viele Grüße
Heiko

ioT4db · 20 Januar 2017, 14:30:26

Hallo Zusammen,

gab es "damals" eigentlich schon eine Entscheidung bzgl. Tabellenfeldlänge?

Da meine Feldlänge vom Standard abweicht, muss ich bei jedem Update händisch die Einträge in der 93_DbLog.pm anpassen.

Mir gefiel die Idee, die Feldlänge von der Datenbank abzufragen...

VG...

Benni · 20 Januar 2017, 16:12:28

Zitat von: DS_Starter am 19 Januar 2017, 22:32:47
anbei die Weiterentwicklung V2.10.2.

...

@Benni ... bei mir hat cacheEvents=2 Events geworfen, aber ich habe die Abfrage für cacheEvents intern umgestellt. Schau mal ob bei dir nun auch Events generiert werden. Deine SVG shen richtig gut aus. Allerdings kann ich daran eigentlich auch nur erkennen dass die DbLog_Log Sub max. 100 ms verbraucht. Kann also eigentlich nicht an der SplitFn liegen...

Hallo Heiko,

Habe die neue Version eben eingespielt.
für cacheUsage wird bei mir immer noch kein Event geworfen. Sieht man auch schön im angehängten Screenshot an den Zeitstempeln in den Readings.

Mit meinem Wunderground-Problem muss ich mich wohl wieder in den entsprechenden Thread zu Wunderground trollen $:-\$

Danke für deine Unterstützung!

Gruß Benni.