93_DbLog - Umstellung Log-Funktion auf non-blocking

[JoeALLb]

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.

Hallo Benni,
was steht bei Dir bei den 4 "event-on.*" Attributen?

[stromer-12]

Ich habe mit der 2.10.2 ebenfalls einen Timeout mit Datenverlust, wenn die Datenbank blockiert war.

Code Auswählen Erweitern

2017.01.20 11:04:22.064 1: Timeout for DbLog_PushAsync reached, terminated process 16482
2017.01.20 11:04:22.065 2: DbLog myDbLog -> DbLog_PushAsync timed out

[Benni]

was steht bei Dir bei den 4 "event-on.*" Attributen?

Hier der Einfachheit halber mal ein vollständiges list meines DbLog-Devices:

Code Auswählen Erweitern


Internals:
   CFGFN
   CONFIGURATION ./mydblog.conf
   DBMODEL    MYSQL
   DEF        ./mydblog.conf .*:.*
   MODE       synchronous
   NAME       logdb
   NR         390
   NTFY_ORDER 50-logdb
   PID        27198
   REGEXP     .*:.*
   STATE      connected
   TYPE       DbLog
   VERSION    2.10.2
   dbconn     mysql:database=fhem;host=localhost;port=3306
   dbuser     fhem
   Helper:
   Readings:
     2017-01-20 18:48:17   CacheUsage      0
     2017-01-20 18:48:17   NextSync        2017-01-20 18:48:47 or if CacheUsage 500 reached
     2017-01-20 18:48:17   background_processing_time 0.0111
     2017-01-20 18:47:55   notify_processing_time 0.0006
     2017-01-20 18:48:17   sql_processing_time 0.0090
     2017-01-20 18:48:17   state           connected
   Cache:
     index      3124
     Memcache:
Attributes:
   DbLogExclude .*
   DbLogSelectionMode Exclude/Include
   DbLogType  History
   asyncMode  1
   cacheEvents 2
   event-on-change-reading .*
   room       99.00_FHEM,Logging
   showNotifyTime 1
   showproctime 1
   syncEvents 1
   verbose    3


[JoeALLb]

Code Auswählen Erweitern


     2017-01-20 18:48:17   CacheUsage      0 


Aber jetzt war CacheUsage aktuell?!?

[christiang]

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

Super danke! Hab die neue Version gerade eingespielt und es schaut sehr gut aus. Bei manueller Ausführung (ca. 20 mal) hab ich jetzt keinen Fehler mehr bekommen. Ich setzt jetzt noch ein at auf, das den reduce über Nacht noch etliche Male laufen lässt.

mfg

[DS_Starter]

@stromer-12 ...

Timeout for DbLog_PushAsync reached, terminated process 16482

Ah ok , In dem Fall läuft der Hintergrundprozess vom BlockingCall in den Timeout. Das bekomme ich nicht abgefangen um die übergebenen Daten wieder in den Cache einzufügen.
Momentan ist der timeout fest auf 60s eingestellt. Ich werde ihn per Attribut einstellbar machen. Dann könnte man ihn höher als den DB Spezifischen innodb_lock_wait_timeout Wert setzen

[JoeALLb]

Ich teste immer eine leicht abgewandelte Version, da ich ohne
"insert ignore into" wegen meinem veränderten PKs Fehlermeldungen erhalte,
aber bisher funktioniert auch die neue Version sehr schön!!

Mal eine Frage an die Runde:
Macht es eigentlich sinn, die Daten in die DB zu schreiben als Transaktion??

Commits sind doch eher für Daten gedacht, die "zusammenhängend, alle oder keiner) in die DB eingetragen werden sollen. Bei Logs ist das doch nicht so!
Im Fehlerfall wäre mir auch "99 von 100) lieber wie 0 von 100.

Hat jemand eine andere Meinug dazu?

beste Grüße
Joe

[Benni]

Aber jetzt war CacheUsage aktuell?!?

Klar! Wenn ich die Seite manuell aktualisiere wird schon der aktuelle Wert angezeigt, aber nicht weiter aktualisiert, sprich es kommen keine Events, d.h. es findet keine Longpoll-Aktualisierung statt und auch im Log landet nichts. Bei cacheEvents=1 funktioniert's ja!

[DS_Starter]

Hi Benni,

hilft zwar jetzt nicht , aber bei mir kommen die Events bei cacheEvents 2 einwandfrei (Screenshots). War aber auch mit der vorherigen Version so.
Vielleicht habe ich noch eine Idee, aber heute nicht mehr ...

VG+GN
Heiko

[DS_Starter]

Guten Morgen,

anbei die weiterentwickelte V2.10.3.

@Benni ... ich habe intern nochmal die Abfrage auf cacheEvents=2 etwas geändert. Klappt bei mir nach wie vor. Vllt. hilft es bei dir nun auch, obwohl ich es mir nicht erkären könnte.

Der timeout für den BlockingCall im asynchronen Modus ist nun mit dem Attr "timeout" einstellbar (default: 120s).
Der Theorie nach soll bei MySQL die Zeit für die DB-Variable "innodb_lock_wait_timeout" eher ablaufen als der Timeout-Wert für den Hintergrundprozess des Moduls im asynchronen Mode.  Damit sollte dann auch dieser DB-Zustand vom Modul abgefangen werden können wie weiter vorn beschrieben.

@stromer12 ... schau mal ob es mit der Einstellmöglichkeit bei dir klappt. Wie provozierst du bei dir einen DB/Tabellen-Lock ? Dann könnte ich es bei mir mal nachstellen.

viele Grüße
Heiko

[DS_Starter]

Hallo friesenjung,

sorry, deine Frage hatte ich fast vergessen.

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

Nein, das war etwas aus dem Fokus geraten.
Allerdings habe ich mir bereits Gedanken dazu gemacht.

Ich würde eine stufenweise Implementierung vornehmen.

Als ersten Schritt würde ich die von betateilchen vorgeschlagene Übersteuerung der Default-Feldlängen im Modul mittels Einträgen im DbLog-Configfile (db.conf) realisieren.
Der zweite (weil umfänglichere) Schritt wäre die Abfrage der Feldlängen aus der DB wie Joe vorgeschlagen hat, die dann ihrerseits die Uservariablen im Configfile sowie die Default-Einstellungen in dem Modul übersteuern.

D.h. von der Wertigkeit wäre die Abfolge:

automatisch ermittelte Feldlängen aus DB  -> wenn nicht ermittelbar -> Uservariablen aus db.conf -> wenn nicht gesetzt -> es gelten die Default-Feldlängen im Modul

Ich würde auch mit vorsehen die aus diesem Mechanismus abgeleiteten Feldlängen in den INTERNALS des Moduls sichtbar zu machen. Man würde dadurch sofort einen Überblick haben mit welchen Feldlängen das Modul effektiv arbeitet.

viele Grüße
Heiko

[Benni]

Hallo Heiko,

nö! Funktioniert immer noch nicht, sorry! 

Ich hab' mal eben einen Blick in den Code geworfen und habe auch keine Erklärung dafür, dass es bei mir keinen Event wirft.

Ich habe extra in DbLog_execmemcache mal noch nach Zeile 1147 noch folgende Zeile eingefügt:

Code Auswählen Erweitern


          Log3($name,3,"DbLog $name: updating cacheUsage (ce=$ce): $memcount")";


Die wird auch ausgeführt und im Log wir bei mir daraufhin jeweils korrekt ein entsprechender Eintrag erzeugt:

Code Auswählen Erweitern


2017.01.21 13:36:34 3: DbLog logdb: updating cacheUsage (ce=2): 29
2017.01.21 13:37:04 3: DbLog logdb: updating cacheUsage (ce=2): 5
2017.01.21 13:37:34 3: DbLog logdb: updating cacheUsage (ce=2): 4
2017.01.21 13:38:04 3: DbLog logdb: updating cacheUsage (ce=2): 3
2017.01.21 13:38:34 3: DbLog logdb: updating cacheUsage (ce=2): 31
2017.01.21 13:39:04 3: DbLog logdb: updating cacheUsage (ce=2): 7
2017.01.21 13:39:34 3: DbLog logdb: updating cacheUsage (ce=2): 1
2017.01.21 13:40:04 3: DbLog logdb: updating cacheUsage (ce=2): 4


Aber im Eventmonitor kommt einfach kein Event an:

Code Auswählen Erweitern


Events (Filter: DbLog.*)   FHEM log   Reset

2017-01-21 13:36:16 DbLog logdb notify_processing_time: 0.0003
2017-01-21 13:36:17 DbLog logdb notify_processing_time: 0.0001
2017-01-21 13:36:22 DbLog logdb notify_processing_time: 0.0003
2017-01-21 13:36:23 DbLog logdb notify_processing_time: 0.0002
2017-01-21 13:36:34 DbLog logdb NextSync: 2017-01-21 13:37:04 or if CacheUsage 500 reached
2017-01-21 13:36:34 DbLog logdb background_processing_time: 0.0157
2017-01-21 13:36:34 DbLog logdb sql_processing_time: 0.0136
2017-01-21 13:36:54 DbLog logdb notify_processing_time: 0.0001
2017-01-21 13:37:03 DbLog logdb notify_processing_time: 0.0002
2017-01-21 13:37:04 DbLog logdb NextSync: 2017-01-21 13:37:34 or if CacheUsage 500 reached
2017-01-21 13:37:04 DbLog logdb background_processing_time: 0.0100
2017-01-21 13:37:04 DbLog logdb sql_processing_time: 0.0078
2017-01-21 13:37:34 DbLog logdb NextSync: 2017-01-21 13:38:04 or if CacheUsage 500 reached
2017-01-21 13:37:34 DbLog logdb background_processing_time: 0.0104
2017-01-21 13:37:34 DbLog logdb sql_processing_time: 0.0092
2017-01-21 13:37:36 DbLog logdb notify_processing_time: 0.0001
2017-01-21 13:38:04 DbLog logdb NextSync: 2017-01-21 13:38:34 or if CacheUsage 500 reached
2017-01-21 13:38:04 DbLog logdb background_processing_time: 0.0084
2017-01-21 13:38:04 DbLog logdb sql_processing_time: 0.0076
2017-01-21 13:38:06 DbLog logdb notify_processing_time: 0.0002
2017-01-21 13:38:20 DbLog logdb notify_processing_time: 0.0005
2017-01-21 13:38:21 DbLog logdb notify_processing_time: 0.0003
2017-01-21 13:38:26 DbLog logdb notify_processing_time: 0.0001
2017-01-21 13:38:26 DbLog logdb notify_processing_time: 0.0002
2017-01-21 13:38:27 DbLog logdb notify_processing_time: 0.0004
2017-01-21 13:38:33 DbLog logdb notify_processing_time: 0.0011
2017-01-21 13:38:34 DbLog logdb NextSync: 2017-01-21 13:39:04 or if CacheUsage 500 reached
2017-01-21 13:38:34 DbLog logdb background_processing_time: 0.0097
2017-01-21 13:38:34 DbLog logdb sql_processing_time: 0.0086
2017-01-21 13:38:36 DbLog logdb notify_processing_time: 0.0001
2017-01-21 13:38:37 DbLog logdb notify_processing_time: 0.0003
2017-01-21 13:38:50 DbLog logdb notify_processing_time: 0.0004
2017-01-21 13:39:04 DbLog logdb NextSync: 2017-01-21 13:39:34 or if CacheUsage 500 reached
2017-01-21 13:39:04 DbLog logdb background_processing_time: 0.0082
2017-01-21 13:39:04 DbLog logdb sql_processing_time: 0.0073
2017-01-21 13:39:14 DbLog logdb notify_processing_time: 0.0002
2017-01-21 13:39:34 DbLog logdb NextSync: 2017-01-21 13:40:04 or if CacheUsage 500 reached
2017-01-21 13:39:34 DbLog logdb background_processing_time: 0.0076
2017-01-21 13:39:34 DbLog logdb sql_processing_time: 0.0068
2017-01-21 13:40:04 DbLog logdb NextSync: 2017-01-21 13:40:34 or if CacheUsage 500 reached
2017-01-21 13:40:04 DbLog logdb sql_processing_time: 0.0067


Sehr mysteriös! 

Aber: Verbrate nicht wegen mir so viel Zeit darauf. Für mich ist das nicht weiter wichtig. War ja nur für die Logs/SVGs während der Wunderground-Analyse interessant für mich.
Die Plots fliegen nachher sowieso wieder raus.

Trotzdem vielen Dank für deine tolle Unterstützung hier!

Gruß Benni.

[DS_Starter]

Hi Benni,

Sehr mysteriös!

Ja, finde ich auch und habe auch keine Erklärung. Ich lass das jetzt auch so.

Wegen deinem "Wunderground"-Problem würde ich euch auch noch unterstützen. Ich habe mal so etwas ähnliches mit dem 76_SMAEM gehabt.
Vielleicht fallen mir dann Parallelen auf.
Das braucht leider immer soviel Zeit ... 

schönes WE !

Grüße
Heiko

[Benni]

Auch auf die Gefahr hin lästig zu werden... 

Irgendwie hat es mir doch keine Ruhe gelassen

Es ist bei mir wohl ein Timing-Problem, da meine Hardware wohl etwas zu schnell ist 

Das Problem wird in DbLog_Log in Zeile 881 verursacht. Das ist in folgendem Code-Fragment der else-Zweig:

Code Auswählen Erweitern


my $memcount = $hash->{cache}{memcache}?scalar(keys%{$hash->{cache}{memcache}}):0;
if($ce == 1) {
  readingsSingleUpdate($hash, "CacheUsage", $memcount, 1)
} else {
  readingsSingleUpdate($hash, "CacheUsage", $memcount, 0)
}


Der schlägt bei mir anscheinend zu schnell zu und verhindert damit auch das Erzeugen des Events, das eigentlich durch das Setzen des Readings in Zeile 1148 in DbLog_execmemcach generiert werden soll.

Wenn ich die Zeile 881 auskommentiere wird bei mir auch der Event korrekt geworfen.

Gruß Benni.

[DS_Starter]

Hi Benni,

Auch auf die Gefahr hin lästig zu werden... 

wirst du nicht ...   

Danke für den Hinweis.
Ich schau mal ob ich es auch für schnelle Hardware kompatibel gestalten kann 

Grüße
Heiko