93_DbLog - Umstellung Log-Funktion auf non-blocking

[DS_Starter]

Hallo miteinander,

habe die Testergebnisse der Mitstreiter von gestern Abend (danke dafür!) übereinandergelegt und mit der angehängten V2.9.2_Test hoffentlich das SVG-Problem gelöst OHNE das sich die Meldung "MySQL-Server has gone" wieder einstellt.
Bei mir habe ich die Version sowohl unter MySQL, SQLIte , mit und ohne plotfork, asynmode=0 bzw. 1 getestet -> no issues.

@Chris, Sunny .. schaut bitte ob eure issues damit erledigt sind

@MySQL-User die mal die Meldung  "MySQL-Server has gone"  hatten bitte ich natürlich auch zu testen ob dieses Meldung weiterhin Geschichte ist.

@h3llsp4wn .... bitte schau ob das Modul deinen Anforderungen auch wieder gerecht wird.

@Benni ... hmm, bzgl. Performance wird sich jetzt nichts geändert haben. DbLog ist durch den array-insert schon im synchron mode beschleunigt. Im asynchronen Mode wird der Schreibvorgang obendrein über Blocking.pm abgewickelt und ist nicht mehr Bestandteil der Notify-Schleife.
Schau dohc mal mit apptime .. es gibt nur zwei Bestandteile von DbLog, die Zeiten schreiben. Das ist DbLog_Log (in der Notifyschleife) und tmr-DbLog_execmemcache (die Funktion für den asynchronen Mode).

Edit: @Benni, vieleicht hat sich doch eine Änderung ergeben. Ich weiß nicht welche DbLog deine letzte Version war, aber ab V2.9.1 verwendet DbLog eine neue von Loredo vorgeschlagene und von Markus/Rudi implementiert neuen Splitfunktionsaufruf wenn das Sendermodul eine eigene Splitfunkzion bereitstellt..

viele Grüße
Heiko

[JoeALLb]

Schöne Version...  macht mich glücklich! Ich arbeite zwar mit MySQL, was bisher auch schon gut funktioniert hat, aber die neuen Funktionen und Weiterentwicklungen seit 2.9.0 sind sehr hilfreich!!

Aktuell habe ich ein

Code Auswählen Erweitern

sql_processing_time = 0.0609
alle 10 Minuten, was mein System deutlich performanter macht und die SSD deutlich länger leben lässt!!!!

Chapeau!

[Benni]

Also...

Ich habe mal 3 update-Zyklen beim Wunderground durchgeführt, natürlich wieder mit den entsprechenden Freezes:

Code Auswählen Erweitern


2017.01.16 19:24:28 3: Wunderground set wuMain update
2017.01.16 19:24:33 1: Perfmon: possible freeze starting at 19:24:30, delay is 3.32
2017.01.16 19:24:40 3: Wunderground set wuMain update
2017.01.16 19:24:44 1: Perfmon: possible freeze starting at 19:24:41, delay is 3.543
2017.01.16 19:24:51 3: Wunderground set wuMain update
2017.01.16 19:24:55 1: Perfmon: possible freeze starting at 19:24:52, delay is 3.556


apptime (max) liefert danach folgendes:

Code Auswählen Erweitern


name             function    max  count    total  average maxDly
                               logdb            DbLog_Log   2497     25     7426   297.04      0 HASH(logdb); HASH(wuMain)
             HG.XX.RG.Batteriestatus readingsGroup_Notify   1067     25     3166   126.64      0 HASH(HG.XX.RG.Batteriestatus); HASH(wuMain)
              tmr-DbLog_execmemcache      HASH(0x543d3a0)     47      1       47    47.00      0 HASH(logdb)
                             HMUART1       HMUARTLGW_Read     39     11      146    13.27      0 HASH(HMUART1)
                              HMLAN3           HMLAN_Read     31      9       49     5.44      0 HASH(HMLAN3)
                   tmr-SYSMON_Update      HASH(0x4bc85d8)     30      1       30    30.00      1 HASH(fhemhost)
               tmr-APCUPSD_PollTimer      HASH(0x56d3bc8)     29      1       29    29.00     16 HASH(USV1)
                         tmr-at_Exec      HASH(0x4b2e658)     28      1       28    28.00      1 HASH(atHearbeat)
            WEB_192.168.178.35_35172              FW_Read     23      1       23    23.00      0 HASH(WEB_192.168.178.35_35172)
                   tmr-HttpUtils_Err      HASH(0x8666be8)     19      1       19    19.00   1396 HASH(0x8666be8)
           WEB_192.168.178.134_34594              FW_Read     18      1       18    18.00      0 HASH(WEB_192.168.178.134_34594)
                               logdb            DbLog_Get     18      1       18    18.00      0 HASH(logdb); logdb; HISTORY; INT; 2017-01-15_19:30:00; 2017-01-16_19:30:01; HG.XX.WS.Wetter:temperature; HG.XX.WS.Wetter:humidity; HG.XX.WS.Wetter:windSpeed; HG.XX.WS.Wetter:brightness
                  HG.XX.DM.Heartbeat            dummy_Set     17      3       17     5.67      0 HASH(HG.XX.DM.Heartbeat); HG.XX.DM.Heartbeat; 18
          tmr-Wunderground_GetStatus      HASH(0x71b0bd0)     15      1       15    15.00      1 HASH(wuMain)
                              wuMain     Wunderground_Set     10     17       12     0.71      0 HASH(wuMain); ARRAY(0xa008498); HASH(0x23e2330)
              EG.EZ.NY.Licht.Telefon          notify_Exec      7     25       13     0.52      0 HASH(EG.EZ.NY.Licht.Telefon); HASH(wuMain)
                    EG.XX.RG.Fenster readingsGroup_Notify      7     25       16     0.64      0 HASH(EG.XX.RG.Fenster); HASH(wuMain)
            WEB_192.168.178.57_49546              FW_Read      7      2       10     5.00      0 HASH(WEB_192.168.178.57_49546)
                   EG.EZ.NY.ST.Licht          notify_Exec      6     25       11     0.44      0 HASH(EG.EZ.NY.ST.Licht); HASH(wuMain)
                   EG.NY.WindowAlarm          notify_Exec      6     25       11     0.44      0 HASH(EG.NY.WindowAlarm); HASH(wuMain)
                    EG.XX.RG.Heizung readingsGroup_Notify      6     25       13     0.52      0 HASH(EG.XX.RG.Heizung); HASH(wuMain)


Es läuft bei mir aktuell Version 2.9.1 im asynchronen Modus:

Code Auswählen Erweitern


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


Modul-Version:

Code Auswählen Erweitern


93_DbLog.pm 13063 2017-01-14 15:09:25Z DS_Starter


Nochmal: Nicht, dass es zu Missverständnissen kommt: Das ist kein neues Problem. Das hat sich auch schon so dargestellt, bevor die Änderungen von dir in Richtung non-blocking und asynchron-Modus vorgenommen wurden.

Ich hatte nur die Hoffnung, dass nachdem an DbLog nun mal wieder ernsthaft jemand weiterentwickelt ggf. auch diese Problem noch behandelt werden kann (oder evtl. schon ist).

Loredos Vermutung war ja, dass die Unit_DbLog_split Funktion zu oft pro Reading aufgerufen wird (Wunderground erzeugt reichlich Readings):

Eine Theorie ist beim DbLog Modul zu suchen, falls du logging verwendest (auch wenn du dieses Device ggf. mit DbLogExclude o.ä. vom Logging ausgeschlossen hast). Es ist schon anderswo aufgefallen, dass DbLog offenbar die Unit_DbLog_split Funktion aus unbekanntem Grund mehrfach pro Reading aufruft, was vielleicht auf langsamen Geräten dann dazu führen kann, dass das bei der Gesamtzahl an Readings 2 Sekunden dauern könnte. Bei Verwendung von apptime sieht man auch, dass DbLog und das WU-Modul von den aktuellen Analysetools wohl nur gesammelt erfasst und nicht differenziert werden.

Wobei ich mit meinem Produktivsystem eigentlich nicht auf einer langsamen Hardware bin 


EDIT:
Ich habe mal eben noch die in apptime ebenfalls auffällige Readingsgroup (HG.XX.RG.Batteriestatus) deaktiviert. Das hat die Freezes dann mal um satte 1.5 Sekunden reduziert.

Code Auswählen Erweitern


2017.01.16 20:28:48 3: Wunderground set wuMain update
2017.01.16 20:28:52 1: Perfmon: possible freeze starting at 20:28:50, delay is 2.088
2017.01.16 20:29:48 3: Wunderground set wuMain update
2017.01.16 20:29:51 1: Perfmon: possible freeze starting at 20:29:49, delay is 2.816


Aber wie gesagt, wenn ich DbLog deaktiviere habe ich gar keine Freezes beim update vom Wunderground. 

[h3llsp4wn]

@JoeALLb

# Mit welchem Modul Pollst Du die Werte?
# Pollst Du in der Nacht nicht, da dann erst um 07:00 wieder Werte eingetragen werden?
# Wie sehen die Poll-Readings aus? Dort müsste dann ja ein Zeitstempel enthalten sein?
# Wie sehen die DB-Einträge jetzt aus? Ist dort in der Spalte "Events" der korrekte Zeitstempel eingetragen?

- Beispielsweise mit dem Modul netatmo
- dort dann alle 15 Minuten (d.h. wenn ich mehrere Änderungen in den 15 Minuten habe, werden diese alle verarbeitet/eingelesen; oder aber eben über Nacht (WLAN aus) - wenn ich es dann am morgen aktiviere fährt er die Werte der Nacht kpl. ein
- die Poll-Readings haben wohl einen Zeitstempel - da müsste ich mir den Debug, den ich in das netatmo-Modul reingebastelt habe noch einmal einbauen
- jetzt steht dort x-Mal die gleiche Uhrzeit mit anderen werten, z.B. 2017-01-15 07:15:53 - dann jeweils mit 1,8 Grad, 1,7 Grad, 2,0 Grad, etc. - d.h. im Timestamp kommt der Zeitstempel nicht an, sondern es wird der Timestamp des verarbeitenden Augenblicks genommen.

@DS_Starter:
Danke - ich spiele die Version heute über Nacht mal ein.

[Sunny]

Moin Heiko,

"schnell Test" mit "93_DbLog_V2.9.2_Test.pm" von "Antwort #345 am: Heute um 19:05:54",
hat mit Android/Firefox und Win10/Firefox keine Auffälligkeiten hervor gerufen!

Freut mich, wenn ich Dir helfen konnte. 

Wenn Du etwas genaueres getestet haben willst, einfach "Bescheid" schreiben.

Besten Dank & freudige Grüße
sunny

[DS_Starter]

Hallo,

@Joe ...prima, freut mich wirklich sehr !

@Benni, ich will gerne dabei weiter mit zu forschen und würde mir auch Wunderground installieren (hab ich bisher nicht). Möchte nur erstmal wieder einen ruhigen Thread haben. Aber die apptime Werte lassen tatsächlich vermuten, dass die Zeit in der Splitfunktion draufgeht. Im asynchronen Modus wird in der DbLog-Funktion nur mit dem Memory gearbietet. Kannst ja mal in den Code schauen ...

@h3llsp4wn ... ok hoffe das alles klappt.

@Sunny ... prima. Naja nichts bestimmtes, einfach hoch und runter testen ....Modi mal umschalten usw.

[Benni]

@Benni, ich gerne dabei weite mit zu forschen und würde mir auch Wunderground installieren (hab ich bisher nicht). Möchte nur erstmal wieder einen ruhigen Thread haben.

Alles klar!
Dann lass ich dich hier erst mal in Ruhe aufräumen

Danke dir!

[JoeALLb]

Zur Info: Anbei ein userReadings, das den
aktuell eingestellten syncInterval mitprotokolliert.
Das nutze ich um die Speicherzeiten des Readings "sql_processing_time"
der cacheUsage und dem eingestellten Intervall gegenüber zu stellen um daraus zu entscheiden,
welches syncInterval für mich ideal ist.....

Code Auswählen Erweitern

attr <device> userReadings cacheCount:CacheUsage.* {\
  return fhem("displayattr myDbLogSQL syncInterval");;\
}


[h3llsp4wn]

@DS_Starter:
Kann bestätigen, dass die Timestamps jetzt wieder korrekt in die DB geschrieben werden. Habe in einem Zyklus von 15 Min.
beim Lüften im Satz, im Log und in der DB 3 Werte mit den entsprechende Ursprungszeiten erhalten.

Danke! Ich werde es noch über Nacht beobachten - denke der Fix kann dann ins Repo.

[stromer-12]

Ich habe gerade festgestellt, wenn die Datenbank erreichbar, aber gelockt durch einen anderen Prozess ist, gehen die im Cache gespeicherten Daten nach einen "Database access timeout" verloren.

[DS_Starter]

Ich habe gerade festgestellt, wenn die Datenbank erreichbar, aber gelockt durch einen anderen Prozess ist, gehen die im Cache gespeicherten Daten nach einen "Database access timeout" verloren.

Bisher habe ich bei Nichterreichbarkeit der DB sichergestellt das nichts verloren geht. Später will ich dann noch eine File-DB als Fall-Back einbauen.
Aber so weit bin ich noch nicht.

[Amenophis86]

Jedes Mal, wenn ich ein Update meiner NAS mache, ist natürlich die MariaDB nicht erreichbar. Dies führt dazu, dass in FHEM folgender Fehler ständig wiederholt wird, bis die DB erreichbar ist:

Code Auswählen Erweitern

2017.01.17 00:24:45 3: DbLog logdb: Error DBLog_execmemcache - DBI connect('database=fhem;host=192.168.2.22;port=3306','fhem',...) failed: Can't connect to MySQL server on '192.168.2.22' (111) at ./FHEM/93_DbLog.pm line 1076.

besteht die Möglichkeit, dass dieser Fehler einmalig ausgegeben wird und nicht ständig, bis quasi ein klar Meldung erfolgt?

[chris1284]

@Chris, Sunny .. schaut bitte ob eure issues damit erledigt sind

diese version läuft!

[DS_Starter]

@Chris ... danke für die Rückmeldung, prima.

@Amenophis86

besteht die Möglichkeit, dass dieser Fehler einmalig ausgegeben wird und nicht ständig, bis quasi ein klar Meldung erfolgt?

Das lässt sich nicht wirklich umsetzen. Wie ich schon stromer-12 schrieb, habe ich noch vor ein optionales File-DB Fallback einzubauen. Dann würden die Daten, falls die DB nicht erreichbar oder anderweitig problembehaftet ist, temporär zwischengespeichert bis sie wieder da ist.
Auf meiner Syno habe ich natürlich das gleiche Verhalten, auch beim Backup mit dem internen Backuptool. Ich setze mein DbLog-Device auf verbose 2, dann gibts keine häufigen Einträge im Logfile. Die Meldung steht ja auch im state, das reicht mir.

viele Grüße

[Amenophis86]

Alles klar. Danke für die Info.