FHEM Forum

Hallo Tobias, rapster, @all,

ich habe mich mit der Umstellung der Log-Funktion auf eine nichtblockierende Arbeitsweise beschäftigt.

Eine Version von DbLog, die bereits mit positiven Ergebnissen in meiner Installation läuft, möchte ich zum Test und Diskussion
mit euch teilen. Ich benutze MariaDB (MySQL), habe es aber auch schon mit SQLite angetestet.
Speziell die Subroutinen DbLog_Log, DbLog_Push sind abgeändert.

Zusammengefasst ist folgendes verändert:

* DbLog Log-Funktion ist umgestellt auf non-blocking mit Blocking.pm
* Umstellung der NotifyFn (DbLog_Log) auf deviceEvents
* Einführung von NOTIFYDEV um nur Events von Devices vom DbLog-Device auswerten zu lassen die auch in der DEF angegeben wurden
* Angabe der noch offenen Verbuchungen/DB-Updates im state-Reading
* verbose 4: Ausgaben von zu bewertenden bzw. zu verarbeitenden Events im Logfile


Abgeleitet von der DbLog-Definition bzw. Regex wird nun auch NOTIFYDEV aufgebaut. Damit soll gewährleistet werden dass DbLog nur die Events
der Devices verarbeiten muß die auch im Define von DbLog angegeben wurden.

Mit verbose 4 kann gut verfolgt werden welche Events bewertet, der Verarbeitung übergeben wurden und wieviele Event-Verbuchungen noch anstehen.
Hier ein Beispiel:

#################################################

2016.12.18 10:10:06.381 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Bezug_WirkP_Zaehler_Diff: 0.0022
2016.12.18 10:10:06.382 4: SMAEM LogDB -> count of current log gaps: 1
2016.12.18 10:10:06.390 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Bezug_WirkP_Kosten_Diff: 0.0005
2016.12.18 10:10:06.391 4: SMAEM LogDB -> count of current log gaps: 2
2016.12.18 10:10:06.402 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Bezug_WirkP_Zaehler_Diff: 0.0022 , Reading: Bezug_WirkP_Zaehler_Diff , Value: 0.0022 , Unit:
2016.12.18 10:10:06.405 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Einspeisung_WirkP_Zaehler_Diff: 0
2016.12.18 10:10:06.406 4: SMAEM LogDB -> count of current log gaps: 3
2016.12.18 10:10:06.421 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Bezug_WirkP_Kosten_Diff: 0.0005 , Reading: Bezug_WirkP_Kosten_Diff , Value: 0.0005 , Unit:
2016.12.18 10:10:06.429 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Einspeisung_WirkP_Verguet_Diff: 0.0000
2016.12.18 10:10:06.431 4: SMAEM LogDB -> count of current log gaps: 4
2016.12.18 10:10:06.448 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Einspeisung_WirkP_Zaehler_Diff: 0 , Reading: Einspeisung_WirkP_Zaehler_Diff , Value: 0 , Unit:
2016.12.18 10:10:06.455 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: -114.1
2016.12.18 10:10:06.457 4: SMAEM LogDB -> count of current log gaps: 5
2016.12.18 10:10:06.484 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Saldo_Wirkleistung: -114.1
2016.12.18 10:10:06.485 4: SMAEM LogDB -> count of current log gaps: 6
2016.12.18 10:10:06.494 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Einspeisung_WirkP_Verguet_Diff: 0.0000 , Reading: Einspeisung_WirkP_Verguet_Diff , Value: 0.0000 , Unit:
2016.12.18 10:10:06.507 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Bezug_Wirkleistung: 114.1
2016.12.18 10:10:06.508 4: SMAEM LogDB -> count of current log gaps: 7
2016.12.18 10:10:06.513 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: -114.1 , Reading: state , Value: -114.1 , Unit:
2016.12.18 10:10:06.526 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Bezug_Wirkleistung_Zaehler: 1050.5732
2016.12.18 10:10:06.527 4: SMAEM LogDB -> count of current log gaps: 8
2016.12.18 10:10:06.528 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Einspeisung_Wirkleistung: 0.0
2016.12.18 10:10:06.529 4: SMAEM LogDB -> count of current log gaps: 9
2016.12.18 10:10:06.530 4: DbLog LogDB -> check Device: SMA_Energymeter , Event: Einspeisung_Wirkleistung_Zaehler: 1485.0672
2016.12.18 10:10:06.530 4: SMAEM LogDB -> count of current log gaps: 10
2016.12.18 10:10:06.544 4: DbLog LogDB -> check Device: Dum.Energy , Event: GridConsumption: 114.1
2016.12.18 10:10:06.549 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Saldo_Wirkleistung: -114.1 , Reading: Saldo_Wirkleistung , Value: -114.1 , Unit:
2016.12.18 10:10:06.598 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Bezug_Wirkleistung: 114.1 , Reading: Bezug_Wirkleistung , Value: 114.1 , Unit:
2016.12.18 10:10:06.606 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Bezug_Wirkleistung_Zaehler: 1050.5732 , Reading: Bezug_Wirkleistung_Zaehler , Value: 1050.5732 , Unit:
2016.12.18 10:10:06.646 4: SMAEM LogDB -> count of current log gaps: 9
2016.12.18 10:10:06.658 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Einspeisung_Wirkleistung: 0.0 , Reading: Einspeisung_Wirkleistung , Value: 0.0 , Unit:
2016.12.18 10:10:06.689 4: SMAEM LogDB -> count of current log gaps: 8
2016.12.18 10:10:06.694 4: DbLog LogDB -> processing Device: SMA_Energymeter , Type: SMAEM , Event: Einspeisung_Wirkleistung_Zaehler: 1485.0672 , Reading: Einspeisung_Wirkleistung_Zaehler , Value: 1485.0672 , Unit:
2016.12.18 10:10:06.710 4: SMAEM LogDB -> count of current log gaps: 7
2016.12.18 10:10:06.720 4: SMAEM LogDB -> count of current log gaps: 6
2016.12.18 10:10:06.725 4: SMAEM LogDB -> count of current log gaps: 5
2016.12.18 10:10:06.741 4: SMAEM LogDB -> count of current log gaps: 4
2016.12.18 10:10:06.752 4: SMAEM LogDB -> count of current log gaps: 3
2016.12.18 10:10:06.761 4: SMAEM LogDB -> count of current log gaps: 2
2016.12.18 10:10:06.771 4: SMAEM LogDB -> count of current log gaps: 1
2016.12.18 10:10:06.777 4: SMAEM LogDB -> count of current log gaps: 0

#################################################################

Der Eintrag "check Device:.. " beschreibt dass ein Event an das Modul weitergeleitet wurde. Das bedeutet noch nicht dass es auch in die
DB geschrieben wird, sondern dass nun eine Bewertung bzgl. Bedingungen wie DbLogExclude, DbLogInclude, MinIntervall erfolgt.

Ist die Prüfung positiv verlaufen und der Event soll in der DB geloggt werden, wird dies durch den Eintrag "processing Device: ..."
gekennzeichnet, d.h. in diesem Moment erfolgt das eigentliche Logging des Events in der DB.

Informativ ist auch der Eintrag "count of current log gaps:...". Es ist ein Zähler der pro in der DB zu verbuchenden Event um 1 erhöht wird und nach dem erfolgreichen DB-Insert wieder um 1 vermindert wird. In dem obigen Beipiel sieht man recht gut wie insgesamt 10 Events
verarbeitet werden sollen und der Wert bis auf "count of current log gaps: 10" ansteigt um dann entsprechend der Abarbeitung durch die
Hintergrundprozesse wieder auf "count of current log gaps: 0" zu sinken.

Auch im state-Reading wird mit "still to update - <Anzahl der offenen Verbuchungen>" ein Überblick über den Zustand des DbLog gegeben.

State sollte demzufolge nur kurzfristig ungleich "0" sein. Wenn z.B. durch Nichterreichbarkeit der DB oder andere Umstände wie Timeout
ein Event nicht in die DB eingefügt werden konnte, wird z.B. "still to update - 3" angezeigt, sofern 3 Prozesse ihre Daten nicht an die DB
loswurden.
Gleiches gilt für den Logeintrag "count of current log gaps:..." mit verbose 4. Auch dieser würde in diesem Fall "3" im Minimum anzeigen.
Bei jedem Restart von FHEM wird dieser Zähler auf 0 gesetzt.

Das Ganze funktioniert auch gut mit dem global Attribut "blockingCallMax", das seit einiger Zeit gesetzt werden kann um die maximal gleichzeitig
laufenden BlockingCalls zu begrenzen.
Das kann hilfreich sein, wenn man wie ich bereits eine ganze Reihe non-blocking Devices (76_SMAInverter, 77_SMAEM, umfangreiche Anzahl 93_DbRep, 93_DbLog,
42_SYSMON, 98_HMinfo, ....) im Einsatz hat.
Wenn verbose 4 gesetzt ist, kann man sehr schön die Auswirkungen verschieden gesetzter blockingCallMax-Werte verfolgen und so den
individuell günstigen Wert finden. Es soll eine zügige Verarbeitung der Events erfolgen, jedoch andererseits nicht die CPU(s) zu stark
auslasten um nicht die Vorteile der non-blocking Arbeitsweise durch einen Bottleneck hervorgerufen durch eine zu hohe CPU-Auslastung
wieder einzubüßen.

@Tobias, rapster ... ich würde mich freuen wenn die Änderungen nach erfolgreichen Tests durch euch/anderen Usern in das offizielle DbLog
einfließen.

@all ... bitte FHEM auf jeden Fall nach Einspielen des Moduls restarten !

Ich freue mich auf eure Testergebnisse und Rückmeldungen.

viele Grüße
Heiko

Ich will anmerken, dass BlockingCall nicht fuer so haeufige Aufrufe gedacht ist. Fuer jede Event-Zeile etliches an Perl-Code, 1*fork(), n*close(), 2*connect, usw. auszufuehren belastet das System deutlich staerker, als mit der aktuellen Implementation. Andererseits freut es mich, wenn bei dir dabei keine Probleme mit BlockingCall aufgefallen sind.

Wenn es nicht blockierend sein soll, dann z.Bsp. beim define ein BlockingCall Prozess anlegen, der ein Serverport oeffnet, mit dem Modul dahin eine Verbindung aufnehmen, und die Daten jeweils diesem zweiten Prozess schicken. Das geht auch nicht-blockierend, z.Bsp. macht FHEMWEB sowas mit addToWritebuffer().

Dieser Anwendungsfall ist eigentlich ideal für SubProcess.pm

Gruß
Markus

Hallo Rudi und Markus,

danke für eure Hinweise.

@Rudi ... ja, läuft bei mir richtig gut. Mit dieser Testversion komme ich auf durchschnittlich 32 - 190 ms (apptime). Vorher lag ich oftmals bei über 1000ms. Weiß nicht wie so etwas auf einem PI läuft, hab ja ein virtualisiertes Linux, aber die positiven Ergebnisse freuen mich  :) ... danke für den Hinweis zu FHEMWEB mit addToWritebuffer() ... schaue ich mir auch mal an.

@Markus, SubProcess.pm würde ich mir auch gerne mal dafür anschauen. Kannst du mir einen Tipp geben wo ich ein Beispiel für die Verwendung finde ?

Grüße
Heiko

Hallo Heiko,

das Modul 88_HMCCU.pm nutzt SubProcess.pm

Es ist leider auch aktuell das einzige. Boris hat SubProcess.pm im Rahmen von https://forum.fhem.de/index.php/topic,34320.0.html erstellt.

Gruß
Markus

Falls du fuer ein DB-Insert 1000ms brauchst, dann ist irgendetwas anderes faul, und ich wuerde das zunaechst beheben.

Thx Markus, dann kann ich mich da mal langhangeln.
Bin trotzdem gespannt ob und wenn ja welche Rückmeldungen von Usern kommen ... ich kann bei mir wie gesagt nichts negatives berichten.

Grüße
Heiko

ZitatFalls du fuer ein DB-Insert 1000ms brauchst, dann ist irgendetwas anderes faul, und ich wuerde das zunaechst beheben.

Für ein Insert nicht, nur habe ich festgestellt dass wenn viele Events gleichzeitig geloggt werden sollten (z.B. die Werte vom Energymeter wie in dem Beispiel), kam es zu Engpässen bzw. zum Anstieg der apptime Ergebnisse. Aber ich habe auch schon an Parametern der MariaDB geschraubt. Die MariaDB auf meiner Synology beherbergt natürlich nicht nur die FHEM-DB's sondern auch noch etliche weitere für andere Applikationen. Mit diesen hatte ich bislang noch keine Probleme festgestellt, allerdings auch nicht so intensiv untersucht muß ich zugeben ....

Diese Diskussion ist auch deshalb interessant, weil ich bereits viele User hatte, die sich über eine schlechte Performance des Wunderground Moduls beklagen, wenn sie über DbLog loggen. Da dort regelmäßig mehrere Duzend Readings aktualisiert werden und die User wohl gerne nach dem Motto "was ich hab das hab ich" loggen, wird DbLog entsprechend stark beansprucht und während der Zeit blockiert FHEM dann doch merklich einige Sekunden auf schwächeren Systemen.
Vielleicht eignet sich das Modul deshalb auch ganz gut für einen Benchmark :-)




Gruß
Julian

zu allem außer Blocking: ich finde die änderungen sehr gut.  und es wäre schöne wenn sie übernommen werden.

zu Blocking: das ist der falsche ansatz. zum einen gibt es datenbanken die nicht multi prozess fähig sind (sqlite) das wäre das ganze kontraproduktiv und würde nicht funktionieren. zum anderen: ich glaube es wäre sinnvoller die db ohne fork asynchron zu betreiben. damit solltest du mindestens die gleiche verbesserung sehen ohne den zusätzlichen overhead durch das forken. unterm
strich sollte es also noch. esser werden.

ich vermute auch das die x prozesse die sich um die db streiten zwar alle vom fhem entkoppelt sind, sich aber eigentlich gegenseitig blockieren weil sie auf die
gleiche tabelle und auch noch an die gleiche stelle zugreifen.

soll heiße wenn man das einfach nach einander und asynchron über die fhem event loop abarbeitet bist du vermutlich mindestens so schnell.

gruss
  andre

ps: warum eine db bei ein paar inserts langsam ist sollte man tatsächlich vorher klären. bei halbwegs adäquater hardware sollten selbst ein paar dutzend readings auf ein mal nicht viel ausmachen.

Mehrere Inserts beschleunigt man, indem man precompiled Statements verwendet (d.h. insert mit ?), und alle in eine Transaktion packt. Manche DB-Module (z.Bsp DBD::Oracle) unterstuetzen Bulk-Insert (Stichwort execute_array), das bringt in manchen Faellen nochmal ein Faktor von 10. Vor ca 10 Jahren habe ich mit perl/execute_array etwa 5000 Inserts/sec erreicht, zugegebenermassen war der Rechner aber schneller als ein RPi.

Hallo zusammen,

erstmal vielen Dank für eure Rückmeldungen und Anregungen.

Was ich jetzt mitnehme ist,  dass Blocking.pm  für diesen Einsatzzweck nicht das Mittel der Wahl ist.
Andererseits ist es dennoch ein Thema das DB-Logging von fhem zu entkoppeln (wie ebenfalls Julians Erfahrungen zeigen), auch unter dem Gesichtspunkt dass wahrscheinlich die Mehrzahl der verwendeten DB's nicht optimal getunt sein werden (meine eingeschlossen).

Ich werde es nochmal mit einem neuen Ansatz versuchen umzusetzen, so wie Andre's Vorschlag einer sequentiellen asynchronen Abarbeitung bzw. die Hinweise von Rudi oder Markus gehen wahrscheinlich in eine ähnliche Richtung.
Wahrscheinlich komme ich aber erst irgendwann nach den Feiertagen dazu mich nochmal intensiver mit dieser Thematik zu beschäftigen.

Ein bisschen Off-Topic ... habe im SQL-Client (ohne jegliches fhem) die Schreibgeschwindigeit für einen Insert in die fhem-db gecheckt.
Sie liegt bei 0.0244 Sekunden. Die DB liegt auf einem Synology Hybrid SHR-Raid 5.
Vergleichswerte sind natürlich gerne willkommen auch wenn sie wegen nicht vergleichbarer Hardware nicht so sehr aussagefähig ist. Nur um mal einen Eindruck zu gewinnen wie schnell andere Systeme schreiben.

Grüße
Heiko

Fuer eine herkoemmliche (sich drehende) Festplatte sind 40 Einzel-Inserts ein normaler Wert, und hat mehr mit der Rotationsgeschwindigkeit, und weniger mit dem Durchsatz der Platte zu tun. Ein Problem entsteht dann, wenn viele Events kommen und man alle loggen will. Z.Bsp. generiert FBAHAHTTP alle 5 Minuten fuer alle angeschlossenen FBDECT Geraete jeweils 13 Events, das sind bei 10 Geraeten 130 Events auf einmal. Damit waere deine Platte mit der aktuellen Architektur 3+ Sekunden lang ausgelastet. Falls man diese Daten zusammenfasst, dann dauert es sicher unter 0.1s.

Kannst du den Aufwand fuer ein FileLog Aktion messen, um einen Vergleichswert zu haben?

ZitatKannst du den Aufwand fuer ein FileLog Aktion messen, um einen Vergleichswert zu haben?

Wenn ich es richtig interpretiere dauert ein Logfile-Eintrag ca. 0.0253s. Ich habe alle Readings vom SMA-Energymeter (ca. 70) loggen lassen und dann entsprechend geteilt.

EDIT: Verschreiber -> 0.0253s

das 130 events 3 sekunden dauern glaube ich nicht. jedenfalls nicht als normalfall. da stimmt schon etwas nicht.

eine vernünftig konfigurierte db sollte auch bei einzel inserts und einer einzigen platte mehr als 40 schaffen. zumindest wenn sie in memory caches unterstützt. das zeigt ja auch der 0.0244 wert von oben. raid5 ist beim schreiben höchstens 2-3 mal so schnell wie eine einzelne platte.

130*0.0244 = 3.172
Oder habe ich mich verrechnet?

Wenn du mit "in memory caches" NVRAM/FLASH/etc meinst, dann klar.

Sonst habe ich Probleme bei einer Platte mit 5400/min Umdrehungen mehr als 90 Transaktionen pro Sekunde vorzustellen, wenn die Daten nur von einer Quelle seriell kommen. Jede Transaktion muss doch auf die Platte gesynct werden, bevor die DB ein Ack senden darf und zwischen Ack und naechsten insert dreht sich die Platte weiter. Wenn das OS nach jedem Sync den Inode wg. Zeitstempel aktualisiert (wie auf einem "normal" gemounteten FS), dann komme ich auf 45.
Ich kann mich irren, mein Wissen ist 10+ Jahre alt. Lerne aber gerne dazu.

nein. die rechnung stimmt. ich habe mich verrechnet. die synology zahlen sind aber nicht unbedingt repräsentativ. da ist noch ein software raid mit einem langsamen prozessor dazwischen. eine reine platte müsste etwas schneller sein.

aber um bei deinem FBDECT beispiel zu bleiben. die 13 events die auf ein mal kommen sollte man z.b. in einer transaktion schreiben. nicht einzeln. das sollte etwa den faktor 13 bringen.

da fällt mir gerade noch eine ziemliche performance bremse bei dblog ein: wenn man DbLogType nicht auf history setzt wird current bei jedem event gelösct und geschrieben. d.h. es werden die dreifachen ios erzeugt. das müsste vor allem bei mysql/mariadb auffallen. sqlite kann diese tabelle komplett im speicher cachen. da ist es dann nicht ganz so schlimm.

Ich begrüße es sehr, wenn DbLog weiterentwickelt wird. Danke Heiko fürs Einbringen neuer Ideen!
Zu den Änderungen kann ich nicht viel sagen, weil es bei mir selbst auf einem RPI 1 mit MySQL recht performant läuft!

In diesem Zusammenhang möchte ich aber weitere Verbesserungen (für die Zukunft)  mit dem Modul vorschlagen,
mit dem Bewußtsein dass es hier zumindest vorerst um andere Punkte geht:
1: MySql: Erstetzen des separaten insert oder update-Handlings durch ON DUPLICATE KEY UPDATE col1 = 2;
2: SqLite: Erstetzen durch INSERT OR REPLACE INTO history (timestamp, device, ...)   VALUES (xxx, 'yyy', 'zzz');
3. Erweitern des Indexes auf timestamp, device, reading im Unique-Modus:
   Vorteile:
   a) Löschen von Datensätzen dank PK leichter und eindeutig möglich
   b) Vorbeugen von unnützen doppelten Einträgen zur selben Zeit vom selben Device und reading. Das kann weder in Plots noch sonst wo korrekt ausgewertet werden!
4. Bessere Trennung von Einträgen in die Spalten Unit und Value. Hierzu gibts mehrere Einträge im Forum, die Funktion "DbLog_ParseEvent" ist einfach nicht allgemein genug dafür.
5. Besseres Handling wenn der SQL-Server nicht erreichbar ist. (zB lokales Zwischenspeichern).
6. ggf. Bulkinsert nutzen.

Wo ich kann und soll würde ich mich auch einbringen.
:D

Hallo zusammen, hallo Joe,

ich konnte es nicht lassen und habe eine weitere Testversion gebaut (V2.2 hier angehängt).
Aus meiner ersten Version habe ich alle für gut befundenen Änderungen beibehalten und Blocking wieder rausgeschmissen.

Als ich Rudis Anmerkung zu execute_array gelesen habe konnte ich nicht anders als es mal mit dem DBI-Interface umzusetzen.
D.h. es werden mit dieser Version die gefilterten (NOTIFYDEV) und bewerteten Events über ein Array an die DB übergeben und im Block abgearbeiet.
Der Erfolg kann sich im Vergleich zur originalen DbLog sehen lassen.
Ich komme jetzt mit meiner MySQL bei vollem Logging des SMA-Energymeters (71 events im Block) auf einen max-Wert von ca. 120ms. Der
apptime-average liegt bei 32ms.
Wenn ein Gerät nur ein event schmeisst der geloggt werden soll dann liegt der max-Wert bei 27ms mit einem avarage von 12,5ms.
Das sind alles Werte erst einmal von meiner Testmaschine.

Es sind doch erhebliche Performancegewinne zu verzeichnen. Mit SQlite habe ich es noch nicht ausprobiert.

Geändert habe ich auch, dass nur in die Tabelle "History" eingefügt wird wenn das Attribut DbLogType nicht gesetzt ist. Man muß also explizit
Current/History setzen wenn die Bearbeitung beider Tabellen gewünscht ist.

Zusammengefasst sind die Änderungen nun folgende:

* DbLog Push-Funktion ist umgestellt auf execute_array
* Insert nur in Tabell History wenn Attr DbLogType nicht gesetzt ist
* Umstellung der NotifyFn (DbLog_Log) auf deviceEvents
* Einführung von NOTIFYDEV um nur Events von Devices vom DbLog-Device auswerten zu lassen die auch in der DEF angegeben wurden

Auch wenn es noch nicht non-blocking ist dürfte diese Änderung m.M. nach in sehr vielen Fällen Erleichterung schaffen.

Würde mich wieder über Testergebnisse freuen, aber zu weiteren Arbeiten komme ich nun momentan wirklich nicht mehr.

Grüße
Heiko

Bisher läuft es wunderbar.
Die Statusanzeige zeigt regelmäßig Module an, die doppelte Logeinträge generieren, das muss ich mir noch nächer ansehen, aber das war mit dem alten Modul nicht anders.

Die Reaktion von FHEM ist gestiegen, da ich aber auch andere Änderungen gemacht habe (entfernen von Subroutinen aus Userreadings) muss ich das
nochmals genauer prüfen.
Meine CPU_Auslastung ist jedenfalls von 0.04 auf 0.01 gesunken!

Morgen Joe,

Was meinst du mit der Statusanzeige von Modulen .... genau ?

Ich habe es jetzt nicht verstanden und vielleicht fällt mir noch etwas dazu ein.

Grüße
Heiko

Im alten Modul zeigte der state vo, DbLog-Device manchmal folgende meldung an
DbLog: Failed to insert new readings into database: DBD::mysql::st execute failed: Duplicate entry 'bad.Rollo-positionCombi-2016-12-21 06:25:22-0' for key 'PRIMARY' at ./FHEM/93_DbLog.pm line 613.

im neuen Modul sieht die Meldung so aus.
DbLog: Failed to insert new readings into database: DBD::mysql::st execute_array failed: Duplicate entry 'bad.Rollo-positionCombi-2016-12-22 09:51:26' for key 'PRIMARY' [err was 1062 now 2000000000]


Eine Ursache dafür ist, dass ich meine Datenbank so eingestellt habe, dass sie doppelte Einträge nicht zulässt.

Ich habe jedoch noch nicht untersucht, warum manche Devices regelmäßig doppelte Einträge produzieren.
Zu den Devicetypen gehören Homematic Dimmer (im state-reading) oder aber auch manche von mir zuwenig
eingeschränkten userReadings.

Aber wie gesagt, ich denke nicht, dass hier Handlungsbedarf besteht, das funktioniert schon alles ganz gut.
Ein Analysetool könnte höchstens (irgendwann mal) diese Module (oder Userreadings) ausfindig machen und dem Benutzer zur Verbesserung melden...

Ich habe es auch mal getestet.

Lief soweit, weniger freezes, aber ich musste aber plotfork deaktivieren, dadurch bei den Grafiken größere freezes.
Und beim Modul 98_lifetracking.pm wurde nichts mehr gelogt.

Habe jetzt wieder zurückgesetzt auf original DbLog.

Hallo stromer-12,
Danke für die Info.
Ich glaube den Fehler gefunden zu haben ...Habe etwas im Code vergessen.
Bei mir auf dem Tablet habe ich es schnell geändert und läuft.
Lade heute Abend eine korrigierte Version zum Test hoch.

Grüße,
Heiko

Hallo zusammen,

hier die korrigierte V2.3. Sie sollte das von stromer-12 gemeldete Problem beseitigen.
Habe auch nochmal speziell mit plotfork=1 auf meinen beiden Systemen gecheckt. Keine Probleme festgestellt.

Grüße
Heiko

Hast Du eine Ahnung, woher dieser Fehler stammen kann?
Dieser kommt vorallem nach dem Neustart
DbLog: Error in inline function: <:>, Error: syntax error at (eval 3222) line 1, near ":"

Ansonsten läuft nun auch bei mir Plotfork! Danke!

Morgen Joe,

ich habe einen alten Thread gefunden: https://forum.fhem.de/index.php/topic,21440.msg149401.html#msg149401 (https://forum.fhem.de/index.php/topic,21440.msg149401.html#msg149401)

Dort war die Lösung:

Zitat... Ich habe den Fehler gefunden. Bei einem Plot hatte ich ein ":" zuviel in der Spec eines Wertes....

Könnte mir ähnliches bei dir vorstellen.

Grüße
Heiko

Morgen Heiko,

das wars tatsächlich... sorry, dass ich nicht zuvor selbst gesucht hatte, mir war es gerade eben nur aufgefallen und ich dachte es wäre hilfreich. sorry!

Offtopic:
Manchmal habe ich das Gefühl, die "::" in den Plots vermehren sich von selbst ;-)

Ist doch Weihnachten  :D

Ich habe das geänderte DbLog inzwischen auch auf meiner Prod-Instanz laufen und bin auch dort mit der Performance schon sehr zufrieden.
Der apptime max-Wert liegt hier so um die 290ms, der average liegt ebenfalls bei 30ms. Es gibt bei mir natürlich Einflüsse durch die Architektur auf dem NAS, die MySQL ist nicht exklusiv für FHEM vorhanden.

Ich habe es auch gestern Abend noch mal erneuert. Das mit plotfork klappt jetzt gut.

Nur wurden vom livetracking Modul keine Werte mehr geloggt. mit der originalen Version klappt das aber.
Fehler werden auch keine angezeigt. Ich bin jetzt wieder auf original zurück.
Ich weis jetzt nicht, ob noch wo anders etwas nicht geloggt wird.

Die einzige Stelle die ich mir momentan vorstellen kann ist dass dein lifetracking-Device nicht im Internal NOTIFYDEV enthalten ist.
Alle zu loggenden Devices sollten dort enthalten sein. (Screenshot). Hast du FHEM restartet mit dem neuen DbLog-Modul ?
Ansonsten stelle mal bitte verbose 4 ein. Dann sieht man im Logfile was bewertet und geloggt wird.
Bei mir wird alles geloggt was auch im NOTIFYDEV enthalten ist und was in die DB soll.

Ich hatte jedesmal einen Restart gemacht.

Ich habe es gerade noch mal eingebunden.
Es wird vom Dblog erkannt, den die splitFn Funktion wird aufgerufen.


2016.12.23 16:01:45.708 4: track_Companion OwnTracks: 2016-12-23 16:01:25  {"_type":"location","t":"u","tid":"1","acc":21,"lat":xx.087540,"lon":yy.390250,"tst":1482505285,"batt":55,"dis":16}
2016.12.23 16:01:45.720 4: DbLog myDbLog -> max events: 1 for device track_Companion
2016.12.23 16:01:45.720 4: DbLog myDbLog -> check Device: track_Companion , Event: battery: 55 %
2016.12.23 16:01:45.721 5: DbLog_ParseEvent calling external DbLog_splitFn for type: livetracking , device: track_Companion
2016.12.23 16:01:45.721 5: event battery: 55 %
2016.12.23 16:01:45.722 5: output battery / 55 / %
2016.12.23 16:01:45.723 4: DbLog myDbLog -> processing event Timestamp: ARRAY(0x5c4e280), Device: track_Companion, Type: LIVETRACKING, Event: battery: 55 %, Reading: battery, Value: 55, Unit: %


Mein notifydev lautet .*

Ich denke das wird das Problem sein:

event Timestamp: ARRAY(0x5c4e280), Device:.....

Dort steht normalerweise der Timestamp so wie bei mir:

processing event Timestamp: 2016-12-23 15:57:37, Device: MySTP_5000

Teste mal bitte die angehängte Version ob es dann bei dir ok ist.

Ich wollte nach den Feiertagen mein dbLog eh etwas umbauen, dann werde ich Deine Version mal testen. Grüße

ZitatIch wollte nach den Feiertagen mein dbLog eh etwas umbauen, dann werde ich Deine Version mal testen

Würde mich freuen, gemeinsam geht halt alles besser  :)
Schöne Feiertage ! Ich mache auch erst im neuen Jahr etwas weiter.

Grüße
Heiko

Jetzt klappt der Eintrag   :)

2016.12.23 16:49:08.417 4: DbLog myDbLog -> processing event Timestamp: 2016-12-23 16:49:08, Device: track_Companion, Type: LIVETRACKING, Event: battery: 53 %, Reading: battery, Value: 53, Unit: %

Prima  :)

Wenn du dir einen Überblick über Performance gemacht hast wäre es interessant zu wissen und welche DB du einsetzt.
Danke für die Geduld beim Test und einen schönen Abend !

Grüße
Heiko

Wenn ihr möchtet: Im Rahmen von Unit.pm gibt es bereits auch eine generalisierte Funktion, die für alle Module einmal als Standard Split Funktion für die Einheiten, welche einmal dafür gedacht wäre, dass sie für alle Module einsetzbar ist und somit gar in das DbLog Modul wandern könnte.


https://github.com/mhop/fhem-mirror/blob/master/fhem/FHEM/Unit.pm#L3715-L3771 (https://github.com/mhop/fhem-mirror/blob/master/fhem/FHEM/Unit.pm#L3715-L3771)


Wird momentan von den Modulen Wunderground und HP1000 genutzt.
Die Performance Diskussion zu DbLog mit Wunderground gab es hier schon (wenig fortgeschritten): https://forum.fhem.de/index.php?topic=61085 (https://forum.fhem.de/index.php?topic=61085.new#new)

Zitat von: Loredo am 23 Dezember 2016, 17:06:43
Wenn ihr möchtet: Im Rahmen von Unit.pm gibt es bereits auch eine generalisierte Funktion, die für alle Module einmal als Standard Split Funktion für die Einheiten, welche einmal dafür gedacht wäre, dass sie für alle Module einsetzbar ist und somit gar in das DbLog Modul wandern könnte.

Mit diesem Modul wäre eine der Baustellen, die ich weiter oben in meiner Liste genannt habe, mit korrigiert....!
Das Unithandling von DbLog ist recht "brachial" und in  die Jahre gekommen.

Ich teste aktuell mit einem kleinen x86-Server auf Atomm und einer DB mit 59GB und  600 Mio. Datensätzen.
Es flutscht: => Ist angenehm schnell und reagiert deutlich spritziger im Vergleich zu zuvor.

Danke, unf fröhliche Feiertage euch allen.

Zitat von: JoeALLb am 23 Dezember 2016, 17:22:21
Das Unithandling von DbLog ist recht "brachial" und in  die Jahre gekommen.

Aktuell taugt Unit.pm auch fast nur zum loggen, weil wir Rudi bisher nicht davon überzeugen konnten einige wenige Patches in fhem.pl, FHEMWEB und TELNET zu akzeptieren. Überzeuger welcome ;-)

Hallo zusammen,

guter Vorschlag Loredo und Joe. Mir ist das ungenügende Split vor allem bei Sysmon aufgefallen.
Jetzt habe ich den gegenwärtigen Entwicklungsstand noch etwas geschönt, das verbose 4 Logging verbessert und hier als V2.4 angehängt.

Es kann uns als Grundlage für die weitere Entwicklung dienen bzw. m.M. nach so wie es ist das bisherige DbLog im SVN ersetzen.  Schön wäre es wenn sich noch ein paar mehr Tester finden würden.

Wenn ich wieder Zeit finde schaue ich mir mal die Integration der Split-Funktion von Unit.pm ins DbLog an. Falls du Lust hast kannst du es ja schonmal probieren Loredo .....

Aber jetzt erstmal allen schöne Weihnachten und paar Tage der Erholung ... bis zum neuen Jahr !

Grüße
Heiko

Zitat von: DS_Starter am 24 Dezember 2016, 08:26:11
Schön wäre es wenn sich noch ein paar mehr Tester finden würden.

Ich wills schon länger mal einbauen, bin aber noch nicht dazu gekommen.

Kann ich das Modul gefahrlos auf einem Prod-System einbauen oder laufe ich Gefahr, irgendwas (in der DB) zu zerschießen?
Backups für den Notfall hab ich natürlich ...

Grüße
Stephan

Ich würde erwarten, dass es das vorhandene Modul ersetzt und es abwärtskompatibel ist.


Gruß

Julian

Ich würde es gut finden, wenn man die verbose Ausgaben von dblog mehr auf bestimmte Device begrenzen könnte.
Sonst es wird sonst ganz schon viel Ausgaben erzeugt bei einer größeren Fhem Installation.

So, Version 2.4 ist jetzt einen Tag gelaufen, letzte Nacht gerade mal 6 Freezes von 1-2.5 Sekunden vorher waren es viel mehr und längere Freezes.

Meine Datenbank ist ca 15GB groß und hat ca 60M Datensätze.

super version 2.4 bremst bei mir fhem derzeit nicht mehr aus. Wichtig finde ich es nicht die Geräte anzugeben welche ich loggen will ... sondern Geräte die ich nicht im Log haben möchte.
Cool wäre es per attr einfach anzugeben.

Wie kann ich Freezes auswerten?

Vielen Dank ....

Die überarbeitete Version (2.4) habe ich getestet und es war sofort ein Geschwindigkeitszuwachs bei Fhem zu bemerken...Keine ewige Ladezeiten mehr im Web etc. Ich hatte teils Freezes bis zu 30s . Komplett weg....

Ich hoffe das wird demnächst eingecheckt...

Hi,
finde ich super das jemand das NonBlocking einbaut. Habe bisher zu wenig Zeit dafür gefunden da ich selbst nur wenige freezes von 1-2sek habe und eher weniger auffällt.

Bzgl. dem Unit Splitting: Es obliegt jedem Modul selbst die DBLog_Split funktion aufzurufen und entsprechend die EInheiten sauber zu übergeben. Diese Funktion gibt schon seit einiger Zeit im DBLog Modul (siehe Wiki -> Developer Infos) . Das "alte" Splitting direkt im DBLog Modul ist "deprecated" und soll bald aus dem Modul selbst raus...

Wenn die Anpassungen gut getestet sind checke ich es natürlich gerne ins Fhem Repo ein...

Hallo zusammen, hallo Tobias,

habe nun doch etwas Zeit gefunden und ein bisschen weiter gearbeitet.
Mit angehängten Version V2.4.3 wurde folgendes ergänzt/verbessert:

* Da nunmehr ein Blockinsert stattfindet wurde eine Auswertung eines jeden Datensatzes innerhalb des Blocks hinsichtlich der erfolgreichen DB-Operation nötig.
   Insbesondere wenn die current-Tabelle neu aufgebaut wird oder Datensätze hinzugefügt werden ist zunächst der Erfolg eines Updates zu checken um bei Misserfolg ein
   Insert statt dessen durchzuführen. Nun wird execute_array entsprechend stärker analysiert und evtl. Fehler im "state" bzw. Logfile (verbose 2) ausgegeben.

* Es gibt das Attribut "verbose4Devs".  Es dient dazu verbose4-Ausgaben auf die interessierenden Devices zu beschränken. Es war eine Anregung von stromer-12.
   Falls gewünscht eine kommaseparierte Liste der relevanten Devices angeben. Bei einstelltem verbose 4 werden nur noch diese Geräte in der Logfile-Ausgabe
   berücksichtigt. Damit man daran erinnert wird, erscheint bei nicht berücksichtigten Devices im Log:
   
   DbLog LogDB -> verbose 4 logging of device SMA_Energymeter skipped due to attribute "verbose4Devs" restrictions
   

Als weiterer Nebeneffekt ist herausgekommen dasss bei mir nun auch die Ausgaben von Sysmon richtig separiert und geloggt werden.

Danke auch an alle die mittesten und ihre Erfahrungen hier teilen !
Wichtig wäre auch zu wissen ob ihr mit MySQL/MariaDB oder SQLite arbeitet um einschätzen zu können, wie das Ganze auf den verschiedenen Architekturen läuft bzw. getestet ist.

Vom richtigen "non-blocking" sind wir zwar noch entfernt, aber mit dieser Technik offensichtlich schon ein gehöriges Stück in die gewünschte Richtung gekommen.

viele Grüße
Heiko

Bevor ich es teste, sollte(!) es auch mit einer PostgreDB funktionieren? Ich setze eine solche ein.

Hallo Tobias,

sollte ... ja. Nur habe ich keine zum Testen und bisher hatte sich hier auch niemand gemeldet der eine einsetzt.
Insofern wärst du der erste ....

Grüße
Heiko

Super Update gemacht läuft nutze pi3 mit normalen mysql server.

Auschließen habe ich im Gerät dbexeclude .* funktioniert super

Zitat von: Tobias am 28 Dezember 2016, 14:47:39
Bevor ich es teste, sollte(!) es auch mit einer PostgreDB funktionieren? Ich setze eine solche ein.

Nach einem schnellen Test, ja es funktioniert.
Gründlich alles mögliche durchtesten werde ich erst die nächsten Tage können.

Zitat von: Tobias am 28 Dezember 2016, 14:47:39
Bevor ich es teste, sollte(!) es auch mit einer PostgreDB funktionieren? Ich setze eine solche ein.

Hi,

Läuft bisher (V2.4) ohne Zwischenfälle auf meiner Postgres.

Greetz
Eldrik

Zitat von: Tobias am 28 Dezember 2016, 13:32:12
Bzgl. dem Unit Splitting: Es obliegt jedem Modul selbst die DBLog_Split funktion aufzurufen und entsprechend die EInheiten sauber zu übergeben. Diese Funktion gibt schon seit einiger Zeit im DBLog Modul (siehe Wiki -> Developer Infos) . Das "alte" Splitting direkt im DBLog Modul ist "deprecated" und soll bald aus dem Modul selbst raus...

Kann auch gerne so beibehalten werden, die Funktion in Unit.pm ist auch nur ein Angebot wie man Einheiten (plus logging) in sein Modul integrieren kann.

Zitat von: Tobias am 28 Dezember 2016, 13:32:12
Hi,
finde ich super das jemand das NonBlocking einbaut. Habe bisher zu wenig Zeit dafür gefunden da ich selbst nur wenige freezes von 1-2sek habe und eher weniger auffällt.

Heißt das, Du möchtest der Modulverantwortliche bleiben? Ich hatte die letzten Monate eher das Gefühl, dass Dich die Weiterentwickling des Moduls nicht mehr sonderlich interessiert.... und hatte nach dem ein oder anderen Kommentar irgendwie für mich gedacht, dass Du die Modulverantwortung gerne übergeben würdest... Mag sein, dass das völlig falsch ist, dann verzeih die Frage und vergiss es.
Ich hoffe, das darf man hier rückfragen, da das Ergebnis der Antwort mich doch irgendwie direkt betrifft....

Hallo miteinander,

nun habe ich den Wunsch von ChrisW auch noch umgesetzt um Devices vom Logging in der DB ausschließen zu können, also die Negation des Inkludierens im Define.
Dazu gibt es das Attribut "excludeDevs", welches wieder eine kommaseparierte Liste der auszuschließenden Devices bekommen muß. Dieses Attribut zieht aber nur wenn
im Define ALLE Devices inkludiert werden, also der Form ".*:...." . Dies soll vermeiden, dass auf der einen Seite Devices explizit inkludiert werden um durch Angabe im Attribut wieder ausgeschlossen zu werden.

Weiterhin akzeptieren die Attribute "verbose4Devs" bzw. "excludeDevs" nun auch Platzhalter.

Auszug aus Commandref:

    verbose4Devs
        attr <device> verbose4Devs <device1>,<device2>,<device..>
        Mit verbose Level 4 werden nur Ausgaben bezüglich der in diesem Attribut aufgeführten Devices im Logfile protokolliert. Ohne dieses Attribut werden mit verbose 4 
        Ausgaben aller relevanten Devices im Logfile protokolliert. Die angegebenen Devices werden als Regex ausgewertet.
       Beispiel
        attr <device> verbose4Devs sys.*,.*5000.*,Cam.*,global
        # Es werden Devices beginnend mit "sys", "Cam" bzw. Devices die "5000" enthalten und das Device "global" protokolliert falls verbose=4 eingestellt ist.

    excludeDevs
        attr <device> excludeDevs <device1>,<device2>,<device..>
        Die Devices "device1", "device2" bis "device.." werden vom Logging in der Datenbank ausgeschlossen. Diese Attribut wirkt nur wenn im Define des DbLog-Devices
        ".*:.." (d.h. alle Devices werden geloggt) angegeben wurde. Dadurch können Devices explizit ausgeschlossen werden anstatt alle zu loggenden Devices im Define
        einzuschließen (z.B. durch den String (device1|device2|device..):.* usw.). Die auszuschließenden Devices werden als Regex ausgewertet.
        Beispiel
        attr <device> excludeDevs global,Log.*,Cam.*
        # Es werden die Devices global bzw. Devices beginnend mit "Log" oder "Cam" vom Datenbanklogging ausgeschlossen.

Die Commandref habe ich auch überarbeitet um die zusätzlichen Attribute und die Änderung bzgl. Nutzung von Tabelle "history" (Stichwort Attribut DbLogType) zu
dokumentieren.

@Tobias ... wenn andere Tester nicht noch irgendwelche Fehler melden, wäre die anghängte Version m.M. nach fertig vorbereitet für den Check-In. Bei mir läuft auch diese Version tadellos.

@Loredo ... wegen der Anmerkung von Tobias zur DBLog_Split Funktion ändere ich diesbezüglich zunächst nichts mehr im DbLog. Aber ich betreue derzeit noch das Modul SMAInverter welches Readings erzeugt die eigentlich mit Einheiten versehen sind/sein sollten. Hier möchte ich versuchen die DBLog_SplitFn unter Verwendung der Unit.pm einzubauen um DbLog die Variablen über diese Funktion zur Verfügung zu stellen.
Hast du noch Hinweise zur Verwendung von Unit.pm oder sollte ich klarkommen wenn ich den von dir angegebenen Thread bzw. deine Module studiere ? (sonst gern auch als PM um den Thread hier nicht zu stören )

Anbei die Version V2.5, die all das Beschriebene enthält.

Grüße,
Heiko

Vielen Dank ;) Gleich mal ausprobiert. Scheint zu klappen.

 Habe jetzt die aktuelle Version (2.5) mit meiner Mysql/MariaDB 10.0.28 am Laufen.....Bisher alles top. :)

Zitat von: DS_Starter am 29 Dezember 2016, 15:40:32
@Loredo ... wegen der Anmerkung von Tobias zur DBLog_Split Funktion ändere ich diesbezüglich zunächst nichts mehr im DbLog. Aber ich betreue derzeit noch das Modul SMAInverter welches Readings erzeugt die eigentlich mit Einheiten versehen sind/sein sollten. Hier möchte ich versuchen die DBLog_SplitFn unter Verwendung der Unit.pm einzubauen um DbLog die Variablen über diese Funktion zur Verfügung zu stellen.
Hast du noch Hinweise zur Verwendung von Unit.pm oder sollte ich klarkommen wenn ich den von dir angegebenen Thread bzw. deine Module studiere ? (sonst gern auch als PM um den Thread hier nicht zu stören )

Passt für mich.

Unit.pm ansich muss man sich nicht unbedingt anschauen (höchstens um zu erfahren, welche vordefinierten RTypes/Units es gibt und wie sie heißen).
Ansonsten zeigen Wunderground.pm und HP1000.pm, wie es geht. Auch wenn Unit.pm intern noch nicht fertig ist, bleiben diese grundsätzlichen Sachen aus Modulsicht erhalten. Im Grunde muss man nur Unit.pm laden und in X_Initialize() ein paar Dinge eintragen:


use Unit.pm;

sub X_Initialize($) {

   [...]

   $hash->{DbLog_splitFn} = "Unit_DbLog_split";

   [...]

   $hash->{readingsDesc} = {
      'readingname1' => { rtype => '<Key aus $rtypes in Unit.pm>', },
      'readingname2' => { rtype => '<Key aus $rtypes in Unit.pm>', },
      'temperature' => { rtype => 'c', },
      'temperature_f' => { rtype => 'f', },
      'humidity' => { rtype => 'pct', formula_symbol => 'H', },
   }

   [...]

}



Es gibt natürlich viele Möglichkeiten da noch was einzustellen, aber das ist noch nicht unbedingt alles Rund und daher auch noch nicht beschreibenswert. Für DbLog ist damit aber die Funktion die Einheit im richtigen Format zu bekommen gegeben.
Wenn Fragen auftauchen oder z.B. Einheiten fehlen, bitte bevorzugt hier im Thread (https://forum.fhem.de/index.php/topic,60285.0.html) öffentlich darüber diskutieren, damit alle was davon haben. PM ist sonst so eine Einzelgeschichte ;-)

ZitatWenn Fragen auftauchen oder z.B. Einheiten fehlen, bitte bevorzugt hier im Thread öffentlich darüber diskutieren, damit alle was davon haben. PM ist sonst so eine Einzelgeschichte ;-)

Machen wir so .... danke für die Erläuterungen.  :)

schönen Abend,
Heiko

Version 2.4 läuft seit einer Wocher unter Postgresql und auch Sqlite ohne Auffälligkeiten. :)

Hallo miteinander,

kurz Rückmeldung auch bei mir.
Die letzte Version 2.5 läuft nun bereits etliche Tage problemlos auf meinen beiden MariaDB/MySQL-Instanzen.

Momentan habe ich eine weitere Version im Test.
Ausgehend von der V2.5 habe ich DbLog um eine asynchrone Loggingmöglichkeit erweitert.

Was heißt das ?
Die neue Version kann zunächst unverändert zur V2.5 genutzt werden, d.h. die Events werden synchron als Bulkinsert in die DB geschrieben.
Mit einem neuen Attribut "asyncMode=1" kann auf den asynchronen Modus umgeschaltet bzw. zwischen beiden Modi geswitcht werden.

Die Merkmale des asynchronen Modus sind folgende:

* Die auftretenden und bewerteten Events werden nicht mehr direkt in die DB geschrieben, sondern zunächst im Speicher gecacht.
  Die gecachten Events können mit dem neuen Befehl "set ... listCache" angezeigt werden.
  Es wird ein Reading "CacheUsage" mit der Anzahl der augenblicklich im Speicher gehaltenen Events erzeugt.
  D.h. die Notify-Funktion DbLog_Log ist sehr schnell und wird nicht mehr durch die DB-Zugriffszeit beeinflußt.
 
* Abhängig vom Attribut "syncInterval" werden die im Speicher gecachten Events in die DB wiederum als Bulkinsert weggeschrieben.
  Ist die DB nicht erreichbar, verbleiben die Events im Cache und werden im nächsten Zyklus gespeichert sofern die DB dann
  erreichbar ist. Das Default-Syncinterval ist 30 Sekunden.
  Es wird das Reading "NextSync" mit dem Zeitpunkt des nächsten Synclaufes erzeugt.
  Für diese Technik verwende ich wieder BlockingCall, der sich m.M. nach nun gut entgegen dem ersten Anlauf
  verwenden lässt da der Aufruf in dem Kontext relativ selten erfolgt, der DB-Zugrif als Bulkinsert passiert und nur ein
  Insertprozess gleichzeitig läuft was den Restriktionen von SQLite Rechnung trägt.
 
* wird vom asynchronen Modus in den synchronen Modus geswitcht, werden die im Cache gehaltenen Events sofort in die DB weggeschrieben.

* Wenn FHEM mit "shutdown ..." heruntergefahren bzw. restartet wird, werden die noch im Cache gehalteten Events in die DB weggeschrieben.
  Es gibt im DBLog schon immer das Attribut "shutdownWait" was eine Wartezeit beim shutdown zum Zweck einer ordnungsgemäßen Beendigung
  der DB-Verbindung bweirkt. Dieses Attr sollte gesetzt sein. Ich habe gute Erfahrungen mit einem Wert von 2s gemacht. Damit wurden
  bisher alle gecachten Events problemlos noch in die DB geschrieben bevor FHEM endete.
 
Das ist der momentane Entwicklungsstand bei mir. Er befindet sich zur Zeit in der Testphase und es sieht richtig gut aus :).
Sobald es bei mir fehlerfrei läuft, stelle ich die neue Version hier wieder zur Verfügung. Es dürfte diese Woche noch soweit sein.

Wenn die eben beschriebene Version gut getestet ist, sehe ich folgende weiteren Schritte:

Es werden die Events bei Nichtverfügbarkeit der DB zunächst aus dem Cache asynchron non-blocking in eine File-basierende DB geschreiben um
einerseits bei längerem DB-Ausfall den Memory nicht zu sehr zu belasten und andererseits die Events bei einem FHEM-Absturz
nicht zu verlieren (sofern es sich um einen längeren DB-Ausfall handelt). Wird die DB irgendwann wieder verfügbar sein, werden die
Events aus der File-DB in die richtige DB übertragen und im File gelöscht.
Desweiteren wäre es noch möglich das eingangs erwähnte SubProcess.pm statt Blocking zu verwenden bzw. Rudis Hinweis aus #1 umzusetzen.

Allen ein gutes neues Jahr !

viele Grüße
Heiko

Zitat von: DS_Starter am 03 Januar 2017, 13:47:34
* Die auftretenden und bewerteten Events werden nicht mehr direkt in die DB geschrieben, sondern zunächst im Speicher gecacht.
  Die gecachten Events können mit dem neuen Befehl "set ... listCache" angezeigt werden.
  Es wird ein Reading "CacheUsage" mit der Anzahl der augenblicklich im Speicher gehaltenen Events erzeugt.
  D.h. die Notify-Funktion DbLog_Log ist sehr schnell und wird nicht mehr durch die DB-Zugriffszeit beeinflußt.

[...] 
en die Events bei Nichtverfügbarkeit der DB zunächst aus dem Cache asynchron non-blocking in eine File-basierende DB geschreiben um
einerseits bei längerem DB-Ausfall den Memory nicht zu sehr zu belasten und andererseits die Events bei einem FHEM-Absturz
nicht zu verlieren (sofern es sich um einen längeren DB-Ausfall handelt). Wird die DB irgendwann wieder verfügbar sein, werden die
Events aus der File-DB in die richtige DB übertragen und im File gelöscht.

Ein Traum wird wahr!! Vielen Dank dafür! Damit kann ich auch die Speicherkarte am RPI, die nicht so viele Speicherzugriffe abbekommen sollte, endlich noch besser entlasten!

Heiko, ich bin beeindruckt :)

das klingt klasse !

gruss
  andre

Großartig!


Von unterwegs gesendet.

WoW

Hallo miteinander,

Nun habe ich die neue Version V2.8.1 auf meinen MariaDB/MySQL Instanzen und auch auf einer SQLite getestet. Läuft bei mir tadellos.
Sie ist hier zum Test angehängt.

Wenn ihr die neue Version einspielt und FHEM restartet ! ist die Arbeitsweise zunächst unverändert zur letzten Version V2.5, d.h. die
Events werden synchron mit Bulk-Insert in die DB geschrieben.

Mit einem neuen Attribut "asyncMode=1" kann nun auf den asynchronen Modus umgeschaltet bzw. zwischen synchronen/asynchronen Modus geswitcht werden.

Die Merkmale des asynchronen Modus und weiteren Änderungen hier nochmal zusammengefasst:

* Die auftretenden und bewerteten Events werden nicht mehr direkt in die DB geschrieben, sondern zunächst im Speicher gecacht.
  Die gecachten Events können mit dem neuen Befehl "set ... listCache" angezeigt werden.
  Es wird ein Reading "CacheUsage" mit der Anzahl der augenblicklich im Speicher gehaltenen Events erzeugt.
  D.h. die Notify-Funktion DbLog_Log ist sehr schnell und wird nicht mehr durch die DB-Zugriffszeit beeinflußt.

* Abhängig vom Attribut "syncInterval" werden die im Speicher gecachten Events in die DB wiederum als Bulkinsert weggeschrieben.
  Ist die DB nicht erreichbar, verbleiben die Events im Cache und werden im nächsten Zyklus gespeichert sofern die DB dann
  erreichbar ist. Das Default-Syncinterval ist 30 Sekunden.
  Es wird das Reading "NextSync" mit dem Zeitpunkt des nächsten Synclaufes erzeugt.
  Für diese Technik verwende ich wieder BlockingCall, der sich m.M. nach nun gut entgegen dem ersten Anlauf
  verwenden lässt da der Aufruf in dem Kontext relativ selten erfolgt, der DB-Zugrif als Bulkinsert passiert und nur ein
  Insertprozess gleichzeitig läuft was den Restriktionen von SQLite Rechnung trägt.

* wird vom asynchronen Modus in den synchronen Modus geswitcht, werden die im Cache gehaltenen Events sofort in die DB weggeschrieben.

* Wenn FHEM mit "shutdown ..." heruntergefahren bzw. restartet wird, werden die noch im Cache gehalteten Events in die DB weggeschrieben.
  Es gibt im DBLog schon immer das Attribut "shutdownWait" was eine Wartezeit beim shutdown zum Zweck einer ordnungsgemäßen Beendigung
  der DB-Verbindung bweirkt. Dieses Attr sollte gesetzt sein. Ich habe gute Erfahrungen mit einem Wert von 2s gemacht. Damit wurden
  bisher alle gecachten Events problemlos noch in die DB geschrieben bevor FHEM endete.
 
* Beim Wechsel in den "disabled"-Modus werden im Cache befindliche Events in die DB geschrieben und danach das Modul disabled sofern
  der asynchrone Modus eingeschaltet ist.
 
* neue Internals MODE bzw. VERSION

* im asynchronen Mode kann mit dem Attr "showproctime" die Verabeitungszeit des Hintergrundprozess ausgegeben werden. In dem Fall
  werden die Readings "background_processing_time" (gesamte Zeit im BlockingCall) und "sql_processing_time" (verbrauchte Zeit für
  SQL-Statements) erzeugt.

Bei mir habe ich mit dem Attr "syncInterval" den Schreibzyklus auf 70s eingestellt damit man die Gelegenheit hat den Aufbau
des Caches zu verfolgen und sich mit "listCache" auch mal anzuzeigen bevor er in die DB weggeschrieben wird.
Nach dem Umschalten in den asyncMode einmal den Browser aktualisieren damit ihr die neuen Readings seht.

Wenn die Version bei euch ebenfalls getestet ist und sauber läuft, würde ich die Commandref überarbeiten und mich dann auch mit der
Möglichkeit einer optionalen File-basierenden DB beschäftigen um einerseits bei längerem DB-Ausfall den Memory nicht zu sehr zu belasten
und andererseits die Events bei einem FHEM-Absturz nicht zu verlieren (sofern es sich um einen längeren DB-Ausfall handelt).
Wird die DB irgendwann wieder verfügbar sein, sollen die Events aus der File-DB in die richtige DB übertragen und im File gelöscht werden.
So der Plan ...

Damit befasse ich mich aber erst wenn der jetzige Entwicklungsstand hinreichend auch bei euch getestet ist.
Also viel Spaß beim Test und gerne wieder Rückmeldungen bzgl. den Ergebnissen.

EDIT: Version 2.8.2 mit überarbeiteter Commandref angehängt

Grüße
Heiko

Hi Heiko,


könntest du auch noch einbauen, dass DbLog_splitFn nicht nur in $modules{ $defs{$name}{TYPE} }{DbLog_splitFn} gesucht wird, sondern auch in $defs{$name}{'.DbLog_splitFn'}?
$defs{$name}{'.DbLog_splitFn'} sollte dabei dann Vorrang haben.

Damit ließe sich dann das ganze auch pro Device-Instanz nochmals überschreiben. Wir könnten das beispielsweise beim 98_powerMap Modul brauchen.

Vielleicht auch nachgelagert der Vollständigkeit halber noch auf ein vorhandenes userattr "DbLog_splitFn" prüfen und verwenden, sofern die darin benannte Funktion existiert?



Gruß
Julian

Vielleicht auch für die Zukunft:

Könnte man bei einem
get myDbLog - all 2017-01-05 2017-01-06 KS300:temperature
auch die Daten des caches mit zurück geben? Dann könnte ich eine relativ lange
Cachezeit (ca. 5 Minuten) nutzen, um die SD-Karte des RPI so weit als möglich zu entlasten
(und die Plots würden trotzdem vollständig gezeichnet).

Hi Julian und Joe,

ja sehe ich mal mit vor. Ich habe mich erstmal auf das Logging als Solches konzentriert. Aber ist eine super Idee ...

@Joe, sowas ließe sich bestimmt machen. Habe mir die Get-Funktion von DbLog bisher noch nciht so genau angeschaut (stand bisher nicht im Fokus meiner Bemühungen), aber das wäre sicherlich auch eine ganz tolle Sache.

Grüße
Heiko

Danke scheint zu laufen
CacheUsage 86

Bei mir will die 2.8 nicht cache auf 800 und nichts in die Datenbank geschrieben.
Bin wieder zurück auf 2.5

Hallo Heiko,

hab die aktuelle Version mal angetestet,

wenn ich Attribut "asyncMode=1" einstelle geht die Verbindung zur SQLite-DB verloren (entspricht der eingestellten Zeit vom Attribut syncInterval).

state geht dann auf -

Zitatstate old BlockingCall is running - resync at NextSync     2017-01-05 22:40:13

vg Jens

Hallo zusammen,

das sind etwas zu wenig Infos. Ihr müßtet mal verbose 4 oder 5 einstellen damit ein paar Logs kommen.

Zitatstate old BlockingCall is running - resync at NextSync

bedeutet dass ein Synclauf noch nicht fertig ist wenn der ein neuer loslaufen soll. Erstmal kein Fehler wenn es sich nicht ständig wiederholt.

@stromer-12, zurück auf 2.5 mußt du nicht .... stell einfach wieder auf asyncMode=0.
Auch hier brauchen wir mal ein paar Infos aus dem log.

Grüße
Heiko

Hier ist zunächst kein Fehler ... nun stell mal bitte verbose 5 ein.
Du müßtest nach Ablauf von SyncInterval einen Eintrag finden der ungefähr so aussieht:


2017.01.05 23:19:30.936 5: DbLog LogDB -> ################################################################
2017.01.05 23:19:30.937 5: DbLog LogDB -> ###              New database processing cycle                                                                             ###
2017.01.05 23:19:30.937 5: DbLog LogDB -> ################################################################
2017.01.05 23:19:30.937 5: DbLog LogDB -> MemCache contains 17 entries to process
2017.01.05 23:19:30.937 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:18:48|SMA_Energymeter|SMAEM|Bezug_WirkP_Zaehler_Diff: 0.0144|Bezug_WirkP_Zaehler_Diff|0.0144|
2017.01.05 23:19:30.937 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:18:48|SMA_Energymeter|SMAEM|Bezug_WirkP_Kosten_Diff: 0.0031|Bezug_WirkP_Kosten_Diff|0.0031|
2017.01.05 23:19:30.937 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:18:48|SMA_Energymeter|SMAEM|Einspeisung_WirkP_Zaehler_Diff: 0|Einspeisung_WirkP_Zaehler_Diff|0|
2017.01.05 23:19:30.937 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:18:48|SMA_Energymeter|SMAEM|Einspeisung_WirkP_Verguet_Diff: 0.0000|Einspeisung_WirkP_Verguet_Diff|0.0000|
2017.01.05 23:19:30.937 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:18:48|SMA_Energymeter|SMAEM|-866.1|state|-866.1|
2017.01.05 23:19:30.938 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:18:48|SMA_Energymeter|SMAEM|Saldo_Wirkleistung: -866.1|Saldo_Wirkleistung|-866.1|
2017.01.05 23:19:30.938 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:18:48|SMA_Energymeter|SMAEM|Bezug_Wirkleistung: 866.1|Bezug_Wirkleistung|866.1|
2017.01.05 23:19:30.938 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:18:48|SMA_Energymeter|SMAEM|Bezug_Wirkleistung_Zaehler: 1308.6693|Bezug_Wirkleistung_Zaehler|1308.6693|
2017.01.05 23:19:30.938 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:18:48|SMA_Energymeter|SMAEM|Einspeisung_Wirkleistung: 0.0|Einspeisung_Wirkleistung|0.0|
2017.01.05 23:19:30.938 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:18:48|SMA_Energymeter|SMAEM|Einspeisung_Wirkleistung_Zaehler: 1572.8506|Einspeisung_Wirkleistung_Zaehler|1572.8506|
2017.01.05 23:19:30.938 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:18:49|MySTP_5000|SMAINVERTER|done|state|done|
2017.01.05 23:19:30.938 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:18:49|Dum.Energy|DUMMY|TotalConsumption: 866.1|TotalConsumption|866.1|
2017.01.05 23:19:30.938 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:19:17|sysmon|SYSMON|ram: Total: 876.27 MB, Used: 577.29 MB, 65.88 %, Free: 298.97 MB|ram|Total: 876.27 MB, Used: 577.29 MB, 65.88 %, Free: 298.97 MB|
2017.01.05 23:19:30.938 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:19:17|sysmon|SYSMON|stat_cpu_percent: 1.36 0.00 0.49 97.87 0.14 0.00 0.14|stat_cpu_percent|1.36 0.00 0.49 97.87 0.14 0.00 0.14|
2017.01.05 23:19:30.938 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:19:17|sysmon|SYSMON|eth0_diff: RX: 0.33 MB, TX: 0.08 MB, Total: 0.41 MB|eth0_diff|RX: 0.33 MB, TX: 0.08 MB, Total: 0.41 MB|
2017.01.05 23:19:30.938 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:19:17|sysmon|SYSMON|swap: Total: 1293.00 MB, Used: 39.18 MB,  3.03 %, Free: 1253.82 MB|swap|Total: 1293.00 MB, Used: 39.18 MB,  3.03 %, Free: 1253.82 MB|
2017.01.05 23:19:30.939 5: DbLog LogDB -> MemCache contains: 2017-01-05 23:19:17|sysmon|SYSMON|loadavg: 0.02 0.10 0.12|loadavg|0.02 0.10 0.12|
2017.01.05 23:19:30.948 5: DbLog LogDB -> DbLog_PushAsync called with timeout: 60
2017.01.05 23:19:30.953 5: DbLog LogDB -> Start DbLog_PushAsync
2017.01.05 23:19:30.957 5: DbLog LogDB -> processing event Timestamp: 2017-01-05 23:18:48, Device: SMA_Energymeter, Type: SMAEM, Event: Bezug_WirkP_Zaehler_Diff: 0.0144, Reading: Bezug_WirkP_Zaehler_Diff, Value: 0.0144, Unit:
.....


Schau mal wie es bei dir aussieht.

Ich glaube noch einen Fehler gefunden zu haben der bei mir nicht aufgefallen ist.

Versuche mal die V2.8.1. Mach bitte auf jeden Fall ein FHEM Restart.

Grüße
Heiko

Heiko,

ja das war es funktioniert. SUPER

Sehr schön  :)

Gute Nacht !

Moin,

Gestern waren folgede Fehler:
2017.01.05 22:16:16.803 2: DbLog myDbLog -> Error: DBD::mysql::db begin_work failed: Turning off AutoCommit failed at ./FHEM/93_DbLog.pm line 920.
2017.01.05 22:16:16.806 1: PERL WARNING: rollback ineffective with AutoCommit enabled at ./FHEM/93_DbLog.pm line 991.

und einmalig nach dem ersten Restart:
Undefined subroutine &main::tv_interval called at ./FHEM/93_DbLog.pm line 1257.

und selbiger dauernder state wie bei newbie.

Mit der 2.8.1 läuft es jetzt.

Moin stromer-12,

super dass es nun auch bei dir klappt. Hatte vergessen ein Perl-Modul zu laden was bei mir bereits mit DbRep verwendet wird. Deswegen
hatte ich bei mir auch keine Sorgen deswegen.

Grüße
Heiko

Wenn ich die Version 2.8.1. downloade, hört bei mir das Modul mitten in der Doku  in Zeile 3257 auf.
Kannst du mal bitte nachsehen?

Hi Tobias,

bin grad bei der Doku am überarbeiten. Habe auch festgestellt dass mir der Editor, warum auch immer, in der 2.8.1 einen Streich gespielt hat.
Stelle die Version mit überarbeiteter Doku in Kürze hier rein.

Grüße
Heiko

Hi Tobias, @all,

anbei die Version 2.8.2 in der die Commandref überarbeitet und mit der Beschreibung der neuen Attribute ergänzt ist.
Ich habe sie auch mit commandref_join.pl gecheckt -> no issues.

Grüße
Heiko

hab ich jetzt am laufen... WOW, nun sehe ich mal was so alles in 30sek bei mir aufläuft... immer zwischen 100 und 130 Datensätze...

nach den vielen Rückmeldungen checke ich es nun ein
Edit: laufen denn die GET abfragen für die Plots auch asyncron?
Edit2: nimm mal bitte für eine Weiterentwicklung die aus dem Repo, ich habe die Item Summary´s noch eingefügt

Hi Tobias,

Zitatlaufen denn die GET abfragen für die Plots auch asyncron?

Nein, bis jetzt habe ich "nur" die eigentliche Log-Funktion, also DbLog_Log und was dazu drumherum nötig war aufgebohrt.
Alle anderen Funktionen wie GET oder auch Reducelog usw. sind nicht berührt und laufen wie bisher.
Der asynchrone Modus verwendet auch ein eigenes Datenbankhandle was undabhängig ist vom "normalen" $dbh.

Das wäre also noch eine mögliche Weiterentwicklung ...

Zitatnimm mal bitte für eine Weiterentwicklung die aus dem Repo, ich habe die Item Summary´s noch eingefügt

ok, mach ich.

Grüße
Heiko

Zitatlaufen denn die GET abfragen für die Plots auch asyncron?

Wenn plotfork gesetzt ist, dann ja. Bitte lieber plotfork unterstuetzen, und nicht "asynchrones get" implementieren, da ohne plotfork das aufwendigere SVG-Erstellen synchron bleibt.

Hi rudi,
abe greift denn plotfork auch unabhängig der SVG Erstellung? Also zb. wenn TabletUI Daten für den eigenen Chart abzieht?

Vielleicht nochmal zum gegenseitigen Abgleich was ich unter dem asynchronen Modus für die Get-Funktion verstanden habe.
Es würde für mich bedeuten, dass beim GET auch Daten aus dem Cache mit berücksichtigt werden (wenn async Mode an) und sich noch nicht in der DB befinden. Das würde dem Hinweis/Wunsch von Joe entsprechen.

War es das was du meintest Tobias /Rudi oder ein anderer Gedanke ?

ok, das ist ev. auch wichtig, meinte ich aber nicht. Ich meinte da NonBlocking Data-Get von DBLog. Holt man zb. ein JahresPlot raus, kann FHEM schonmal für mehrere Sekunden hängen bleiben... Und mit Plot meine ich ein Plot in TabletUI, nicht zwingend ein BuildIn SVG in FHEM pgm2

ah ... ok.  Das ist genau die Vorgehensweise mit der ich im DbRep die Analysen der DB-Inhalte fahre. Das läuft dort genauso wie von dir gemeint.

EDIT: vielleicht kann man in der  Get-Funktion eine Fallentscheidung einbauen um dieses Problem zu lösen ? Ich habe mich wie gesagt mit der Get-Funktion noch garnicht im Detail beschäftigt. Wenn du/ihr eine Idee habt ....

ZitatAlso zb. wenn TabletUI Daten für den eigenen Chart abzieht?

Das kenne ich nicht. Kannst du mich bitte aufklaeren, oder zeigen, wo ich was nachlesen kann?

Anbei einj Auszug aus meinem Verbose5 Log.
Diese Fehlermeldung verstehe ich, stimmt die Annahme dass dieser eine Eintrag dann schlicht NICHT in der DB eingefügt wurde, die anderen aus dem Cache jedoch schon?
So wäüre es ja korrekt! (Oder scheitert dann der komplette insert aller gecachten Daten?)
DbLog myDbLogSQL DBD::mysql::st execute_array failed: Duplicate entry 'myDbLogSQL-CacheUsage-2017-01-06 14:57:41' for key 'PRIMARY' [err was 1062 now 2000000000]


Aber häufig kommt eben auch diese Fehlermeldung, die ich nicht wirklich verstehe:
DbLog myDbLogSQL DBD::mysql::st execute_array failed: executing 7 generated 1 errors at ./FHEM/93_DbLog.pm line 1183.

@Heiko: Hast Du eine Idee, wie ich das genauer untersuchen kann?

Danke für die tolle Erweiterung!!!


DbLog myDbLogSQL NextSync: 2017-01-06 14:57:18
DbLog myDbLogSQL connected
DbLog myDbLogSQL CacheUsage: 2
DbLog myDbLogSQL connected
DbLog myDbLogSQL CacheUsage: 2
DbLog myDbLogSQL CacheUsage: 4
DbLog myDbLogSQL CacheUsage: 5
DbLog myDbLogSQL CacheUsage: 5
DbLog myDbLogSQL CacheUsage: 6
DbLog myDbLogSQL CacheUsage: 6
DbLog myDbLogSQL CacheUsage: 7
DbLog myDbLogSQL CacheUsage: 0
DbLog myDbLogSQL NextSync: 2017-01-06 14:57:28
DbLog myDbLogSQL connected
DbLog myDbLogSQL CacheUsage: 2
DbLog myDbLogSQL DBD::mysql::st execute_array failed: executing 7 generated 1 errors at ./FHEM/93_DbLog.pm line 1183.

DbLog myDbLogSQL CacheUsage: 3
DbLog myDbLogSQL CacheUsage: 4
DbLog myDbLogSQL CacheUsage: 5
DbLog myDbLogSQL CacheUsage: 6
DbLog myDbLogSQL CacheUsage: 7
DbLog myDbLogSQL CacheUsage: 9
DbLog myDbLogSQL CacheUsage: 10
DbLog myDbLogSQL CacheUsage: 13
DbLog myDbLogSQL CacheUsage: 14
DbLog myDbLogSQL CacheUsage: 15
DbLog myDbLogSQL CacheUsage: 16
DbLog myDbLogSQL CacheUsage: 19
DbLog myDbLogSQL CacheUsage: 20
DbLog myDbLogSQL CacheUsage: 21
DbLog myDbLogSQL CacheUsage: 22
DbLog myDbLogSQL CacheUsage: 23
DbLog myDbLogSQL CacheUsage: 24
DbLog myDbLogSQL CacheUsage: 25
DbLog myDbLogSQL CacheUsage: 26
DbLog myDbLogSQL CacheUsage: 27
DbLog myDbLogSQL CacheUsage: 28
DbLog myDbLogSQL CacheUsage: 29
DbLog myDbLogSQL CacheUsage: 30
DbLog myDbLogSQL CacheUsage: 31
DbLog myDbLogSQL CacheUsage: 32
DbLog myDbLogSQL CacheUsage: 32
DbLog myDbLogSQL CacheUsage: 33
DbLog myDbLogSQL CacheUsage: 35
DbLog myDbLogSQL CacheUsage: 36
DbLog myDbLogSQL CacheUsage: 0
DbLog myDbLogSQL NextSync: 2017-01-06 14:57:38
DbLog myDbLogSQL connected
DbLog myDbLogSQL CacheUsage: 2
DbLog myDbLogSQL DBD::mysql::st execute_array failed: executing 36 generated 11 errors at ./FHEM/93_DbLog.pm line 1183.

DbLog myDbLogSQL CacheUsage: 3
DbLog myDbLogSQL CacheUsage: 3
DbLog myDbLogSQL CacheUsage: 4
DbLog myDbLogSQL CacheUsage: 9
DbLog myDbLogSQL CacheUsage: 10
DbLog myDbLogSQL CacheUsage: 12
DbLog myDbLogSQL CacheUsage: 13
DbLog myDbLogSQL CacheUsage: 15
DbLog myDbLogSQL CacheUsage: 16
DbLog myDbLogSQL CacheUsage: 0
DbLog myDbLogSQL NextSync: 2017-01-06 14:57:51
DbLog myDbLogSQL connected
DbLog myDbLogSQL CacheUsage: 2
DbLog myDbLogSQL DBD::mysql::st execute_array failed: Duplicate entry 'myDbLogSQL-CacheUsage-2017-01-06 14:57:41' for key 'PRIMARY' [err was 1062 now 2000000000]
executing 16 generated 1 errors at ./FHEM/93_DbLog.pm line 1183.

DbLog myDbLogSQL CacheUsage: 2
DbLog myDbLogSQL CacheUsage: 2



Nachtrag: Ich habe bewußt einen PK in die Datenbank eingefügt, um doppelte Datensätze
zu vermeiden und Module, die diese erzeugen besser aufspüren zu können
PRIMARY KEY (`DEVICE`, `READING`, `TIMESTAMP`),

@rudi: https://github.com/knowthelist/fhem-tablet-ui

@DS_Starter, hab ich jetzt nicht verstanden, in DBRep machst du ein Non-Blocking? Rufst du da Funktionen von DBLog auf? Wenn ja, dann bleibt FHEM nicht hängen?
sorry für die Fragen, blick das nicht ganz...

Zitatin DBRep machst du ein Non-Blocking? Rufst du da Funktionen von DBLog auf?

Ich rufe die DB-Inhalte non-Blocking aus der DB ab. Aber ich verwende dafür eigene Funktionen im DbRep und greife dazu nicht ins DbLog.
Aber es ist die Technologie die du meintest.  ;)

Hallo Joe,

ZitatDbLog myDbLogSQL DBD::mysql::st execute_array failed: executing 7 generated 1 errors at ./FHEM/93_DbLog.pm line 1183.

Die Meldung wird direkt von dem DBI-interface  bei dir generiert.

Mit verbose 5 müßtest du im Erfolgsfall im Log so etwas finden:

DbLog $name -> $rows of $ceti events successfully inserted into table history

oder aber

"DbLog $name -> Failed to insert into history: ......

Findest du dies ?

Grüße
Heiko

Hallo Heiko:

ich bekomme folgendes: daraus geht für mich nicht ganz hervor, ob nun alle datensätze aus dem cache eingefügt wurden und was nicht.
Aber folgender Vorschlag: Könnten wir "insert into" ändern in "insert ignore into"?
Dann würden die anderen (nicht doppelten) Datensätze immer eingefügt werden...

2017.01.06 14:57:28 5: DbLog myDbLogSQL -> DbLog_PushAsync finished
2017.01.06 14:57:28 5: DbLog myDbLogSQL -> Start DbLog_PushAsyncDone
2017.01.06 14:57:28 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:28 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:57:28 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:28 4: DbLog myDbLogSQL -> amount of events received: 1 for device: myDbLogSQL
2017.01.06 14:57:28 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: DBD::mysql::st execute_array failed: executing 36 generated 11 errors at ./FHEM/93_DbLog.pm line 1183.

2017.01.06 14:57:28 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:28, Device: myDbLogSQL, Type: DBLOG, Event: DBD::mysql::st execute_array failed: executing 36 generated 11 errors at ./FHEM/93_DbLog.pm line 1183.
, Reading: DBD::mysql::st execute_array failed, Value: executing 36 generated 11 errors at ./FHEM/93_DbLog.pm line 1183.
, Unit:
2017.01.06 14:57:28 5: DbLog myDbLogSQL -> DbLog_PushAsyncDone finished
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> amount of events received: 1 for device: HMLAN1
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> check Device: HMLAN1 , Event: loadLvl: low
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> amount of events received: 1 for device: myDbLogSQL
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: CacheUsage: 3
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:33, Device: myDbLogSQL, Type: DBLOG, Event: CacheUsage: 3, Reading: CacheUsage, Value: 3, Unit:
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> amount of events received: 5 for device: CO20
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> check Device: CO20 , Event: voc: 1028
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:35, Device: CO20, Type: CO20, Event: voc: 1028, Reading: voc, Value: 1028, Unit:
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> check Device: CO20 , Event: debug: 776
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:35, Device: CO20, Type: CO20, Event: debug: 776, Reading: debug, Value: 776, Unit:
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> check Device: CO20 , Event: pwm: 386
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:35, Device: CO20, Type: CO20, Event: pwm: 386, Reading: pwm, Value: 386, Unit:
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> check Device: CO20 , Event: r_h: 153.29
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:35, Device: CO20, Type: CO20, Event: r_h: 153.29, Reading: r_h, Value: 153.29, Unit:
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> check Device: CO20 , Event: r_s: 192516
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:35, Device: CO20, Type: CO20, Event: r_s: 192516, Reading: r_s, Value: 192516, Unit:

Noch ein Gedanke:
Sollte nicht beim löschen des attributs "assync" ebenfalls der cach in die db geschrieben werden?
bei mir blieben dabei Datensätze zurück im Memcache.

sG Joe

Hallo Joe,

Zitatdaraus geht für mich nicht ganz hervor, ob nun alle datensätze aus dem cache eingefügt wurden und was nicht.

Für mich auch nicht.

Der Logauszug ist auch nicht der richtige bzw. ausschlaggbebende. Schau mal bitte in deinem Logfile nach der verbose 5 Passage die so aussieht:


2017.01.06 16:54:39.560 5: DbLog LogDB -> ################################################################
2017.01.06 16:54:39.561 5: DbLog LogDB -> ###              New database processing cycle               ###
2017.01.06 16:54:39.561 5: DbLog LogDB -> ################################################################
2017.01.06 16:54:39.561 5: DbLog LogDB -> MemCache contains 22 entries to process
2017.01.06 16:54:39.561 5: DbLog LogDB -> MemCache contains: 2017-01-06 16:53:32|sysmon|SYSMON|loadavg: 0.07 0.05 0.05|loadavg|0.07 0.05 0.05|
2017.01.06 16:54:39.561 5: DbLog LogDB -> MemCache contains: 2017-01-06 16:53:32|sysmon|SYSMON|eth0_diff: RX: 0.34 MB, TX: 0.07 MB, Total: 0.41 MB|eth0_diff|RX: 0.34 MB, TX: 0.07 MB, Total: 0.41 MB|
2017.01.06 16:54:39.561 5: DbLog LogDB -> MemCache contains: 2017-01-06 16:53:32|sysmon|SYSMON|stat_cpu_percent: 1.51 0.00 0.61 97.11 0.57 0.00 0.20|stat_cpu_percent|1.51 0.00 0.61 97.11 0.57 0.00 0.20|
.........
.........
2017.01.06 16:54:39.574 5: DbLog LogDB -> DbLog_PushAsync called with timeout: 60
2017.01.06 16:54:39.579 5: DbLog LogDB -> Start DbLog_PushAsync
2017.01.06 16:54:39.586 5: DbLog LogDB -> processing event Timestamp: 2017-01-06 16:53:32, Device: sysmon, Type: SYSMON, Event: loadavg: 0.07 0.05 0.05, Reading: loadavg, Value: 0.07 0.05 0.05, Unit:
2017.01.06 16:54:39.586 5: DbLog LogDB -> processing event Timestamp: 2017-01-06 16:53:32, Device: sysmon, Type: SYSMON, Event: eth0_diff: RX: 0.34 MB, TX: 0.07 MB, Total: 0.41 MB, Reading: eth0_diff, Value: RX: 0.34 MB, TX: 0.07 MB, Total: 0.41 MB, Unit:
2017.01.06 16:54:39.586 5: DbLog LogDB -> processing event Timestamp: 2017-01-06 16:53:32, Device: sysmon, Type: SYSMON, Event: stat_cpu_percent: 1.51 0.00 0.61 97.11 0.57 0.00 0.20, Reading: stat_cpu_percent, Value: 1.51 0.00 0.61 97.11 0.57 0.00 0.20, Unit:
2017.01.06 16:54:39.586 5: DbLog LogDB -> processing event Timestamp: 2017-01-06 16:53:32, Device: sysmon, Type: SYSMON, Event: ram: Total: 876.27 MB, Used: 591.86 MB, 67.54 %, Free: 284.40 MB, Reading: ram, Value: Total: 876.27 MB, Used: 591.86 MB, 67.54 %, Free: 284.40 MB, Unit:
2017.01.06 16:54:39.586 5: DbLog LogDB -> processing event Timestamp: 2017-01-06 16:53:32, Device: sysmon, Type: SYSMON, Event: swap: Total: 1293.00 MB, Used: 46.71 MB,  3.61 %, Free: 1246.28 MB, Reading: swap, Value: Total: 1293.00 MB, Used: 46.71 MB,  3.61 %, Free: 1246.28 MB,


Also der Beginn des asynchronen DB-Inserts wird mit dem Header "New database processing cycle" im Log gekennzeichnet. Deine "start of new Logcycle" - Einträge rühren von der Notify-Funktion her, sind auch verbose 4. Die relevanten Einträge müßten also weiter unten kommen. Wenn dir die Ausgabe durch die Logcycle-Einträge mit verbose 4 dein Log zu unübersichtlich macht, kannst du mit dem attr "verbose4Devs" nur auf ein Device beschränken. Dann funken dir die "start of new Logcycle" - Einträge nicht mehr dazwischen.

ZitatKönnten wir "insert into" ändern in "insert ignore into"?

Probieren wir im nächsten Entwicklungsschritt mit aus.

ZitatSollte nicht beim löschen des attributs "assync" ebenfalls der cach in die db geschrieben werden?

Ja, klappt bei mir auch einwandfrei. Das schauen wir uns noch genauer an wenn dein anderes Problem genügend analysiert ist.

Grüße
Heiko

Hallo Heiko,

sorry, ich denke, das ist jetzt das korrekte Log:

2017.01.06 14:56:50 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> amount of events received: 9 for device: temp.wz.innen
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: battery: low
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: humidity: 34
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: T: 22.4 H: 34
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: temperature: 22.4
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: batteryCopy: ok
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: dew: 5.78
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: dd: 921.0
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: af: 6.8
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: empfehlung: Lüften nicht notwendig
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> amount of events received: 1 for device: myDbLogSQL
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: CacheUsage: 3
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:56:50, Device: myDbLogSQL, Type: DBLOG, Event: CacheUsage: 3, Reading: CacheUsage, Value: 3, Unit:
2017.01.06 14:56:50 3:  Batteriewarnung %
2017.01.06 14:56:50 3:  Batteriewarnung %
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> ###              New database processing cycle               ###
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains 4 entries to process
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:48|myDbLogSQL|DBLOG|CacheUsage: 0|CacheUsage|0|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:48|myDbLogSQL|DBLOG|NextSync: 2017-01-06 14:56:58|NextSync|2017-01-06 14:56:58|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:48|myDbLogSQL|DBLOG|DBD::mysql::st execute_array failed: executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
|DBD::mysql::st execute_array failed|executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:50|myDbLogSQL|DBLOG|CacheUsage: 3|CacheUsage|3|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> DbLog_PushAsync called with timeout: 60
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> Start DbLog_PushAsync
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-06 14:56:48, Device: myDbLogSQL, Type: DBLOG, Event: CacheUsage: 0, Reading: CacheUsage, Value: 0, Unit:
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-06 14:56:48, Device: myDbLogSQL, Type: DBLOG, Event: NextSync: 2017-01-06 14:56:58, Reading: NextSync, Value: 2017-01-06 14:56:58, Unit:
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-06 14:56:48, Device: myDbLogSQL, Type: DBLOG, Event: DBD::mysql::st execute_array failed: executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
, Reading: DBD::mysql::st execute_array failed, Value: executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
, Unit:
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-06 14:56:50, Device: myDbLogSQL, Type: DBLOG, Event: CacheUsage: 3, Reading: CacheUsage, Value: 3, Unit:
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> amount of events received: 3 for device: myDbLogSQL
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: CacheUsage: 0
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:56:58, Device: myDbLogSQL, Type: DBLOG, Event: CacheUsage: 0, Reading: CacheUsage, Value: 0, Unit:
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: NextSync: 2017-01-06 14:57:08
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:56:58, Device: myDbLogSQL, Type: DBLOG, Event: NextSync: 2017-01-06 14:57:08, Reading: NextSync, Value: 2017-01-06 14:57:08, Unit:
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: connected
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> 4 of 4 events successfully inserted into table history
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> DbLog_PushAsync finished
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> Start DbLog_PushAsyncDone
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> amount of events received: 1 for device: myDbLogSQL
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: connected
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> DbLog_PushAsyncDone finished


Hi Joe,

genau das ist es. Hier siehst du auch genau die Ergebnisse.
Der Hintergrundprozess startet mit


2017.01.06 14:56:58 5: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> ###              New database processing cycle               ###
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains 4 entries to process


Es sind 4 Einträge in die DB zu bringen. Danach wird aufgezählt welche das sind:


2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:48|myDbLogSQL|DBLOG|CacheUsage: 0|CacheUsage|0|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:48|myDbLogSQL|DBLOG|NextSync: 2017-01-06 14:56:58|NextSync|2017-01-06 14:56:58|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:48|myDbLogSQL|DBLOG|
DBD::mysql::st execute_array failed: executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
|DBD::mysql::st execute_array failed|executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:50|myDbLogSQL|DBLOG|CacheUsage: 3|CacheUsage|3|


In dem Fall ist der Eintrag "2017-01-06 14:56:48|myDbLogSQL|DBLOG|DBD::mysql::st execute_array failed: executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
|DBD::mysql::st execute_array failed|executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
|"  allerdings ein Event der in die DB geschrieben werden soll !!  und kein Fehler an sich.

Wahrscheinlich loggst du bei dir jedes Device mit der Konfiguration ".*:.*". Wenn das so ist/sein soll würde ich aber an deiner Stelle das Device "myDbLogSQL" über das Attribut "excludeDevs" ausschließen.

Weiter unten siehst du dass alle 4 Events in die DB geschrieben wurden.


2017.01.06 14:56:58 5: DbLog myDbLogSQL -> 4 of 4 events successfully inserted into table history
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> DbLog_PushAsync finished
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> Start DbLog_PushAsyncDone


Wenn ein Insert nicht gemacht werden konnte würde ich im Log ausschreiben "DbLog $name ->Failed to insert into history:  <Device>,  <Event>".
Also in dem Beispiel ist alles gut.

Wenn du tatsächlich mal auf den Fehler "DBD::mysql::st execute_array failed:" läufst müßte man das genauso analysieren ob nur der eine Event nicht in die DB kommt oder der Block. Vielleicht kannst du es provozieren. Ganz gemein wäre natürlich wenn dein DBI-Modul an der Stelle einfach die Arbeit einstellt. Dann gäbe es nichts auszuwerten. Aber das muß man sehen.

Kommst du damit klar ?

Grüße
Heiko

Hallo Heiko,

vielen Dank, das hätte ich da nicht alles rauslesen können....

Wenn ich mit myDbLogSQL mit "excludeDevs" ausnehme,  bekomme ich die Fehlermeldung nicht.
Dennoch wunderts mich... woher diese Fehlermeldung kommt. Bisher hatte ich beim Device myDbLogSQL einfach mit "DbLogExclude" einzelne Readings ausgenommen.
manchmal steht da
executing 9 generated 2 errors
ein anderes mal
executing 21 generated 3 errors

Also scheint die Meldung zumindest nicht statisch zu sein...

Ich lasse es nun weiter mit async laufen und werde morgen sehen, was alles in die Logdatei geschrieben wurde.

Noch eine Rückfrage: Ist es ganz korrekt, dass hier die Meldung "myDbLogSQL excluded from database ..." 2x kommt? Wird hier der Ausschluss 2x berechnet?
2017.01.06 18:03:30 4: DbLog myDbLogSQL -> Device: myDbLogSQL excluded from database logging due to attribute "excludeDevs" restrictions
2017.01.06 18:03:30 5: DbLog myDbLogSQL -> Start DbLog_PushAsyncDone
2017.01.06 18:03:30 4: DbLog myDbLogSQL -> Device: myDbLogSQL excluded from database logging due to attribute "excludeDevs" restrictions
2017.01.06 18:03:30 5: DbLog myDbLogSQL -> DbLog_PushAsyncDone finished


Hi Joe,

ZitatDennoch wunderts mich... woher diese Fehlermeldung kommt.

Mit den Ausschriften "executing 9 generated 2 errors" oder "executing 21 generated 3 errors" kann ich ehrlich gesagt auch nichts anfangen. Sie sind mir auch bis jetzt nicht begegnet. Vielleicht mal die Suchfunktion im Browser bemühen. Möglicherweise sind diese Meldungen von der DB-Version abhängig.
Aber mit ziemlicher Sicherheit ist es eine Meldung deines Perl DBI-Interface weil ich in Zeile  1183 den execute_array-Aufruf starte. Die Auswertungen und Ausschriften die ich über das Modul ausgebe, kommen aber erst später.

ZitatNoch eine Rückfrage: Ist es ganz korrekt, dass hier die Meldung "myDbLogSQL excluded from database ..." 2x kommt? Wird hier der Ausschluss 2x berechnet?

Die Meldung ist soweit ok. Aber sie bezieht sich auf zwei unterschiedliche Events die über die Notify-Funktion hereinkommen und bewertet werden, ist also nicht doppelt berechnet/ausgegeben. Die Meldung soll den Nutzer lediglich daran erinnern dass er dieses Device vom Logging ausgeschlossen hat wenn er Analysen mit verbose4/5 tätigt.

Schauen wir morgen mal weiter ...

Schönen Abend !

Grüße,
Heiko

Guten Abend!

Möchte ich ein SVG von einem Device erstellen, das nachdem ich die DbLog eingespielt habe erstellt wurde, so finde ich es nicht in der Auswahlliste/Dropdown.
Schreibe ich die Devices händisch in die *.plot Datei werden die SVG Plots erstellt.

Ich verwende die Version 2.8.2 unter PostgreSQL.

Tante EDIT sagt:
Ich kann keinen Eintrag für die neuen Devices in der current Tabelle entdecken können.

Hallo Pyromane,



Du mußt das Attribut DbLogType explizit auf "Current" bzw. "History/Current" setzen um die Current-Tabelle zu benutzen.

VG

Zitat von: DS_Starter am 06 Januar 2017, 22:43:48Du mußt das Attribut DbLogType explizit auf "Current" bzw. "History/Current" setzen um die Current-Tabelle zu benutzen.

Kaum Umgestellt und schon funktioniert wieder alles :)
Herzlichen Dank für die schnelle Hilfe!

Große Anerkennung für die Arbeit am DBLog! Hier flutschts plötzlich in ungeahnten Geschwindigkeiten... Vielen vielen Dank euch!
Was ich noch nicht ganz sicher rausgelesen habe: Ist das Ding hier schon im normalen Update von Fhem mit drin?

Zitat von: rubbertail am 07 Januar 2017, 11:21:11Ist das Ding hier schon im normalen Update von Fhem mit drin?

Ja, gestern Mittag eingecheckt

Der Dank geht natürlich an DS_Starter :)

Astrein, flutscht  :D


Wie sieht denn jetzt die Best-Practice/Referenz-Tabellenstruktur aus? In ./contrib/dblog/ wurde bisher ja nichts aktualisiert.
War nicht die Rede davon, dass für die Performance und Zuverlässigkeit z.B. auch noch ein PRIMARY KEY gesetzt werden sollte? Ist der Search_Idx so ausreichend?


Ich hatte beispielsweise TIMESTAMP mandatory definiert.

Bei mir funktioniert das Logging in die Datenbank seit meinem update heute vormittag gar nicht mehr.

Kann es sein, dass bei der Auswertung der regexp irgendwas geändert wurde?


define dbLog DbLog ./sqldb/dblog.conf (.*actuator.*|.*temp.*|owo.*)
attr dbLog DbLogType History


Die events von owo.* werden geloggt, alle anderen nicht.

Hallo betateilchen,

die DbLog_Log Funktion verwendet nun deviceEvents wie im Wiki https://wiki.fhem.de/wiki/DevelopmentModuleIntro#X_Notify beschrieben.
Es sollten alle Events von Devices durchkommen die im Internal NOTIFYDEV aufgelistet sind.
Schau mal ...

Grüße
Heiko

Die Antwort hilft mir nicht weiter.

Offenbar bekommt DbLog die events gemäß der bestehenden regexp Definition nicht mehr mit. Darauf habe ich als "Empfänger" (im Log) doch gar keinen Einfluß.

icxh hätte noch eine kleine Bitte ...

Kannst Du noch das Statformat unterstützen?

Wäre cool schon in der Übersicht den Status außer "Connected" to kennen - also zb. Beispiel: "Mode State Queue: CacheUsage"

ansonsten:

Super Arbeit - D a n k e

Zitat von: DS_Starter am 07 Januar 2017, 14:29:52
Es sollten alle Events von Devices durchkommen die im Internal NOTIFYDEV aufgelistet sind.
Schau mal ...

Da steht:

NOTIFYDEV .*actuator.*,.*temp.*,owo.*

weil ich von ALLEN Devices, die events loggen will, die actuator oder irgendein temp reading erzeugen.

Das NOTIFYDEV wird aus dem Regexp aus dem Define abgeleitet.
Was steht denn im Internal NOTIFYDEV bei dir ?  Sollte m.M. nach ".*actuator.*,.*temp.*,owo.*" sein, oder ?
Welche Events von DbLog empfangen und bewertet werden siehst du mit verbose 4 in der Form:


2017.01.07 14:47:50.270 4: DbLog LogDB -> ################################################################
2017.01.07 14:47:50.271 4: DbLog LogDB -> ###              start of new Logcycle                       ###
2017.01.07 14:47:50.271 4: DbLog LogDB -> ################################################################
2017.01.07 14:47:50.271 4: DbLog LogDB -> amount of events received: 5 for device: MySTP_5000
2017.01.07 14:47:50.271 4: DbLog LogDB -> check Device: MySTP_5000 , Event: modulstate: normal
2017.01.07 14:47:50.271 4: DbLog LogDB -> check Device: MySTP_5000 , Event: etotal: 12787.711
2017.01.07 14:47:50.272 4: DbLog LogDB -> added event to memcache - Timestamp: 2017-01-07 14:47:50, Device: MySTP_5000, Type: SMAINVERTER, Event: etotal: 12787.711, Reading: etotal, Value: 12787.711, Unit:
2017.01.07 14:47:50.272 4: DbLog LogDB -> check Device: MySTP_5000 , Event: etoday: 2.68


Der Eintrag " check Device:" erscheint wenn DbLog eine Event empfangen hat und bewertet ob es geloggt werden soll (DbExclude usw.). Im positiven Fall wird mit "added event to memcache" angezeigt dass der Event geloggt werden soll.
Vielleicht kommen wir damit weiter.

Zitat von: DS_Starter am 07 Januar 2017, 14:55:34
Das NOTIFYDEV wird aus dem Regexp aus dem Define abgeleitet.
Was steht denn im Internal NOTIFYDEV bei dir ?  Sollte m.M. nach ".*actuator.*,.*temp.*,owo.*" sein, oder ?

genau das steht drin, siehe meinen letzten Beitrag.

Zitat von: DS_Starter am 07 Januar 2017, 14:55:34
Welche Events von DbLog empfangen und bewertet werden siehst du mit verbose 4 in der Form:

es kommen selbst bei verbose=5 keine events zu actuator und temp bei DbLog an.

Liefert "list .*actuator.*,.*temp.*,owo.*" das zurueck, was du erwartest?

nö, warum sollte es?

Ihr könnt doch nicht allen Ernstes erwarten, dass seit Neuestem jedes Device einzeln in der Log-Definition aufgeführt sein muss?
Und dass man bei jedem neuen Temperatursensor oder Heizkörperregler die Log-Definitionen ändern muss?

Bei 5 devices mag das ja alles noch gehen, aber bei 300 ist das unzumutbar.

Hey - die bisherige Lösung war genial einfach zu handhaben. Warum musste man eine funktionierende Lösung wieder einmal kaputtmachen?

Also nun habe ich Rudis Hinweis aufgenommen und testweise mein Def so angepasst:


(.*5000.*|Rep.Show.DbSize|Sonnenstrom_Relative|Sonnenstrom|MyWetter|SMA_Energymeter|sysmon|Dum.Energy):.*


Es wird alles geloggt was 5000 enthält.
Außerdem klappt auch ein list mit allen Devices die 5000 enthalten wenn ich den String aus NOTIFYDEV benutze:


list .*5000.*,Rep.Show.DbSize,Sonnenstrom_Relative,Sonnenstrom,MyWetter,SMA_Energymeter,sysmon,Dum.Energy

Ausgegeben wird:


MySTP_5000
N.MySTP_5000.Set.Icon
N.MySTP_5000.getdata
N.STP_5000.getdata
STP_5000
SVG_LogDB_MySTP5000
Rep.Show.DbSize
Sonnenstrom_Relative
Sonnenstrom
MyWetter
SMA_Energymeter
sysmon
Dum.Energy


Hallo Wuppi68,

freut mich , danke !  :)
Sehe ich demnächst mit vor.

Grüße
Heiko

Zitat von: DS_Starter am 07 Januar 2017, 15:22:34
Es wird alles geloggt was 5000 enthält.

Du hast mein Problem noch nicht verstanden. Es geht nicht um devicename die 5000 enthalten, sondern den kompletten event.

Was ich mit meiner regexp erreichen will:

• es existieren die Geräte mit Namen wz_TC wz_RT bd_RT
• alle diese Homematic Geräte erzeugen verschiendene Temperatur-Readings (temperature, desired-temp, measured-temp)
• mit .*temp.* konnte ich bisher ALLE diese Readings von ALLEN Geräten auf einfachste Weise loggen.

Das funktioniert jetzt nicht mehr.

das sollte nach wie vor so wie bisher auch funktionieren mit der Definition:

.*:(.*actuator.*|.*temp.*|owo.*)

Zitat von: DS_Starter am 07 Januar 2017, 15:35:01
das sollte nach wie vor so wie bisher auch funktionieren mit der Definition:

Ja, das funktioniert natürlich.

Aber das ist defintiv nicht "wie bisher", weil ich nun auf sämtlichen fhem Installationen (und das sind nicht wenige) die Definitionen der Logfiles entsprechend anpassen muss.

NOTIFYDEV ist im Prinzip eine tolle Sache. Aber an manchen (zentralen) Stellen ist es einfach Kacke und hinderlich.

Mit "wie bisher" meinte ich natürlich dass in der DbLog-Commandref auf die Verwendung von ".*:.*", also "Device":"Event" hingewiesen wurde.
Und wurde auch so beibehalten.

ZitatNOTIFYDEV ist im Prinzip eine tolle Sache.

Sehe ich genauso und hoffe dass diese Ergänzung langfristig viele Vorteile bringt.

Grüße
Heiko

@DS_Starter: das problem ist das man ohne : in der regex nicht entscheiden kann ob devices oder readings gemeint sind. (und sogar mit : manchmal nicht). d.h. wenn es keinen : gibt kann man NOTIFYDEV nicht verwenden und muss auf .* umschalten und jedes event wieder einzeln gegen die regex prüfen.

gruss
  andre

Zitat von: justme1968 am 07 Januar 2017, 16:07:11
d.h. wenn es keinen : gibt kann man NOTIFYDEV nicht verwenden und muss auf .* umschalten und jedes event wieder einzeln gegen die regex prüfen.

Genau DAS wäre für mich ein Lösungsansatz, der 93_DbLog.pm bezüglich der regexp Auswertung weitestgehend abwärtskompatibel machen würde.

Denn ich bin mit Sicherheit nicht der einzige User, der mit "einfachen" regexp sein DbLog optimiert hat, zumal diese Variante in der Vergangenheit immer wieder empfohlen wurde, um device-unabhängig loggen zu können.

Hi Andre,

ja das ist wohl eine Crux. Kriegen wir sicher eingebaut.

Grüße
Heiko

Wenn Du an der Stelle nochmal schraubst, solltest Du bitte daran denken, dass es durchaus auch "gemischte" regexp gibt.
Wenn ich wieder zuhause bin, kann ich Dir die regexp von meinem fhem dort posten, dann siehst Du, wie "komplex" sowas aussehen kann.

Auf meinem fhem zuhause sieht die regexp z.B. so aus:

(.*:lumi.*|GW1_.*|.*:batVoltage.*|.*:measured-temp.*|.*:desired.*|.*:actuator.*|.*:valve.*|.*:Bb]attery:.*|.*:temperature.*|.*:humidity.*|.*:dewpoint.*|.*:pressure.*|Melder.*:.*|RM_.*:.*|sunDummy.*:.*|out_Regen.*:.*|.*_SenPwr.*|gds.*)

ZitatWenn ich wieder zuhause bin, kann ich Dir die regexp von meinem fhem dort posten, dann siehst Du, wie "komplex" sowas aussehen kann.

Ja mach das, vllt. können wir das ja gemeinsam optimieren.

auch so etwas kann man nicht mehr automatisch für NOTIFYDEV aufarbeiten.

wie wäre es mit einem attribut um zu beeinflussen ob NOTIFYDEV verwendet wird?

Um NOTIFYDEV zu setzen gibt es (seit 3 Jahren) eine Funktion notifyRegexpChanged.
Was ist NOTIFYDEF?

Zitat von: rudolfkoenig am 07 Januar 2017, 16:38:28
Was ist NOTIFYDEF?

Vermutlich eine majestätische Halluzination  8)

:)

nach Update habe ich ein kleines Problem.

FHEM2FHEM daten werden nicht in DB geschrieben

Daten die bisher in der datenbank gelogt wurden, werden es jetzt nicht mehr. Es handelt sich hierbei um daten die von einem anderen fhem server per FHEM2FHEM
übertragen werden. Mit "inform on" auf beiden Server werden sie angezeigt, aber nicht mehr in die datenbank geschrieben. Wie kriege ich das wieder hin?

Definition:

define con_conn FHEM2FHEM 192.168.20.161 LOG:(ws300\..*|hzTemp\..*|.*_pid|St.Vs..*|SDM630M.*)

Internals:
   DEF        192.168.20.161 LOG:(ws300\..*|hzTemp\..*|.*_pid|St.Vs..*|SDM630M.*)
   FD         77
   Host       192.168.20.161:7072
   NAME       con_conn
   NR         372
   PARTIAL   
   STATE      connected
   TYPE       FHEM2FHEM
   informType LOG
   regexp     (ws300\..*|hzTemp\..*|.*_pid|St.Vs..*|SDM630M.*)
   Helper:
     Dblog:
       State:
         Mydblog:
           TIME       1483801976.25551
           VALUE      CONNECTED
Attributes:
   room       Heizung



VG

Zitat von: My-FHEM am 07 Januar 2017, 17:03:06
nach Update habe ich ein kleines Problem.

FHEM2FHEM daten werden nicht in DB geschrieben

Das ist vermutlich genau das gleiche Problem.

Da werden noch einige mehr aufschlagen...

93_DbLog.pm sollte NOTIFYDEV erstmal pauschal auf .* setzen, bis man sich überlegt hat, ob man das Problem sinnvoll anders lösen kann.

Oder per Attribut vom User wählbar abschaltbar gestalten.

ZitatOder per Attribut vom User wählbar abschaltbar gestalten.

So werde ich das morgen früh einbauen ....

Grüße
Heiko

Auch mit .* werden keine FHEM2FHEM daten geloggt.

Wie kriege ich das wieder hin?


Internals:
   CONFIGURATION ./db.conf
   DBMODEL    MYSQL
   DEF        ./db.conf .*
   MODE       asynchronous
   NAME       myDbLog
   NOTIFYDEV  .*
   NR         4
   NTFY_ORDER 50-myDbLog
   PID        2994
   REGEXP     .*
   STATE      connected
   TYPE       DbLog
   VERSION    2.8.2
   dbconn     mysql:database=fhem;host=localhost;port=3306
   dbuser     fhemuser
   Helper:
   Helper:
     Dblog:
       Cacheusage:
         Mydblog:
           TIME       1483806780.105
           VALUE      21
       Dbd::mysql::st execute_array failed:
         Mydblog:
           TIME       1483803885.42194
           VALUE      executing 1278 generated 1 errors at ./FHEM/93_DbLog.pm line 1183.

       Nextsync:
         Mydblog:
           TIME       1483806779.21278
           VALUE      2017-01-07 17:33:29
       State:
         Mydblog:
           TIME       1483806779.64402
           VALUE      connected
   Readings:
     2017-01-07 17:33:00   CacheUsage      22
     2017-01-07 17:32:59   NextSync        2017-01-07 17:33:29
     2015-02-21 14:57:11   countCurrent    3053
     2015-02-21 14:57:11   countHistory    148316222
     2017-01-07 17:32:59   state           connected
     2017-01-07 00:05:00   userCommand     select
                                max(to_number(value,'999.999')) - min(to_number(value,'999.999')) as kw
                                from history
                                where device = 'PCA301_FeOben'
                                and reading = 'consumption'
                                and timestamp >= TO_TIMESTAMP('2017-01-06 00:00:00','YYYY-MM-DD HH24:MI:SS')
                                and timestamp <= TO_TIMESTAMP('2017-01-06 23:59:59','YYYY-MM-DD HH24:MI:SS')
   Cache:
     index      3256
     Memcache:
       3235       2017-01-07 17:32:59|myDbLog|DBLOG|CacheUsage: 0|CacheUsage|0|
       3236       2017-01-07 17:32:59|myDbLog|DBLOG|NextSync: 2017-01-07 17:33:29|NextSync|2017-01-07 17:33:29|
       3237       2017-01-07 17:32:59|myDbLog|DBLOG|connected|state|connected|
       3238       2017-01-07 17:32:59|EC3000_476A|EC3000|consumption: 1685.343|consumption|1685.343|
       3239       2017-01-07 17:32:59|EC3000_476A|EC3000|power: 16.1|power|16.1|
       3240       2017-01-07 17:32:59|EC3000_476A|EC3000|powerMax: 18.5|powerMax|18.5|
       3241       2017-01-07 17:32:59|EC3000_476A|EC3000|on|state|on|
       3242       2017-01-07 17:32:59|EC3000_476A|EC3000|consumptionTotal: 1685.343|consumptionTotal|1685.343|
       3243       2017-01-07 17:32:59|myDbLog|DBLOG|CacheUsage: 8|CacheUsage|8|
       3244       2017-01-07 17:32:59|EC3000_3E58|EC3000|consumption: 31.296|consumption|31.296|
       3245       2017-01-07 17:32:59|EC3000_3E58|EC3000|power: 1.8|power|1.8|
       3246       2017-01-07 17:32:59|EC3000_3E58|EC3000|powerMax: 1266.4|powerMax|1266.4|
       3247       2017-01-07 17:32:59|EC3000_3E58|EC3000|on|state|on|
       3248       2017-01-07 17:32:59|EC3000_3E58|EC3000|Total: 31.296|Total|31.296|
       3249       2017-01-07 17:32:59|myDbLog|DBLOG|CacheUsage: 14|CacheUsage|14|
       3250       2017-01-07 17:32:59|myDbLog|DBLOG|connected|state|connected|
       3251       2017-01-07 17:33:00|EC3000_3DDC|EC3000|consumption: 93.986|consumption|93.986|
       3252       2017-01-07 17:33:00|EC3000_3DDC|EC3000|power: 3.4|power|3.4|
       3253       2017-01-07 17:33:00|EC3000_3DDC|EC3000|powerMax: 99.6|powerMax|99.6|
       3254       2017-01-07 17:33:00|EC3000_3DDC|EC3000|on|state|on|
       3255       2017-01-07 17:33:00|EC3000_3DDC|EC3000|consumptionTotal: 93.986|consumptionTotal|93.986|
       3256       2017-01-07 17:33:00|myDbLog|DBLOG|CacheUsage: 21|CacheUsage|21|
Attributes:
   DbLogType  Current/History
   asyncMode  1
   room       db-logs
   shutdownWait 5
   verbose    0



      Dbd::mysql::st execute_array failed:
         Mydblog:
           TIME       1483803885.42194
           VALUE      executing 1278 generated 1 errors at ./FHEM/93_DbLog.pm line 1183.


bedeutet diese Meldung bezüglich FHEM2FHEM etwas?


VG

PS. nach einiger Zeit zeigt list myDbLog:

   CONFIGURATION ./db.conf
   DBMODEL    MYSQL
   DEF        ./db.conf .*.
   MODE       synchronous
   NAME       myDbLog
   NOTIFYDEV  .*.
   NR         4
   NTFY_ORDER 50-myDbLog
   PID        2994
   REGEXP     .*.
   STATE      connected
   TYPE       DbLog
   VERSION    2.8.2
   dbconn     mysql:database=fhem;host=localhost;port=3306
   dbuser     fhemuser
   Helper:
   Helper:
     Dblog:
       Cacheusage:
         Mydblog:
           TIME       1483811468.89884
           VALUE      168
       Dbd::mysql::st execute_array failed:
         Mydblog:
           TIME       1483809090.57913
           VALUE      executing 309 generated 1 errors at ./FHEM/93_DbLog.pm line 1183.

       Nextsync:
         Mydblog:
           TIME       1483811447.36378
           VALUE      2017-01-07 18:51:17
       State:
         Mydblog:
           TIME       1483811447.51395
           VALUE      connected
   Readings:
     2017-01-07 18:51:08   CacheUsage      169
     2017-01-07 18:50:47   NextSync        2017-01-07 18:51:17
     2015-02-21 14:57:11   countCurrent    3053
     2015-02-21 14:57:11   countHistory    148316222
     2017-01-07 18:50:47   state           connected
     2017-01-07 00:05:00   userCommand     select
                                max(to_number(value,'999.999')) - min(to_number(value,'999.999')) as kw
                                from history
                                where device = 'PCA301_FeOben'
                                and reading = 'consumption'
                                and timestamp >= TO_TIMESTAMP('2017-01-06 00:00:00','YYYY-MM-DD HH24:MI:SS')
                                and timestamp <= TO_TIMESTAMP('2017-01-06 23:59:59','YYYY-MM-DD HH24:MI:SS')

Attributes:
   DbLogType  Current/History
   asyncMode  1
   room       db-logs
   shutdownWait 5
   verbose    0




es wird in den internals: synchronous angezeit obwohl ATTR asyncMode 1

Eine Idee?

Wo gibt es die letzte funktionierende Version vor den Update?

./db.conf .*.

Eventuell so. Aber dann wird alles geloggt

Auch das führt nicht zum loggen von FHEM2FHEM Daten

VG

FHEM2FHEM im LOG-Mode legt temporaer Geraete an, es sei denn, ein Geraet mit dem passenden Namen existiert schon.

Das in DoTrigger verwendete %ntfyHash wird in createNtfyHash aus NOTIFYDEV mit devspec2array berechnet.
createNtfyHash wird nur beim Aendern von Geraeten aufgerufen, nicht aber, wenn FHEM2FHEM ein temporaeres Geraet anlegt.
-> Von FHEM2FHEM temporaer angelegte Geraete koennen nur ohne NOTIFYDEV benachrichtigt werden.

Die Funktion notifyRegexpChanged prueft sowas, und berechnet aus einem Regexp NOTIFYDEV bzw. loescht sie, falls NOTIFYDEV kontraproduktiv ist. Modulautoren sollten NOTIFYDEV nur ueber diese Funktion setzen, und nie direkt. Damit ist auch eine Aenderung/Optimierung eher moeglich.

Zitat von: DS_Starter am 07 Januar 2017, 17:24:48
So werde ich das morgen früh einbauen ....

wobei ich den von Rudi empfohlenen Weg sogar noch besser finde...

Zitat von: rudolfkoenig am 07 Januar 2017, 19:20:27
Die Funktion notifyRegexpChanged prueft sowas, und berechnet aus einem Regexp NOTIFYDEV bzw. loescht sie, falls NOTIFYDEV kontraproduktiv ist. Modulautoren sollten NOTIFYDEV nur ueber diese Funktion setzen, und nie direkt. Damit ist auch eine Aenderung/Optimierung eher moeglich.

Bei mir werden seit dem Update heute auch keine Daten mehr vom Type GPIO4 geloggt. Vorher wurde alles geloggt. Die Events sind im Event-Monitor sichtbar:

2017-01-07 22:44:22 GPIO4 Heizungsvorlauf temperature: 40.875
2017-01-07 22:44:33 GPIO4 Heizungsvorlauf temperature: 40.25
2017-01-07 22:44:55 GPIO4 Heizungsvorlauf temperature: 39.312

DbLog ist wie folgt definiert:
defmod LogDB DbLog ./db.conf (Heizung|HK_).*:.*
attr LogDB group Log
attr LogDB room System
attr LogDB sortby 12

Was kann ich einstellen, das es wieder loggt?
Signale vom Type MAX werden weiterhin geloggt.

Sorry war bis jetzt unterwegs ...

So sollte es gehen:

defmod LogDB DbLog ./db.conf (Heizung.*|HK_.*):.*

Morgen früh werde ich das Problem fixen..

Danke,

so klappt es bei mir. Nach der Änderung ist unter Internals auch ein NOTIFYDEV und REGEXP sichtbar. Das es vorher nicht gab.

Prima ... das NOTIFYDEV ist eine feine Sache weil es FHEM bei einer umfangreichen Installation entlastet. Hat aber leider jetzt Späne verursacht.
Muß mich morgen um eine Verbesserung bemühen.

Guten Morgen,

anbei die korrigierte Version V8.2.3 bzgl. der NOTIFYDEV-Verwendung.

Habe die von Rudi angemerkte Funktion zum Setzen des  NOTIFYDEV eingebaut.
Außerdem gibt es noch das Attribut "noNotifyDev" womit der User die Verwendung von NOTIFYDEV explizit unterbinden kann wenn es nötig/gewünscht ist.

Die Commandref ist auch ergänzt und gecheckt.

EDIT: In der auch angehängten V2.8.4 habe ich gleich noch $readingFnAttributes ergänzt, sodass nun die Attribute stateFormat, event-on-change-reading ... ebenfalls verfügbar sind.

Grüße
Heiko

noch einen  Tip ...

man sollte DbLogExclude mit CacheUsage,NextSync,sql_processing_time auf das Device setzen, sonst logged sich die Queue selber von alleine nach oben :-)

bei event-on-change-reading mit .* filtert sich der state ja von alleine

Hallo zusammen,

kleine Frage, aber bitte nicht hauen.
Geht bei euch noch das neu anlegen von Plots? Ich habe ein frisch aufgesetztes System und mir werden wenn DbLog ausgewählt wird keine Sensoren angezeigt (sie auch hier: https://forum.fhem.de/index.php/topic,64384.0.html

Danke und Grüße ...Carsten

Das selbst Problem hatte ich einige Beiträge vorher auch, die Lösung war:

Zitat von: DS_Starter am 06 Januar 2017, 22:43:48
Du mußt das Attribut DbLogType explizit auf "Current" bzw. "History/Current" setzen um die Current-Tabelle zu benutzen.

Besten Dank,

den Beitrag habe ich wahrscheinlich zu schnell "überflogen"!

"C/H" brachte den Erfolg, auch wenn ich den Zusammenhang nicht wirklich verstehe.  :(
"C" wächst nicht (wirklich) und "H" stetig. Heißt das mit anderen Worten das in "C" die letzten Werte vorgehalten werden und danach bei Änderung in "H" verschoben werden? Sorry für die dumme Frage, aber ...

DbLog ist jetzt aber sehr gesprächig geworden, für jedes von anderen Geräten erzeugtes Event-Paket wirft DbLog mindestens 2 neue Events heraus selbst wenn die anderen Geräte nicht geloggt werden.

Ist das beabsichtigt?

Zitat2017-01-08 18:30:48.315 CUL_HM LCSW4_Sw_03 set_on
2017-01-08 18:30:48.419 DbLog logdb CacheUsage: 0
2017-01-08 18:30:48.419 DbLog logdb CacheUsage: 0
2017-01-08 18:30:48.436 CUL_HM Heiz_Nacht set_on
2017-01-08 18:30:48.504 DbLog logdb CacheUsage: 0
2017-01-08 18:30:48.504 DbLog logdb CacheUsage: 0
2017-01-08 18:30:48.520 CUL_HM Heiz_Tag set_off
2017-01-08 18:30:48.589 DbLog logdb CacheUsage: 0
2017-01-08 18:30:48.589 DbLog logdb CacheUsage: 0
2017-01-08 18:30:48.607 DOIF Steuerung cmd_nr: 3
2017-01-08 18:30:48.607 DOIF Steuerung cmd: 3
2017-01-08 18:30:48.607 DOIF Steuerung cmd_event: BrennerStatus
2017-01-08 18:30:48.607 DOIF Steuerung Nacht
2017-01-08 18:30:48.660 DbLog logdb CacheUsage: 1
2017-01-08 18:30:48.660 DbLog logdb CacheUsage: 1
2017-01-08 18:30:48.694 DOIF BrennerStatus cmd_nr: 2
2017-01-08 18:30:48.694 DOIF BrennerStatus cmd: 2
2017-01-08 18:30:48.694 DOIF BrennerStatus 0
2017-01-08 18:30:48.763 DbLog logdb CacheUsage: 2
2017-01-08 18:30:48.763 DbLog logdb CacheUsage: 2

nimm die Version aus dem letzten Postr von DS-Starter.

Dort werden die Set Extensions unterstützt.

Jetzt gibt es ein Event-on-change und auch Stateformat :-)

die CacheUsage würde ich aber noch auf jeden Fall in Exclude Log nehmen --> siehe meinen letzten Post

Einer ist beabsichtigt wenn man ihn will . Sonst event-on .....
Der zweite kann nur vom DbLog selbst kommen wenn die Events durch die dblog_log Schleife laufen . Setz mal dblogexclude auf cacheusage. Dann sollte das nicht mehr so sein. Es kann in der Form nur dann der Fall sein wenn die zu loggen devices nicht durch Notifydev gefiltert werden. Auch mit dem Attribut excludedevs kannst ein ganzes device von der Verarbeitung ausnehmen, in dem Fall das DbLog device selbst.

Sorry , wortergänzung auf dem mobilteil
Vg

Ich moechte von einem DbLog-Event bei jedem Log abraten, event-on-.* ist nicht soo bilig.
Wozu braucht man so ein Event?

Zum Beispiel wenn man sich die Entwicklung des CacheUsages aufzeichnen möchte.
Ausschließen geht auch über das Attr excludedevs für das ganze DbLog device. Dann braucht man kein event-on...
Im synchronen Mode wird CacheUsage nicht erzeugt weil es das dann nicht gibt.

Danke, dann werde ich mal auf excludedevs umstellen.

Habe es gerade mit excludeDevs probiert, aber es werden immer noch events generiert!

Zitat von: DS_Starter am 08 Januar 2017, 19:29:17
Zum Beispiel wenn man sich die Entwicklung des CacheUsages aufzeichnen möchte.
Ausschließen geht auch über das Attr excludedevs für das ganze DbLog device. Dann braucht man kein event-on...
Im synchronen Mode wird CacheUsage nicht erzeugt weil es das dann nicht gibt.

Ich habs umgestellt, cacheusage kommt immer noch, aber nur einmal pro Geräte-Event.

Und wenn ich lese, dass event-on... nicht billig ist, dann plädiere ich dafür die exzessive Eventerzeugung als OptIn vorzusehen.

30% der Events werden von DbLog erzeugt.

Zitat2017-01-08 19:45:50.464 DOIF TempWZvirtual_di cmd: 1
2017-01-08 19:45:50.464 DOIF TempWZvirtual_di cmd_event: SHT21
2017-01-08 19:45:50.464 DOIF TempWZvirtual_di cmd_1
2017-01-08 19:45:50.514 DbLog logdb CacheUsage: 7
2017-01-08 19:45:50.536 I2C_SHT21 SHT21 temperature: 19.96
2017-01-08 19:45:50.536 I2C_SHT21 SHT21 dTdt: -1.17918066214531
2017-01-08 19:45:50.536 I2C_SHT21 SHT21 result_temperature_linreg: -0.958145
2017-01-08 19:45:50.764 DbLog logdb CacheUsage: 7
2017-01-08 19:45:50.779 PRESENCE AVRan absent
2017-01-08 19:45:50.779 PRESENCE AVRan presence: absent
2017-01-08 19:45:53.229 DbLog logdb CacheUsage: 0
2017-01-08 19:45:53.229 DbLog logdb NextSync: 2017-01-08 19:46:23
2017-01-08 19:45:53.229 DbLog logdb connected
2017-01-08 19:45:53.494 DbLog logdb connected
2017-01-08 19:45:53.735 DbLog logdb CacheUsage: 0
2017-01-08 19:45:53.749 PRESENCE LaptopAn present
2017-01-08 19:45:53.749 PRESENCE LaptopAn presence: present
2017-01-08 19:45:53.873 DbLog logdb CacheUsage: 3
2017-01-08 19:45:53.888 I2C_BMP180 BMP180 T: 20.3 P: 1028 P-NN: 1029
2017-01-08 19:45:53.888 I2C_BMP180 BMP180 temperature: 20.3
2017-01-08 19:45:53.888 I2C_BMP180 BMP180 pressure: 1028
2017-01-08 19:45:53.888 I2C_BMP180 BMP180 pressure-nn: 1029

Excludedevs mit dem DbLog device im argument. Hmm ... Dann werden noch cacheusage Events erzeugt wenn cacheeiträge der zu loggenden device erfolgen. Wenn event-on .. wie Rudi geschrieben hat nicht gut ist kann ich für cacheusage die eventerzeugung nur generell auf 0 setzen bzw. Wie ellert geschrieben hat mit einem ATR im Bedarfsfall zuschaltbar zu machen was wohl das Beste wäre.

Edit: wenn ich nachher wieder zu Hause bin sehe ich diese Möglichkeit vor

Zitat von: DS_Starter am 08 Januar 2017, 19:57:38
Excludedevs mit dem DbLog device im argument. Hmm ... Dann werden noch cacheusage Events erzeugt wenn cacheeiträge der zu loggenden device erfolgen. Wenn event-on .. wie Rudi geschrieben hat nicht gut ist kann ich für cacheusage die eventerzeugung nur generell auf 0 setzen bzw. Wie ellert geschrieben hat mit einem ATR im Bedarfsfall zuschaltbar zu machen was wohl das Beste wäre.

Ja, OptIn wäre schön. Auch NextSync und connected würde ich ein/abschaltbar machen, wirklich notwendig wären Events im Fehlerfall, wenn die Datenbank nicht erreichbar ist oder ein Timeout abgelaufen ist oder bei Cache-Überlauf.

Nextsync kommt ja relativ selten, reicht da nicht event-on..  ?  Aber wenn ich schonmal dabei bin ...

Ich bin noch nicht sicher ob es hierher gehört,
hat seit dem update schonmal jemand ein neues Device angelegt und zum dblog hinzugefügt? Wenn ich versuche dieses neue Device in einen SVG-Plot zu bringen wird es mir nicht vorgeschlagen...
Über sequel pro kann ich aber sehen das die Werte geschrieben werden, im SVG-Editor tut sich nix.

@lolo: attr DbLogType Current/History


Von unterwegs gesendet.

Zitat von: Loredo am 05 Januar 2017, 18:53:13
könntest du auch noch einbauen, dass DbLog_splitFn nicht nur in $modules{ $defs{$name}{TYPE} }{DbLog_splitFn} gesucht wird, sondern auch in $defs{$name}{'.DbLog_splitFn'}?
$defs{$name}{'.DbLog_splitFn'} sollte dabei dann Vorrang haben.

Ich habe das inzwischen in das sich in Entwicklung befindliche Modul "98_powerMap" (https://forum.fhem.de/index.php/topic,63016.msg556706.html#msg556706) mit eingebaut. Es setzt bereits $defs{$name}{'.DbLog_splitFn'} und wartet darauf, dass DbLog es dort abholt  ;)
Wäre also prima, wenn bei den ganzen gerade ohnehin stattfindenden Updates diese Kleinigkeit ergänzt werden könnte.




Danke & Gruß
Julian

Hallo zusammen,

hier wie angekündigt die V2.8.5. Es werden Events von CacheUsage, NextSync nur noch erzeugt wenn die Attr "syncEvent"" bzw. "cacheEvents" gesetzt sind. State gibt im Normalfall keine Events, Fehler wie DBI-Error usw. tun dies.
Commandref ist aktualisiert.

@Julien, ja habe es nicht vergessen. Aber ich möchte erstmal hier in ruhigere Fahrwasser kommen.

LG
Heiko

Ich habe mal 15 min geloggt und es gibt keine DbLog-Events. Nur das Attribut asyncMode 1 ist gesetzt.

Danke
Ellert

Hi Julian,
warum willst du "$defs{$name}{'.DbLog_splitFn'}" das so einbauen und niocht so, wie es im Wiki für die Modulentwickler drinsteht?
Oder hab ich noch etwas nicht ganz verstanden?

@DS_Starter: du könntest das Modul im stabilen Zustand auch selbst einchecken. Anosnsten musst du mir eine PM schreiben wen ich es machen soll. Allerdings mit 1-2 Tagen verzögerung möglich ...

Hallo Zusammen,
bin kein Entwickler, nur User!  :-[

Ich habe aber festgestellt, dass seit dem Update auf 2.8.2 des DbLog-Moduls Events mit sehr langen Inhalt nicht komplett geloggt werden, sondern "abgeschnitten" gespeichert werden.

Aufgefallen ist es mir beim THZ-Modul, welches z.B. ein sehr langes Reading "sGlobal" hat. Es ist etwa 750 Zeichen lang.

Nach dem Update auf Version 2.8.2 wurde dieser Reading sGlobal bei ca. 513 Zeichen "abgeschnitten".

Könnte das etwas mit den hier vorgenommenen Änderungen zu tun haben?

Auch fällt auf, dass bei gleichzeitigem Verwenden des FileLog-Devices auch im Filelog nur noch das gekürzte Event steht. Deaktiviert man das Logging per DbLog, so wird das Reading auch wieder vollständig im FileLog abgespeichert!

Danke schonmal für Euer Feedback und VG...

Zitat von: friesenjung am 09 Januar 2017, 13:01:49
Aufgefallen ist es mir beim THZ-Modul, welches z.B. ein sehr langes Reading "sGlobal" hat. Es ist etwa 750 Zeichen lang.

Hast Du die Spalte in der Datenbank  manuell "verbreitert"?
Im Standard ist diese nur 512 Zeichen "breit", kann also gar nicht mehr zeichen abspeichern....

Zitat von: JoeALLb am 09 Januar 2017, 13:15:08
Hast Du die Spalte in der Datenbank  manuell "verbreitert"?
Im Standard ist diese nur 512 Zeichen "breit", kann also gar nicht mehr zeichen abspeichern....

Hi. Ja, hab ich. Die Spalte EVENT ist bei mir auf 1024 Zeichen geändert. Wie gesagt ging es ja bis ich, ich glaube vorgestern Abend, FHEM aktualisiert habe.

Auch würde das nicht erklären, warum beim Parallelbetrieb (FileLog + DbLog) auch das Event gekürzt im FileLog auftaucht...

Zitat von: Tobias am 09 Januar 2017, 12:13:47
warum willst du "$defs{$name}{'.DbLog_splitFn'}" das so einbauen und niocht so, wie es im Wiki für die Modulentwickler drinsteht?
Oder hab ich noch etwas nicht ganz verstanden?

Der Wiki Artikel (https://wiki.fhem.de/wiki/DbLog#Bereitstellung_der_UNITS) spricht davon $hash->{DbLog_splitFn} in der X_Initialize() Funktion zu setzen.
Dies entspricht einer Definition für alle Instanzen dieses Moduls, da $hash hier nur eine Referenz auf $modules{ $hash->{TYPE} } ist und DbLog_splitFn somit tatsächlich in $modules{ $hash->{TYPE} }{DbLog_splitFn} gespeichert wird (siehe auch hier (https://wiki.fhem.de/wiki/DevelopmentModuleIntro#Wichtige_globale_Variablen_aus_fhem.pl)). Daran möchte ich nichts ändern.

Was mir fehlt ist die Möglichkeit pro definiertem Device ebenfalls individuell eine DbLog_splitFn setzen zu können, also in $defs{ $hash->{NAME} }. Sprich: Dort würde dann eigentlich ein INTERNAL angelegt. Mir erschien es sinnvoll dies hier mit einem führenden Punkt unsichtbar zu schalten statt es sichtbar zu haben. Deshalb $defs{ $hash->{NAME} }{'.DbLog_splitFn'}. Der Grund ist, dass IMHO ein externes Modul wie 98_powerMap nicht direkt in den Hash der Moduldefinition schreiben soll, sondern wenn überhaupt nur in eine Modulinstanz unter $defs (und auch dann nur "freundlich"; in diesem Fall auch nur, wenn das externe Modul bisher noch gar keine DbLog_splitFn gesetzt hat).

Über den führenden Punkt kann man aber sicher streiten und letztlich geht es mir nur um die Funktionalität ansich.

Zitat von: friesenjung am 09 Januar 2017, 13:43:24
Hi. Ja, hab ich. Die Spalte EVENT ist bei mir auf 1024 Zeichen geändert. Wie gesagt ging es ja bis ich, ich glaube vorgestern Abend, FHEM aktualisiert habe.

Auch würde das nicht erklären, warum beim Parallelbetrieb (FileLog + DbLog) auch das Event gekürzt im FileLog auftaucht...

Nun, in Zeile 819 wird der text mit folgendem code gekürzt.
$reading  = substr($reading,0, $columns{READING});
Wenn Du das für dich in
$reading  = substr($reading,0, 1024);
änderst, sollte das vorerst gehen.

Warum genau dieses Kürzen der Readings hier gemacht wird, kann ich nicht einschätzen.... meiner Meinung nach sollte das MySQL selbst auch passend kürzen, wenn eine Spalte zu schmal ist.

MySQL tut das auch. Macht es SQLite auch?

Zitat von: marvin78 am 09 Januar 2017, 16:46:37
MySQL tut das auch. Macht es SQLite auch?

Im Code ist speziell SQLite ausgenommen... also wird es nur für die anderen DBs gemacht.
if ($hash->{DBMODEL} ne 'SQLITE') {

In DbLog ist vieles seltsam und es wird nicht besser.

Zitat von: JoeALLb am 09 Januar 2017, 16:44:23
Nun, in Zeile 819 wird der text mit folgendem code gekürzt.

Code Auswählen Erweitern

$reading  = substr($reading,0, $columns{READING});
Wenn Du das für dich in

Code Auswählen Erweitern

$reading  = substr($reading,0, 1024);
änderst, sollte das vorerst gehen.

Warum genau dieses Kürzen der Readings hier gemacht wird, kann ich nicht einschätzen.... meiner Meinung nach sollte das MySQL selbst auch passend kürzen, wenn eine Spalte zu schmal ist.

das ging schnell, danke für die Info! Ich werde erst noch etwas warten, bevor ich die Zeile ändere. Vielleicht gabs nen wichtigen Grund!? Falls dieser für mich unrelevant ist, änder ich es in der Zeile...

Zitat von: marvin78 am 09 Januar 2017, 17:02:52
In DbLog ist vieles seltsam und es wird nicht besser.

Da halte ich dagegen: Es tun sich hier gerade wunderbare Weiterentwicklungen! Dafür bin ich Heiko sehr dankbar!!

Hallo miteinander,

das Beschneiden der Feldlängen vor dem Schreiben in die DB (für nicht SQLite-DB's) gab es bereits in dieser Form in der bisherigen DbLog-Version und wurde aus Kompatibilitätsgründen auch so übernommen.
Möglicherweise ist es nicht (mehr) notwendig und könnte entfernt werden. Aber das würde ich nur nach entsprechenden Tests gemeinsam mit euch tun.

An dieser Stelle mal einen herzlichen Dank an die Unterstützer dieses Umstellungsprozesses !!

@ friesenjung ... wenn du für dich in deiner DB-Umgebung die Spaltenbreite angepasst hast, dann kannst du diese Werte gleich am Anfang des Moduls
ab Zeile 56 (etwa) zentral ändern :


my %columns = ("DEVICE"  => 64,
               "TYPE"    => 64,
                "EVENT"   => 512,
                "READING" => 64,
                "VALUE"   => 128,
                "UNIT"    => 32
          );


Bei dir wäre dann " "EVENT"   => 1024, " gültig. So wäre es besser als direkt im Code zu ändern wenn man solche Veränderungen an der DB vorgenommen hat.

@Tobias ... danke für die Info. Ich denke die jetzige V2.8.5 aus #167 sollten wir heute Abend einchecken da sie die wichtigen Korrekturen für NOTIFYDEV-Verwendung und und die zuschaltbaren Events enthält.

Grüße
Heiko

Zitat von: marvin78 am 09 Januar 2017, 17:02:52
In DbLog ist vieles seltsam und es wird nicht besser.

93_DbLog.pm ist die "fhem-Nutte" - da haben schon ganz viele dran rumgefummelt...

Zitat von: betateilchen am 09 Januar 2017, 19:46:16
93_DbLog.pm ist die "fhem-Nutte" - da haben schon ganz viele dran rumgefummelt...

ich würds ja auch alleine machen, aber soviel Zeit habe ich nicht. Da ist jede Zuarbeit willkommen. Allerdings sehe ich mich trotzdem als Maintainer um drauf zu achten Was dort Wie reinkommt.

Fhem-Nutte *schmunzel*

Zitat von: betateilchen am 09 Januar 2017, 19:46:16
93_DbLog.pm ist die "fhem-Nutte" - da haben schon ganz viele dran rumgefummelt...

Na, na! Mind your words.


Heiko ist jedenfalls IMHO keiner, der da auch nur eben schnell drüber huscht. Das wird seinem Engagement nicht gerecht.

Zitat von: Loredo am 09 Januar 2017, 20:36:40
Na, na! Mind your words.

ich weiß, wovon ich rede, ich habe in der Vergangenheit auch schon einiges in das Modul implantiert...  8)

Hallo,

ich hab heute Mittag ein ReduceLog ausgeführt, seitdem funktioniert der async-Modus mit der Version 2.8.5 nicht mehr. Es werden keine Daten in die Datenbank geschrieben. Mit der alten Version 2.8.1 funtioniert es.

Version 2.8.5
2017.01.09 21:14:03.171 4: DbLog logdb -> ################################################################
2017.01.09 21:14:03.171 4: DbLog logdb -> ###              start of new Logcycle                       ###
2017.01.09 21:14:03.171 4: DbLog logdb -> ################################################################
2017.01.09 21:14:03.172 4: DbLog logdb -> amount of events received: 2 for device: logdb
2017.01.09 21:14:03.172 4: DbLog logdb -> check Device: logdb , Event: background_processing_time: 0.0122
2017.01.09 21:14:03.172 4: DbLog logdb -> check Device: logdb , Event: sql_processing_time: 0.0041
2017.01.09 21:14:03.174 5: DbLog logdb -> DbLog_PushAsyncDone finished
2017.01.09 21:14:11.177 4: DbLog logdb -> ################################################################
2017.01.09 21:14:11.178 4: DbLog logdb -> ###              start of new Logcycle                       ###
2017.01.09 21:14:11.178 4: DbLog logdb -> ################################################################
2017.01.09 21:14:11.178 4: DbLog logdb -> amount of events received: 1 for device: SZ_Clima
2017.01.09 21:14:11.178 4: DbLog logdb -> check Device: SZ_Clima , Event: 28
2017.01.09 21:14:11.183 4: DbLog logdb -> ################################################################
2017.01.09 21:14:11.183 4: DbLog logdb -> ###              start of new Logcycle                       ###
2017.01.09 21:14:11.183 4: DbLog logdb -> ################################################################
2017.01.09 21:14:11.184 4: DbLog logdb -> amount of events received: 2 for device: SZ_Ventil2
2017.01.09 21:14:11.184 4: DbLog logdb -> check Device: SZ_Ventil2 , Event: ValveDesired: 28
2017.01.09 21:14:11.184 4: DbLog logdb -> check Device: SZ_Ventil2 , Event: set_28
2017.01.09 21:14:11.306 4: DbLog logdb -> ################################################################
2017.01.09 21:14:11.306 4: DbLog logdb -> ###              start of new Logcycle                       ###
2017.01.09 21:14:11.307 4: DbLog logdb -> ################################################################
2017.01.09 21:14:11.307 4: DbLog logdb -> amount of events received: 6 for device: SZ_Ventil2
2017.01.09 21:14:11.307 4: DbLog logdb -> check Device: SZ_Ventil2 , Event: ValvePosition: 28
2017.01.09 21:14:11.307 4: DbLog logdb -> check Device: SZ_Ventil2 , Event: battery: ok
2017.01.09 21:14:11.307 4: DbLog logdb -> check Device: SZ_Ventil2 , Event: motor: stop
2017.01.09 21:14:11.308 4: DbLog logdb -> check Device: SZ_Ventil2 , Event: motorErr: ok
2017.01.09 21:14:11.308 4: DbLog logdb -> check Device: SZ_Ventil2 , Event: operState: onTarget
2017.01.09 21:14:11.308 4: DbLog logdb -> check Device: SZ_Ventil2 , Event: 28
2017.01.09 21:14:13.060 4: DbLog logdb -> ################################################################
2017.01.09 21:14:13.061 4: DbLog logdb -> ###              start of new Logcycle                       ###
2017.01.09 21:14:13.061 4: DbLog logdb -> ################################################################
2017.01.09 21:14:13.061 4: DbLog logdb -> amount of events received: 1 for device: hmusb
2017.01.09 21:14:13.061 4: DbLog logdb -> check Device: hmusb , Event: loadLvl: low
2017.01.09 21:14:21.827 4: DbLog logdb -> ################################################################
2017.01.09 21:14:21.828 4: DbLog logdb -> ###              start of new Logcycle                       ###
2017.01.09 21:14:21.828 4: DbLog logdb -> ################################################################
2017.01.09 21:14:21.828 4: DbLog logdb -> amount of events received: 1 for device: HMLAN1
2017.01.09 21:14:21.828 4: DbLog logdb -> check Device: HMLAN1 , Event: loadLvl: batchLevel



vg Jens

Edit: Version 2.8.4 funktioniert auch noch
2. Edit mit aktiviertem Attr. "cacheEvents" geht auch die Version 2.8.5, hab die Funtion dieses Attr. aber anders verstanden

Hallo DbLog Freunde ;)

Hat jemand eine Idee woran es bei meinen DbLogExclude-Problem (https://forum.fhem.de/index.php/topic,63731.msg549528.html#msg549528) liegt?

Gruss, Xcoder

Zitat von: Newbie am 09 Januar 2017, 21:19:58
Hallo,

ich hab heute Mittag ein ReduceLog ausgeführt, seitdem funktioniert der async-Modus mit der Version 2.8.5 nicht mehr. Es werden keine Daten in die Datenbank geschrieben. Mit der alten Version 2.8.1 funtioniert es.

Wie sieht Dein Filter aus?

Ich musste bei mir nach dem Update von (KNX_....:.*|SWC_170:.*) auf (KNX_....|SWC_170):.* wechseln, weil sonst nur noch KNX_.... Events gelogt wurden.

Gruss, Xcoder

Hallo,

hatte ursprünglich meine Frage im Bereich "Anfänger" eingestellt, da ich euch nicht mit diesen "Kinderkram" nerven wollte. Aber ich denke es könnte mit dieser Thematik etwas zu tun haben, da ein weiterer User vom gleichen/ähnlichen Fehler berichtet.
Bitte steinigt mich nicht wenn ich total daneben liege.

Der Fehler (gemäß Logauszug):
2017.01.08 15:00:56 5: exec at command DBLogging_Reopen
2017.01.08 15:00:56 2: DbLog DBLogging -> Error: DBD::mysql::db begin_work failed: Turning off AutoCommit failed at ./FHEM/93_DbLog.pm line 923.

2017.01.08 15:00:56 1: PERL WARNING: rollback ineffective with AutoCommit enabled at ./FHEM/93_DbLog.pm line 994.
2017.01.08 15:00:56 3: DBLogging_Reopen: Reopen executed.

kommt meistens, nachdem das DBLogging_Reopen mit at aufgerufen wird, aber es gibt auch Zeiten wo kein Fehler zu beobachten ist.
Wenn ich mein Log ansehe, kommt der Fehler erst seit dem Fhem Update vom 07.01.2016, hier ist auch eine Änderung in der "93_DbLog: can now working in  async mode" enthalten. Kann auch nur eine falsche Vermutung sein, denn wenn es so wäre, gäb es sicher bei mehreren Usern Probleme. Da ich mein System derzeit in Fhem komplett neu aufbaue, kann ich natürlich nicht ausschließen, dass ich irgend etwas noch anderes geändert habe, was den Fehler auslöst.

Verwendetes System und versuchte Lösungen in Stichpunkten:
Raspberry PI 3 mit 16 GB Speicherkarte
MYSQL Datenbank ist über Console (mysql) und HeidiSQL jederzeit erreichbar und sichtbar
Verwendeter Datenbankclient unter WIN7 HeidiSQL -> in die Datenbank wird korrekt geschrieben
Tabelle history ist mit Daten gefüllt
Tabelle current ist leer ???? :-[ ???? -> denke aber mittlerweile das ist OK so!
MySQL Datenbank komplett gelöscht und neu angelegt und eingerichtet, jedoch gleicher Fehler wieder
Fhem ist aktuell, eben update ausgeführt
Raspi mehrmals neu gestartet, Fehler bleibt jedoch

Es wäre nett wenn ihr mir einen Tipp geben könntet woran es liegt oder wie ich den Fehler eingrenzen könnte. Gerne liefere ich noch weitere Informationen, sollten diese Hilfreich sein.

Den usprünglichen Beitrag "https://forum.fhem.de/index.php/topic,64405.0.html" habe ich geschlossen.

Gruß Reinhard

Hallo Xcoder,

die Einstellungen sind schon ok bei mir. Problem mit der 2.8.5 ist im async-Modus, das nur 1x die Daten in die Datenbank geschrieben werden und danach nicht mehr. Bis zur Version 2.8.4 geht es.
Bis zum "set reduceLog" funktionierte ja die Version 2.8.5 auch.

vg Jens

@Newbie, die Unterschiede zw. 2.8.4 und 2.8.5 sind geringfügig. Der async-Modus funktioniert auf Timer-Basis. Möglicherweise liegt da das Problem.
Wie sieht es aus wenn du fhem mit der Version 2.8.5 restart hast, klappt dann alles wieder ?

@Rewe2000, nach deinem Fehler suche ich mal im Netz. Die Daten werden geloggt, das ist das Wichtigste. Die Current-Tabelle kannst du mit füllen wenn du das Attr "DbLogType" auf "Current" bzw. "Current/History" setzt.

EDIT: habe gerade das gesehn:

ZitatEdit mit aktiviertem Attr. "cacheEvents" geht auch die Version 2.8.5, hab die Funtion dieses Attr. aber anders verstanden

Ist auch anders, eben nur eine Eventgenerierung.  Das erschließt sich mir gerade nicht.

Hallo Heiko,

shutdown und System neu gestartet schon probiert. Gleiches Ergebnis.
Ich sehe im Reading "CacheUsage" das einmal Daten hochzählen, nach Ablauf von "syncInterval"(bei mir 60sek) in die Datenbank geschoben werden und danach CacheUsage bei 0 stehenbleibt.

vg Jens

@XCoder, das Filterproblem für die Regex ist mit 2.8.3 behoben, am besten gleich die 2.8.5 benutzen.

@Rewe2000, habe hier https://rt.cpan.org/Public/Bug/Display.html?id=105382 einen Hinweis auf ein solches Problem gefunden. Bezieht sich auf Perl 5.14.2 with DBD::mysql 4.031 Version. Möglicherweise gibt es noch mehr Hinweise. Mal schauen ...

Hallo Jens,

du hattest doch geschrieben

Zitatmit aktiviertem Attr. "cacheEvents" geht auch die Version 2.8.5

Bin jetzt etwas verwirrt.

Hallo Heiko,

mit cacheEvents=1 geht es ja auch.

ZitatIch sehe im Reading "CacheUsage" das einmal Daten hochzählen, nach Ablauf von "syncInterval"(bei mir 60sek) in die Datenbank geschoben werden und danach CacheUsage bei 0 stehenbleibt.

bezog sich bei cacheEvents=0

Ich habe hier die Error: DBD::mysql::db begin_work failed Meldungne mit Perl 5.24.1 und DBD::mysql 4.041. DbLog 2.8.2 ist im synchronen Modus.


@DS_Starter: Wo finde ich den 2.8.5? Ist das nicht im SVN?

Also wenn cacheEvents nicht gesetzt ist, wird auch die Anzeige nicht mehr aktualisiert. Hast du mal den Brower refresht und geschaut ob sich cacheEvents ändert ? Ansonsten mit verbose 5 schauen ob du den Start des DB-processing im Log findest:

2017.01.09 22:40:51.055 5: DbLog LogDB -> ################################################################
2017.01.09 22:40:51.056 5: DbLog LogDB -> ###              New database processing cycle               ###
2017.01.09 22:40:51.056 5: DbLog LogDB -> ################################################################
2017.01.09 22:40:51.056 5: DbLog LogDB -> MemCache contains 17 entries to process
2017.01.09 22:40:51.056 5: DbLog LogDB -> MemCache contains: 2017-01-09 22:40:09|SMA_Energymeter|SMAEM|Bezug_WirkP_Zaehler_Diff: 0.0117|Bezug_WirkP_Zaehler_Diff|0.0117|
2017.01.09 22:40:51.056 5: DbLog LogDB -> MemCache contains: 2017-01-09 22:40:09|SMA_Energymeter|SMAEM|Bezug_WirkP_Kosten_Diff: 0.0025|Bezug_WirkP_Kosten_Diff|0.0025|
2017.01.09 22:40:51.056 5: DbLog LogDB -> MemCache contains: 2017-01-09 22:40:09|SMA_Energymeter|SMAEM|Einspeisung_WirkP_Zaehler_Diff: 0|Einspeisung_WirkP_Zaehler_Diff|0|


@XCoder. die V2.8.5 findest du hier im Beitrag #167.  Tobias wird sie heute sicherlich noch einchecken.

So hab jetzt etwas intensiver rumprobiert.

Ergebnis 1 - warum heute Nachmittag nicht gelogt wurde ist nicht mehr festzustellen

Ergebnis 2 - es wird zwar korrekt in die Datenbak geschrieben, aber die Anzeige von "CacheUsage" wird nach dem ersten Interval nicht mehr aktualisiert (mit Linux,Windows sowie verschiednene Browser probiert). Lade ich die Seite neu steht wieder einmal der aktuelle Wert drin. Und wie schon geschrieben mit cacheEvent=1 geht´s.

vg Jens

Hallo Jens,

ZitatLade ich die Seite neu steht wieder einmal der aktuelle Wert drin. Und wie schon geschrieben mit cacheEvent=1 geht´s.

Ja das ist normal wenn die Eventgenerierung ausgeschaltet ist wird das Reading nicht mehr automatisch aktualisiert. Die nicht erzeugten Events sollen die Systemressourcen schonen, sind aber zuschaltbar wenn der User es will/braucht. Nebeneffekt ist dass dann die Anzeige wieder refresht wird und automatisch aktualisieren.

Grüße
Heiko

Danke für die Info,

bleibt also nur das ungeklärte Problem vom Nachmittag. Wobei ich den Eindruck habe, das es sinnvoll ist bei Einstellungsänderungen am DbLog-Modul nicht nur FHEM neu zu starten sondern das komplette System.

Sorry für die Aufregung und DANKE für deine Arbeit hier.


vg Jens

Hallo,

anbei die V2.8.6.
Es sollte das Prob "mysql::db begin_work failed: Turning off AutoCommit failed" was bei XCoder immer mal auftritt, nicht mehr in Erscheinung treten.
Bitte Rückmeldung ob ok.

EDIT: das geschilderte Problem dass nach reducelog der asynchrone Logmodus nicht fortgeführt wird sollte auch behoben sein.

VG

2.8.6 ist jetzt eingecheckt.
@DS_Starter, dachte du machst das gestern ;)

Morgen Tobias,

danke  :)  War gestern noch zeimlich mit den User-Issues beschäftigt und darüber ganz untergegangen ... thx !

Wünsche dir einen schönen Tag ... Arbeit ruft...
Grüße
Heiko

Hallo Heiko,

Zitat von: DS_Starter am 09 Januar 2017, 18:48:52
das Beschneiden der Feldlängen vor dem Schreiben in die DB (für nicht SQLite-DB's) gab es bereits in dieser Form in der bisherigen DbLog-Version und wurde aus Kompatibilitätsgründen auch so übernommen.
Möglicherweise ist es nicht (mehr) notwendig und könnte entfernt werden. Aber das würde ich nur nach entsprechenden Tests gemeinsam mit euch tun.

Das wurde aber in der (nahen) Vergangenheit nicht ausgeführt. Bisher reichte es völlig aus, die Datenbank-Spalte zu verbreitern.
Erst seit den jüngsten Updates muss dazu noch die Breite im Modul mit geändert werden.
Warum, konnte ich leider anhand der Diffs des Moduls nicht finden.

als Ad Hoc Vorschlag:

Sollte man die Feldlängen nicht als Optionales Attribut einführen?

Zitat von: Wuppi68 am 10 Januar 2017, 09:41:33
als Ad Hoc Vorschlag:

Sollte man die Feldlängen nicht als Optionales Attribut einführen?

den Vorschlag finde ich gut!

Habe gestern die Feldlängen im Modul angepasst und nach FHEM-restart gings noch nicht. Hab dann Raspi komplett neugestartet und seit dem geht es wunderbar, so wie "früher".

Um nun nicht nach jedem FHEM-Update die Datei neu editieren zu müssen, wäre ein Attribut echt klasse.

Btw. gibt es eine Möglichkeit ein Modul explizit vom Update auszuschließen?

Grüße...

Zitat von: friesenjung am 10 Januar 2017, 13:12:18
Btw. gibt es eine Möglichkeit ein Modul explizit vom Update auszuschließen?

Ja. Indem man die Doku zu "update" liest, da steht sowas drin.

help update

Und dann Augenmerk auf den Abschnitt mit den Attributen.

Zitat von: Wuppi68 am 10 Januar 2017, 09:41:33
als Ad Hoc Vorschlag:

Sollte man die Feldlängen nicht als Optionales Attribut einführen?

Ich wäre eher dafür, das in der Konfigurationsdatei, die man ohnehin für DbLog braucht, zu hinterlegen.

Zitat von: betateilchen am 10 Januar 2017, 13:16:26
Ich wäre eher dafür, das in der Konfigurationsdatei, die man ohnehin für DbLog braucht, zu hinterlegen.

Ich wäre eher dafür, (sobald es denn überhaupt notwendig ist),
diese Information bei der Initialisierung direkt aus der DB abzufragen. Nur so ist sichergestellt, dass die beiden Werte übereinstimmen.
Bei SQLite und bei MySQL sehe ich jedoch keinerlei Notwendigkeit dafür, diese Strings schon im Modul zu kürzen.

Bei MySQL ist standardmäßig STRICT_TRANS_TABLES und STRICT_ALL_TABLES disabled, was das automatische Kürzen beim Insert erlaubt.
Der Benutzer muss es also bewußt deaktivieren.

Vielleicht sollten wir bei der Initialisierung auf ein paar wenige Standardeinstellungen prüfen und eine Meldung anzeigen, sofern diese nicht den Anforderungen von DbLog entspricht....

Hallo zusammen,
da komt ich doch noch mal mit meinem "Device:Reading" Problem bei den Plots ...
Heute morgen habe ich ein Update von FHEM gemacht und das 93_DbLog wurde auch aktualisiert. Die bisherigen Geräte werden weiterhin in der History Tabelle geschrieben, nun habe ich ein weiteres Gerät eingebunden und wollte mir einen passenden Plot erstellen. Nun sind aber wieder alle "Device:Reading" leer.
Im DbLog hatte ich wie angeraten das Attribute "DbLogType" auf "Current/History" gestellt. Beim neuen Gerät und auch bei den alten/vorhanden Geräten ist das "Device:Reading"  wieder leer.

Was habe ich übersehen bei den Änderungen?

Danke und Grüße ...Carsten

Zitat von: friesenjung am 10 Januar 2017, 13:12:18
Habe gestern die Feldlängen im Modul angepasst und nach FHEM-restart gings noch nicht. Hab dann Raspi komplett neugestartet und seit dem geht es wunderbar, so wie "früher".

Wie hast Du restarted? mit "shutdown restart" oder über das init-script? Dies solltest du überprüfen, denn
ein komplett-restart des raspi ist für soetwas niemals notwendig!

Zitat von: JoeALLb am 10 Januar 2017, 17:09:01
Wie hast Du restarted? mit "shutdown restart" oder über das init-script? Dies solltest du überprüfen, denn
ein komplett-restart des raspi ist für soetwas niemals notwendig!

mit init-script meinst Du "set <...> rereadcfg" ? Ja, das war das Erste > keine Änderung
Dann "shutdown restart" > keine Änderung

Raspi neu gestartet > ging

Es war spät und auch meine letzte Idee. Computer sind halt auch nur Menschen ;)

VG...

Hallo zusammen,

@Carsten, es scheint sich hierbei um ein (temporäres) Verbindungsproblem zur DB zu handeln. Sicherheitshalber habe ich dazu noch einen Verbindungscheck im Datenabruf eingebaut. Bitte teste es mit der angehängten V2.8.7 ob es nun sicher und sauber läuft.
Die Current-Tabelle muß auf jeden Fall verwendet und gefüllt werden.

Diesen Hinweis habe ich auch noch in die Commandref geschrieben. Irgendwo im Wiki steht etwas dazu aber in der Commandref stand bisher kein Vermerk darauf.

Grüße
Heiko

Bei mir schmiert fhem ab, wenn ich in fhemweb im SVG im Ploteditor auf "Show preprocessed input" klicke.
Ich verwende auch logproxy.  DbLog hat V2.8.6

Es erscheint nur:
2017.01.10 18:52:40.567 1: DbLog myDbLog: DBLog_Get - DB Session dead, try to reopen now !
Can't use string ("") as a SCALAR ref while "strict refs" in use at ./FHEM/98_logProxy.pm line 538.
und fhem hat sich beendet.

Auch mit
attr global stacktrace 1
gibt es nicht mehr Meldungen.

Mit der 2.8.7 schmiert FHEM nicht mehr ab.

Es funktioniert im normalen Modus, im asyncModus schmiert FHEM ab.

Ja, hatte bereits auf das gleiche Prob getippt. Bei mir funktioniert das alles.

Noch mal etwas rumgetestet.

Lasse ich das Browserfenster wie es ist und starte FHEM neu, übersteht fhem den Mausklick.
Aktuallisiere ich aber das Browserfenster nach FHEM Neustart, schmiert Fhem wieder ab.

alles im asyncModus

Habe nun in der Get-Funktion auch noch einen Verb.-Check eingebaut V2.8.8. Wie sieht es damit bei dir aus ?

Mit Mausklick meinst du sicherlich "Show preprocessed input" ...

Und nochwas:

2017.01.10 19:35:11.438 4: WEB_127.0.0.1_39917 POST /fhem/SVG_WriteGplot?detail=SVG_myHeizbedarf&showFileLogData=1&pos=zoom=hour;off=0&fw_id=1285; BUFLEN:0
2017.01.10 19:35:11.458 5: Cmd: >get myLogProxy HISTORY INT 2017-01-10_18:40:00 2017-01-10_19:40:01 DbLog:myDbLog,extend=100000:HM_ES_TX_WM_GZ_HZ:.........<
2017.01.10 19:35:11.462 4: myLogProxy: calling get myDbLog HISTORY INT 2017-01-09_14:53:20 2017-01-11_23:26:41 HM_ES_TX_WM_GZ_HZ:statGasCntLast:::$val=~s/Hour:.([\d\.]*).*/$1/eg
2017.01.10 19:35:11.463 5: Cmd: >get myDbLog HISTORY INT 2017-01-09_14:53:20 2017-01-11_23:26:41 HM_ES_TX_WM_GZ_HZ:statGasCntLast:::$val=~s/Hour:.([\d\.]*).*/$1/eg<
2017.01.10 19:35:11.466 1: DbLog myDbLog: DBLog_Get - DB Session dead, try to reopen now !
2017.01.10 19:35:11.471 5: Triggering myDbLog (1 changes)
2017.01.10 19:35:11.473 5: Starting notify loop for myDbLog, 1 event(s), first is connected
Can't use string ("") as a SCALAR ref while "strict refs" in use at ./FHEM/98_logProxy.pm line 538.

die 2.8.8 ist identisch mit der 2.8.7

Sorry war auch noch die gleiche 2.8.7, habe mich vertan . Bitte nochmal die 2.8.8 aus dem Vorbeitrag ziehen.
Habe es bei mir in allen Variationen getestet. SVG -Editor Fenter aufgemacht.  "Show preprocessed input"  , dann FHEM Restart > Browser refresh danach -> alles ok.

Ein diff zeigt bei mir zwischen zwischen meiner installierten und der 2.8.8 nur:

root@cubie:/opt/fhem/FHEM# diff ~/93_DbLog_V2.8.8.pm 93_DbLog.pm
16d15
< # 2.8.8      10.01.2017       connection check in Get added
58c57
< my $DbLogVersion = "2.8.8";
---
> my $DbLogVersion = "2.8.7";

War jetzt hier etwas durcheinander geraten ... nochmal bitte die 2.8.8 von oben.

Klappt jetzt auch wieder.

Die DropDown-Listen auch ok bei dir ? Falls du die Current Tabelle einsetzt.

Felder sind da, musste erstmal wieder Current aktivieren.
Ich bearbeite die gplot-Dateien direkt.
Bei mir ist meistens sowieso ein Text-Feld und keine Dropdownfeld für device:reading da.

ok, super .... dann checke ich oder Tobias heute Abend die neue Version ein.

Hallo DS_Starter

Die Fehlermeldung ist mit 2.8.6 nun leicht anders:
2017.01.10 21:44:45 1: Including fhem.cfg
2017.01.10 21:44:45 0: Using EIB is deprecated. Please migrate to KNX soon. Module 10_EIB is not maintained any longer. If you still want to use the module EIB,
please set the attribute useEIB to 1 within the tul-device. Please keep in mind, that 10_KNX has a changed syntax regarding the definition, arguments and readings. Please refer to the commandref.
As well 10_EIB and 10_KNX are compatible to daemon eibd and knxd.
2017.01.10 21:44:45 2: eventTypes: loaded 1155 events from ./log/eventTypes.txt
2017.01.10 21:44:46 1: Including ./log/fhem.save
2017.01.10 21:44:46 0: Featurelevel: 5.7
2017.01.10 21:44:46 0: Server started with 449 defined entities (fhem.pl:12966/2017-01-05 perl:5.024001 os:linux user:fhem pid:29421)
2017.01.10 21:44:56 1: PERL WARNING: Argument "no" isn't numeric in numeric gt (>) at ./FHEM/23_LUXTRONIK2.pm line 1188.
2017.01.10 21:46:26 2: DbLog logdb_core -> Error: DBD::mysql::st execute_array failed: MySQL server has gone away [err was 2006 now 2000000000]
executing 13 generated 13 errors at ./FHEM/93_DbLog.pm line 946.

2017.01.10 21:46:26 1: PERL WARNING: rollback ineffective with AutoCommit enabled at ./FHEM/93_DbLog.pm line 1014.
2017.01.10 21:48:17 2: DbLog logdb_core -> Error: DBD::mysql::st execute_array failed: MySQL server has gone away [err was 2006 now 2000000000]
executing 2 generated 2 errors at ./FHEM/93_DbLog.pm line 946.

2017.01.10 21:48:31 2: DbLog logdb_core -> Error: DBD::mysql::st execute_array failed: MySQL server has gone away [err was 2006 now 2000000000]
executing 2 generated 2 errors at ./FHEM/93_DbLog.pm line 946.

2017.01.10 21:48:39 2: DbLog logdb_core -> Error: DBD::mysql::st execute_array failed: MySQL server has gone away [err was 2006 now 2000000000]
executing 2 generated 2 errors at ./FHEM/93_DbLog.pm line 946.

2017.01.10 21:48:41 2: DbLog logdb_core -> Error: DBD::mysql::st execute_array failed: MySQL server has gone away [err was 2006 now 2000000000]
executing 2 generated 2 errors at ./FHEM/93_DbLog.pm line 946.

Bis jetzt 21:55 aber keine neuen Meldungen. MySQL war auf jeden Fall verfügbar ich habe laufend in phpMyAdmin die current Tabelle betrachtet, und keine Ausfälle bemerkt. MySQL läuft lokal.

Gruss, Xcoder

Hallo XCoder,

die Warnungen habe ich mit der V2.8.8 hier weiter oben auch eliminiert.
Verwende die bitte mal.
Ich gehe aber davon aus dass deine DB ganz normal logged ?

Richtig, alles wird geloggt.

Die AutoCommit-Meldung ist weg. Aber diese kommt immer noch:
2017.01.10 23:53:30 2: DbLog logdb_core -> Error: DBD::mysql::st execute_array failed: MySQL server has gone away [err was 2006 now 2000000000]
executing 2 generated 2 errors at ./FHEM/93_DbLog.pm line 951.

Ich kann die Meldung fast zuverlässig erzwingen, wenn ich SVG Plots aus dem DbLog anzeigen lasse...

Ist aber nicht so tragisch. Das Problem mit DbLogExclude ist da schon eher störend.


Danke und Gruss, Xcoder

Hallo Xcoder,

schau mal ob für dich diese Hinweise hier gültig sind:

http://piwik.org/faq/troubleshooting/faq_183/
http://stackoverflow.com/questions/7942154/mysql-error-2006-mysql-server-has-gone-away

Vielleicht hilft das.
Gute Nacht .

Hallo Heiko,

vielen Dank nochmals, die Versionen laufen sehr flott und sind eine wirkliche Verbesserung!!!!

Diese Fehlermeldung ist sicherlich eine Spezialität meiner Installation.
Ich bekomme noch immer diese Einträge im state.
DBD::mysql::st execute_array failed: executing 195 generated 3 errors at ./FHEM/93_DbLog.pm line 1221.
Ich bin mir sicher, dass diese im Zusammenhang mit Primary-Key Fehlern kommen, wenn gewisse Einträge nicht nicht in die DB geschrieben werden können,
weil sie dort bereits vorhanden sind. Da ich einen PK auf "Timestamp, device, reading" gelegt habe und manche Devices leider 2 Einträge zur selben Zeit
produzieren, kommt das manchmal vor.

Ist es dazu ausreichend, wenn ich in Zeile 921 und 1188 für einen Test
INSERT INTO
durch
INSERT IGNORE INTO
ersetze? Ich werde das jedenfalls für heute so testen!

schöne Grüße
Joe

Morgen Joe,

Ja genau, das sollte so passen.
Wünsche dir einen schönen Tag. Bei mir ruft die Arbeit ...

Grüße Heiko

Guten Morgen,

ich will das nicht noch mal alles quoten, daher der Verweis: https://forum.fhem.de/index.php/topic,64537.msg558617.html#msg558617 (https://forum.fhem.de/index.php/topic,64537.msg558617.html#msg558617)

Jemand eine Idee was da los ist? Tante Google hat mich nicht wirklich weiter gebracht :(

Die Datenlänge in DbLog für das Feld VALUE ist 64. Die Meldung liest sich so dass dies zu lang wäre für deine DB und spezielle Reading. Ist die Feldlänge für value in der DB auch auf 64 eingestellt ?

Die Werte habe ich gestern hochgestellt, ja... Weil ich die Meldung so interpretiert hatte.

Zitat von: Tedious am 11 Januar 2017, 11:53:25
Jemand eine Idee was da los ist? Tante Google hat mich nicht wirklich weiter gebracht :(

setz ein
show COLUMNS  from history;
und wenn du auch die current-tabelle verwendest zusätzlich noch ein
show COLUMNS  from current;

Als Ergebnis solltest Du etwas in der Form für beide Tabellen erhalten!


Field Type Null Key Default Extra
TIMESTAMP datetime NO PRI 0000-00-00 00:00:00
DEVICE varchar(64) NO PRI
TYPE varchar(32) YES
EVENT varchar(512) YES
READING varchar(64) NO PRI
VALUE varchar(32) YES
UNIT varchar(32) YES


Was ist das Ergebnis davon?
show variables  like 'STRICT_%';

Zitat von: JoeALLb am 11 Januar 2017, 13:44:17
setz ein

Code Auswählen Erweitern

show COLUMNS  from history;
und wenn du auch die current-tabelle verwendest zusätzlich noch ein

Code Auswählen Erweitern

show COLUMNS  from current;

Als Ergebnis solltest Du etwas in der Form für beide Tabellen erhalten!

Code Auswählen Erweitern


Field Type Null Key Default Extra
TIMESTAMP datetime NO PRI 0000-00-00 00:00:00
DEVICE varchar(64) NO PRI
TYPE varchar(32) YES
EVENT varchar(512) YES
READING varchar(64) NO PRI
VALUE varchar(32) YES
UNIT varchar(32) YES


Was ist das Ergebnis davon?

Code Auswählen Erweitern

show variables  like 'STRICT_%';

Wenn ich mich da mal zwischen drängeln darf. Bei mir sieht das nicht so aus wie bei Dir

MariaDB [fhem]> show COLUMNS  from history;
+-----------+--------------+------+-----+-------------------+-----------------------------+
| Field     | Type         | Null | Key | Default           | Extra                       |
+-----------+--------------+------+-----+-------------------+-----------------------------+
| TIMESTAMP | timestamp    | NO   |     | CURRENT_TIMESTAMP | on update CURRENT_TIMESTAMP |
| DEVICE    | varchar(32)  | YES  | MUL | NULL              |                             |
| TYPE      | varchar(32)  | YES  |     | NULL              |                             |
| EVENT     | varchar(512) | YES  |     | NULL              |                             |
| READING   | varchar(32)  | YES  |     | NULL              |                             |
| VALUE     | varchar(32)  | YES  |     | NULL              |                             |
| UNIT      | varchar(32)  | YES  |     | NULL              |                             |
+-----------+--------------+------+-----+-------------------+-----------------------------+
7 rows in set (0.00 sec)


Ne Idee was nun "besser" oder "schlechter" ist?

32 war die alte Spaltenbreite und wurde nunmehr auf 64 angeboben, daher sind alle Überprüfungen des Moduls ebenfalls auf 64 angehoben!

Also bitte verbreitere die Tabellen!

@Heiko:
Ich würde tatsächlich vorschlagen, beim init des Moduls internals zu generieren mit den Spaltenbreiten aus der Tabelle!
Ich erwarte zukünftig mehrere solcher Fehlermeldungen, und dadurch würden wir diese direkt erkennen.
Wennd as Auslesen in das internal nicht klappt, kann der Wert ja immer noch die Default-Breite annehmen.

Optimaler (für Später) könnten wir im STATE oder einem anderen Reading noch eine Warnung ausgeben: "Achtung, die Spaltenbreite ist kleiner als empfohlen, dies kann zu Fehlern beim Loggen führen"

Hi Joe, cooltux  ja scheint so. Aber was mich wirklich wundert ist dass in dem ausgangsmodul sowohl die breite als auch die Beschränkung der Felder beim Schreiben enthalten war und unverändert geblieben ist. Könnt ihr euch das zusammenreimen ? Ich nicht.  Hab jetzt erstmal keine Zeit mehr ... Evtl wieder am Abend.

Nein, ich auch nicht! Habe den Code des Moduls  bis vor einem Jahr zurück angeschaut, es war definitiv als Code enthalten,
aber gekürzt hat es bei mir dennoch nicht! Ich habe viele alte Einträge mit längeren Readings... (und manuell angepasst habe ich das Modul auch nie).

Mit den Feldlängen in der Log-Tabelle solltet Ihr modulseitig nicht beliebig rumspielen.

Zumindest nicht mit der Feldlänge für den DEVICE-Namen.
Es macht keinen Sinn, dieses Feld länger als 64 Zeichen zu machen.

Zitat von: betateilchen am 11 Januar 2017, 16:58:21
Es macht keinen Sinn, dieses Feld länger als 64 Zeichen zu machen.

Ich denke nicht, dass dies jemand|viele möchten. Die Hauptschwierigkeit sind im Moment die User mit der alten Breite von 32. Die können Fehlermeldungen erhalten, wenn sie plötzlich
Devices anlegen, deren Dateinamen länger sind...

Moin,

die Tabellen waren/sind alle so angelegt - ausser Device, das stand noch auf 32. Das habe ich jetzt geändert (exemplarisch).

ALTER TABLE `fhem`.`history`
CHANGE COLUMN `DEVICE` `DEVICE` VARCHAR(64) CHARACTER SET 'utf8' NULL DEFAULT NULL ;


3 4 17:46:53 show variables  like 'STRICT_%' 0 row(s) returned 0.110 sec / 0.000 sec

Liefert die Variablen-Abfrage.

Zitat von: DS_Starter am 11 Januar 2017, 00:10:05
schau mal ob für dich diese Hinweise hier gültig sind:

http://piwik.org/faq/troubleshooting/faq_183/
http://stackoverflow.com/questions/7942154/mysql-error-2006-mysql-server-has-gone-away

Hat leider keine Verbesserung gebracht. Den SQL Server habe ich auch nie umkonfiguriert. Die Meldung kommt erst seit dem Update Gestern...

Gruss, Xcoder

Hallo XCoder,

hast du diese Meldungen mit dem aktuellen DbLog auch dann wenn du in den asnchronen Mode wechselst (asyncMode=1) ?

Unabhängig davon habe ich für dich eine Testversion angefertigt.
Teste diese dann ebenfalls mit beiden Modi,d.h. synchronous bzw. asynchron.

Grüße
Heiko

Hallo Loredo,

in der angehängten Version habe ich die von dir gewünschte SplitFn-Variante mit eingebaut.
Schau mal ob es genau das ist was du möchtest.

Grüße
Heiko

Zitat von: Tedious am 11 Januar 2017, 17:48:45
die Tabellen waren/sind alle so angelegt - ausser Device, das stand noch auf 32. Das habe ich jetzt geändert (exemplarisch).

Eine wichtige Information fehlt: Die Fehlermeldung sollte jetzt weg sein?!?

Zitat von: DS_Starter am 11 Januar 2017, 23:59:42
in der angehängten Version habe ich die von dir gewünschte SplitFn-Variante mit eingebaut.
Schau mal ob es genau das ist was du möchtest.

Ja, sieht gut aus. Vielen Dank!
Vielleicht bei der Gelegenheit noch die Fehlergefahr verringern und prüfen, ob der Inhalt auch wirklich eine existierende Funktion ist, bevor sie ausgeführt wird:




if($defs{$device}{'.DbLog_splitFn'} && &$defs{$device}{'.DbLog_splitFn'}) {
    ...
}
  ...

if($modules{$dtype}{DbLog_splitFn} && &$modules{$dtype}{DbLog_splitFn}) {
    ...
}


Morgen Julien und Joe,

Ja deinen Hinweis sehe ich mit vor, danke !
Ich warte noch auf die Rückmeldung von xcoder bzgl. Seiner Testversion und baue dann eine allgemeine neue Version für den Test und check-in.
Mal schauen wie sein Ergebnis ausfällt.

Schönen Tag,
Heiko

Hallo zusammen,

warum nutzt ihr für die modulweite DbLog_splitFn nicht die Funktion CallFn() (https://svn.fhem.de/trac/browser/trunk/fhem/fhem.pl#L3278) um modul-Funktionen aufzurufen? Man muss ja das Rad nicht jedesmal neu erfinden.

CallFn($hash->{NAME}, "DbLog_splitFn", $event)

Ich persönlich würde diese Funktion dann erweitern um auch definitionsbezogene Funktionen aufzurufen. Momentan startet CallFn() nur Funktionen die in $modules{$hash->{TYPE}} definiert sind. Diese könnte man ja einfach erweitern um zuerst definitionsbezogene Funktionen unter $hash zu verwenden analog wie es Loredo vorgeschlagen hat. Falls nicht definiert, wird dann wie bisher die Funktion unter $modules verwendet.

Dadurch wäre es einheitlich für alle Module verfügbar und keine Insellösung.

Viele Grüße

Markus

Hi Markus,
ich habe das noch nicht wirklich verstanden... Um CallFn nutzen zu können, was muss im Modul DBLog rein, was in alle andere Module?
Aktuell ist es so das pro Modul die DbLogSplitfn implementiert sein muss/sollte da nur das Modul selbst weiß wie die Readings aufgebaut sind. Das DBLog Modul ruft dann diese SplitFn in den Modulen auf wenn ein Reading aus diesem Modul eintrifft

Zitat von: Tobias am 12 Januar 2017, 10:26:46
Um CallFn nutzen zu können, was muss im Modul DBLog rein, was in alle andere Module?

Es geht hierbei nur um DbLog selber. Alle Module, welche eine DbLog_splitFn in der Initialize-Funktion setzen sind ja bereits korrekt.

Insbesondere für DbLog selber vereinfacht dies eine Menge, da du das gesamte If-Konstrukt in Zeile 405 (https://svn.fhem.de/trac/browser/trunk/fhem/FHEM/93_DbLog.pm?rev=13039#L405) entfernen kannst, da sich CallFn um alles nötige kümmert.

Du rufst in Zeile 405 einfach nur CallFn() samt Name der entsprechenden Definition, dem Namen der Funktion ("DbLog_splitFn") und die Argumente, welche die splitFn benötigt ($event, $device):


($reading, $value, $unit) = CallFn($device, "DbLog_splitFn", $event, $device);

# undef bedeutet, Modul stellt keine DbLog_splitFn bereit
if(defined($reading))
{
   return ($reading, $value, $unit);
}


Zitat von: Tobias am 12 Januar 2017, 10:26:46
Aktuell ist es so das pro Modul die DbLogSplitfn implementiert sein muss/sollte da nur das Modul selbst weiß wie die Readings aufgebaut sind. Das DBLog Modul ruft dann diese SplitFn in den Modulen auf wenn ein Reading aus diesem Modul eintrifft

Genau, nur musst du nun nicht selbst alles prüfen und sicherstellen, ob die Funktion existiert usw. Das erledigt alles CallFn() für dich. sofern die entsprechende Funktion von dem zugrundeliegenden Modul von $device bereitgestellt wird, wird diese ausgeführt, andernfalls wird undef zurückgegeben.

Loredo bat ja darum, definitionsbezogen die splitFn definieren zu können. Dies kann durch einen sehr kleinen Patch in CallFn() erreicht werden. Damit würde dieses Feature im gesamten FHEM zur Verfügung stehen.

Ich möchte gerne vermeiden, das mit der ursprünglichen Idee wieder Insellösungen geschaffen werden.

Du findest CallFn() in fhem.pl hier: https://svn.fhem.de/trac/browser/trunk/fhem/fhem.pl#L3278

Dort kannst du sehen, was CallFn genau macht.

Gruß
Markus

Zitat von: JoeALLb am 12 Januar 2017, 08:26:23
Eine wichtige Information fehlt: Die Fehlermeldung sollte jetzt weg sein?!?

Das ist in der Tat ein wichtiger Punkt :)

Nein, sind sie leider nicht!

2017-01-12 12:08:40 Revolt Revolt_38c3 P:   8.3 E: 395.05 V: 234 C:   0.08 F: 50 Pf: 0.46
2017-01-12 12:08:41 DbLog myDbLog connected
2017-01-12 12:08:41 DbLog myDbLog connected
2017-01-12 12:08:41 DbLog myDbLog connected
2017-01-12 12:08:41 DbLog myDbLog DBD::mysql::st execute_array failed: MySQL server has gone away [err was 2006 now 2000000000] executing 1 generated 1 errors at ./FHEM/93_DbLog.pm line 946.
2017-01-12 12:08:41 DbLog myDbLog DBD::mysql::st execute_array failed: Data too long for column 'VALUE' at row 1 [err was 1406 now 2000000000] executing 1 generated 1 errors at ./FHEM/93_DbLog.pm line 946.
2017-01-12 12:08:41 readingsGroup ZE.Batterie LaCrosse_0D.battery:  2017-01-12 12:08:42 LaCrosse LaCrosse_0D battery: ok
2017-01-12 12:08:42 LaCrosse LaCrosse_0D temperature: 16.6
2017-01-12 12:08:42 LaCrosse LaCrosse_0D humidity: 39
2017-01-12 12:08:42 LaCrosse LaCrosse_0D T: 16.6 H: 39 D: 2.6
2017-01-12 12:08:42 LaCrosse LaCrosse_0D dewpoint: 2.6
2017-01-12 12:08:43 DbLog myDbLog connected
2017-01-12 12:08:43 DbLog myDbLog connected
2017-01-12 12:08:43 DbLog myDbLog connected
2017-01-12 12:08:43 DbLog myDbLog DBD::mysql::st execute_array failed: MySQL server has gone away [err was 2006 now 2000000000] executing 1 generated 1 errors at ./FHEM/93_DbLog.pm line 946.
2017-01-12 12:08:43 DbLog myDbLog DBD::mysql::st execute_array failed: Data too long for column 'VALUE' at row 1 [err was 1406 now 2000000000] executing 1 generated 1 errors at ./FHEM/93_DbLog.pm line 946.

Zitat von: Tedious am 12 Januar 2017, 12:09:29
Nein, sind sie leider nicht!

Nun ok, da steht eindeutig drinnen, dass die Breite der Spalte "Value" zu klein ist...
Im Screenshot vorhin sieht man dass er bei dir 64 ist,
lt.
https://svn.fhem.de/trac/browser/trunk/fhem/contrib/dblog/db_create_mysql.sql
ist die aktuelle Breite 128. (die ich persöhnlich etwas für übertrieben halte ;-) )

Wie es scheint hast Du Module, die solch breite Value-Einträge erzeugen....

Das Beste ist wohl, Du verbreiterst diese Spalte ebenfalls.

Joe

@Heiko:
Noch zwei Wünsche hätte ich ;-)

1. Könnten wir ein "set DbLog flushCache" in Zukunft ergänzen?
2. Könnten wir für PlotAbriss eine direkte Schnittstelle zu DbLog bekommen, in der ich auch das datetime einstellen kann?
   https://wiki.fhem.de/wiki/Plot-Abriss_vermeiden

in DbRep gibt es ja schon die Möglichkeit des "inserts", nun möchte ich aber nicht für jegliches Device ein DbRep-Device anlegen.
Wäre es denkbar, ein

set DbLog addLog '2016-01-11', '00:00', 'DEVICE', 'READING', 'VALUE' wobei addCache auch denkbar wäre?

Dann könnte ich das direkt und ohne myUtils99 nutzen. Im Moment habe ich immer die Sorge, was passiert, wenn der Trigger länger als 1s dauert.
(zB da mein System gerade ausgelastet ist)
Dann bekomme ich keinen Eintrag um 23:59:59, sondern um 00:00:01, was mir nicht weiter hilft!

Edit1: zweiter Wunsch ergänzt.

Hallo,

nur zur Info, auch bei mir kommt immer beim reopen der bekannte Fehler, unabhängig ob asyncMode 1 oder 0:
2017.01.12 17:46:45 3: Connecting to database mysql:database=fhem;host=localhost;port=3306 with user Reinhard
2017.01.12 17:46:45 3: Connection to db mysql:database=fhem;host=localhost;port=3306 established for pid 1323
2017.01.12 17:46:45 3: Connecting to database mysql:database=fhem;host=localhost;port=3306 with user Reinhard
2017.01.12 17:46:45 3: Connection to db mysql:database=fhem;host=localhost;port=3306 established for pid 1323
2017.01.12 17:46:45 3: Connection to db mysql:database=fhem;host=localhost;port=3306 established
2017.01.12 17:46:45 2: DbLog DBLogging -> Error: DBD::mysql::st execute_array failed: MySQL server has gone away [err was 2006 now 2000000000]
executing 1 generated 1 errors at ./FHEM/93_DbLog.pm line 951.

2017.01.12 17:46:45 3: Connecting to database mysql:database=fhem;host=localhost;port=3306 with user Reinhard
2017.01.12 17:46:45 3: Connection to db mysql:database=fhem;host=localhost;port=3306 established for pid 1323
2017.01.12 17:46:45 3: Connection to db mysql:database=fhem;host=localhost;port=3306 established
2017.01.12 17:46:45 3: Connection to db mysql:database=fhem;host=localhost;port=3306 established
2017.01.12 17:46:45 3: DBLogging_Reopen: Reopen executed.

Die Datenbank wird aber auch bei mir korrekt gefüllt.
Verwende derzeit "93_DbLog.pm 13039 2017-01-10 22:19:58Z"

Der andere Fehler "begin_work failed" tritt nicht mehr auf.

Gruß Reinhard

Hallo zusammen, hallo Reinhard,

ich bin der Meldung

mysql::st execute_array failed: MySQL server has gone away [err was 2006 now 2000000000]

auf der Spur.

Werde in Kürze eine Testversion bereitstellen, die dieses Problem beheben soll. Braucht nicht mehr gepostet werden.

VG
Heiko

Zitat von: JoeALLb am 12 Januar 2017, 14:06:59

Wie es scheint hast Du Module, die solch breite Value-Einträge erzeugen....

Das Beste ist wohl, Du verbreiterst diese Spalte ebenfalls.

Joe

Das ist ja das spannende - habe ich nicht ;) Wenn ich mir die Eventlogs anschaue passiert das scheinbar immer wenn ein LacCrosse oder ein Revolt schreibt, die "langen" aus dem Sysmon laufen sauber durch.

Ich hatte heute Mittag ein Update gemacht, seit dem ist scheinbar Ruh' im grünen Kakadu. Aber ich bin da noch verhalten optimistisch, das hatte ich gestern auch schon mal..

Zitat von: Markus Bloch am 12 Januar 2017, 09:26:23
Ich persönlich würde diese Funktion dann erweitern um auch definitionsbezogene Funktionen aufzurufen. Momentan startet CallFn() nur Funktionen die in $modules{$hash->{TYPE}} definiert sind. Diese könnte man ja einfach erweitern um zuerst definitionsbezogene Funktionen unter $hash zu verwenden analog wie es Loredo vorgeschlagen hat. Falls nicht definiert, wird dann wie bisher die Funktion unter $modules verwendet.

Dadurch wäre es einheitlich für alle Module verfügbar und keine Insellösung.

Bin ich absolut für zu haben. Wer checkt die Zeile ein? ;)

ZitatBin ich absolut für zu haben. Wer checkt die Zeile ein?

Mach ich gleich mit. Habe die nächste Version fast fertig. Noch ein paar Tests ....

Ich glaube formell sollte das besser Rudi überlassen werden, aber ich kenne die neue Aufgabenteilung bei den Officials nicht...

Das war ein Mißverständnis ... ich meinte natürlich jetzt im DbLog.

Hallo zusammen,

in der hier angehängten Version V2.9 sind folgende Änderungen enthalten:

* die Meldung "mysql::st execute_array failed: MySQL server has gone away [err was 2006 now 2000000000]" sollte eliminiert sein.

* neuer Befehl "set ... flushCache"
   im asynchronen Mode kann der Inhalt des Cache gelöscht werden. Joe, dein Wunsch 1 ist somit erledigt ;-)
   
* neuer Befehl "set ... syncCache"
   im asynchronen Mode wird der Cacheinhalt in die Datenbank weggeschrieben. Der interne Timer wird dabei neu gesetzt.
   Der Befehl kann nützlich sein um manuell bzw. von außen z.B. über ein AT den asynchronen Prozess neu zu initiieren
   falls nötig/gewünscht.

* die SplitFn habe ich so wie von Markus beschrieben implementiert

Bitte testet diese Version, insbesondere die User welche die "MySQL server has gone away"-Meldung erhalten.
FHEM Restart ist notwendig !

@Markus, Loredo ... schaut mal ob das so passt und mit dem kleinen Patch von Markus dann auch für Devices klappt.
Markus ... ich habe

if(defined($reading))
{
   return ($reading, $value, $unit);
}

geändert in

if($reading)
{
   return ($reading, $value, $unit);
}

Sonst wurden READING, VALUE, UNIT leer in die DB geschrieben wenn SplitFn im Eventsender nicht definiert ist.

viele Grüße
Heiko

Zitat von: Loredo am 12 Januar 2017, 21:35:08
Ich glaube formell sollte das besser Rudi überlassen werden, aber ich kenne die neue Aufgabenteilung bei den Officials nicht...

Die Zuständigkeiten bei der Entwicklung von FHEM ist unverändert. Änderungen in fhem.pl werden durch Rudi durchgeführt. Da es deine Anforderung ist, würde ich Dich bitten, einen entsprechenden Patch für CallFn() in FHEM Development einzureichen.  8) Wenn das OK für dich ist.

Viele Grüße

Markus

Zitat von: DS_Starter am 12 Januar 2017, 22:16:21
* neuer Befehl "set ... flushCache"
   im asynchronen Mode kann der Inhalt des Cache gelöscht werden. Joe, dein Wunsch 1 ist somit erledigt ;-)

Sehr schön, vielen vielen Dank!! Ich benötige das um Mitternacht um eine Berechnung über Stored Procedures durchzuführen.... und die macht nur Sinn wenn die Werte in der DB sind :D

Zitat von: DS_Starter am 12 Januar 2017, 22:16:21in der hier angehängten Version V2.9 sind folgende Änderungen enthalten:

* die Meldung "mysql::st execute_array failed: MySQL server has gone away [err was 2006 now 2000000000]" sollte eliminiert sein.

Sorry, hatte jetzt erst Zeit mich damit zu befassen. Die gone away Meldung erscheint mit V2.9 ach bei wildesten SVG Plot Orgien nicht mehr (synchron und asynchron).

Vielen Dank und Gruss,
Xcoder

Guten Morgen,

Danke für die Rückmeldung xcoder ... Sehr schön !

@Joe ... Ich denke syncCache wäre die für dich richtige Funktion. FlushCache löscht lediglich den Cache 😉

Grüße
Heiko

Zitat von: Markus Bloch am 12 Januar 2017, 22:30:51
Da es deine Anforderung ist, würde ich Dich bitten, einen entsprechenden Patch für CallFn() in FHEM Development einzureichen.  8) Wenn das OK für dich ist.

Guckst du hier (https://forum.fhem.de/index.php/topic,64741.msg560098.html#msg560098).
Mal schauen, wie/ob sich Rudi entscheidet das allgemein aufzunehmen. Derzeit sieht es eher so aus, als wenn wir hier zur moduleigenen Lösung zurückkehren sollen/müssen (ggf. mit eigener Funktion).

Hi Loredo,

Ich werde in v2.9 noch die Commandref ergänzen und werde dabei wohl auch die beiden neuen Funktionen FlushCache und syncCache wahrscheinlich etwas umbenennen. Um die Abgrenzung beider Funktionen besser in der Begrifflichkeit zu manifestieren wird aus FlushCache dann resetcache und aus syncCache dann FlushCache so wie Joe es wohl ursprünglich verstanden hatte.

Bei der Gelegenheit werde ich die Entscheidung bzgl. Splitfn auch mit berücksichtigen wenn es eine gibt. Mal schauen.

VG
Heiko

Gibt es eine optimale Datenmenge, wann der Cache geleert werden sollte?
Könnte der Cache bei dieser Menge nicht automatisch geschrieben werden, statt ein Intervall zu nutzen?

Kann ich davon ausgehen, dass der Cache beim shutdown geleert wird?

Hallo,

auch bei mir sind mit der Version 2.9 die "MySQL server has gone away" Fehler verschwunden.
Test erfolgte mit "asyncMode" 0 und 1.

Danke für eure Mühe
Reinhard

Hallo Reinhard,

danke auch für deine positive Rückmeldung !

VG
Heiko

Hallo Ellert,

ich beginne deine Fragen mal von hinten zu beantworten ...

ZitatKann ich davon ausgehen, dass der Cache beim shutdown geleert wird?

Ja, kannst du. Die entsprechende Schreibfunktion wird beim Shutdown aufgerufen.
Allerdings würde ich das immer schon vorhandene Attribut "shutdownWait" setzen. Ich habe es bei mir
auf 2s gesetzt und gute Erfahrungen damit gemacht. Die SQL-Zeit im asynchronen Modus liegt bei mir so
zwischen ca. 0,03 - 0,09s (kannst du mit Attr "showproctime" anzeigen lassen).
Du kannst ja mal schauen wie es bei dir damit aussieht.

ZitatKönnte der Cache bei dieser Menge nicht automatisch geschrieben werden, statt ein Intervall zu nutzen?

Das hatte ich vor mit als Nächstes zu implementieren. Wahrscheinlich werde ich es so machen, dass der Schreibvorgang in
die DB beim Erreichen einer der gesetzten Grenzwerte, also entweder die gwünschte Anzahl der Einträge im Cache oder das eingestellte
"syncInterval" gestartet wird.
Das hätte auch den positiven Nebeneffekt, dass der Cache auf jeden Fall in die DB weggeschrieben wird falls der Timer aus welchen Gründen
auch immer, mal versagen sollte.

ZitatGibt es eine optimale Datenmenge, wann der Cache geleert werden sollte?

Darüber habe ich mir eigentlich noch keine Gedanken gemacht. Das hängt IMHO einerseits von den Wünschen des Users ab,
wie schnell er seine Daten aktuell in der DB haben möchte und andererseits von den Systemressourcen.
Ich habe mich bei der Erstellung der asynchronen Modes davon leiten lassen, eine weitgehende Entflechtung des Schreibvorgangs
der Daten in die DB von den anderen Abläufen im FHEM zu erreichen um die allgemeine Performance zu steigern.
Man müßte vllt. mal einen Test machen wie schnell eine sehr große aufgelaufene Datenmenge (vllt. nach 1 Stunde)in die DB weggeschrieben
wird. Habe ich noch nicht probiert.
Aber angenommen hatte ich, dass die Schreibyklen im Normalfall so bei 60s +/- liegen würden.
In beiden Modi (synchron bzw. asynchron) werden die vorhandenen Daten als Block in die DB geschrieben.

Viele Grüße
Heiko

Zitat von: DS_Starter am 13 Januar 2017, 13:16:31
[...] Abgrenzung beider Funktionen besser in der Begrifflichkeit zu manifestieren wird aus FlushCache dann resetcache und aus syncCache dann FlushCache so wie Joe es wohl

in FHEM hat es sich eingebürgert, mit kleinen Buchstaben zu beginnen und zwischendrinnen einen Großbuchstaben einzubinden.
Zusätzlich habe ich auch nochmal über den Namen nachgedacht und würde folgende Vorschlagen, da diese eindeutig sind:
# commitCache
# purgeCache

(Ich kann aber mit den anderen Namen selbverständlich auch sehr gut leben!)

Hi Joe,

ja, das mache ich auch. Von meinem Mobilteil geschriebene Texte werden oft durch die Texterkennung/Autokorrektur verfälscht.
Da kommen manchmal merkwürdige Dinge an ...

VG

Zitat von: DS_Starter am 13 Januar 2017, 16:55:32
Aber angenommen hatte ich, dass die Schreibyklen im Normalfall so bei 60s +/- liegen würden.
In beiden Modi (synchron bzw. asynchron) werden die vorhandenen Daten als Block in die DB geschrieben.

Ich habe mal mit 30 Minuten getestet und dabei 3600 Datensätze im Cache produziert.
Diese wurden in 1,2s in die DB geschrieben, auf einem eher langsamen Watt-optimierten Server (jedoch mit ssd).
Wenn ich also mit 300ms Speicherzeit alle 10 Minuten rechne, habe ich viel gewonnen und das System reagiert deutlich schneller.

Bei zu vielen Datensätzen hätte ich tatsächlich mal die Sorge, sie zu verlieren, wenn irgendein Modul abschmiert oder zu viel Speicher
nutzen möchte, aber 10 Minuten ist für mich ein durchaus denkbarer Wert wür eine noch kleinere RPI-Installation, die die Daten auf eine SD-Karte schreibt.
Da diese SD-Karten nicht gerne viele Schreibvorgänge mögen, wurde hier bisher immer eher FileLog empfohlen. Ich habe mit DbLog jedoch sehr gute und zuverlässige Erfahrungen gemacht!

Hi!

Zitat von: JoeALLb am 13 Januar 2017, 17:01:09
# commitCache
# purgeCache

(Ich kann aber mit den anderen Namen selbverständlich auch sehr gut leben!)

Um ehrlich zu sein finde gerade flushCache in seiner bisherigen "Belegung" ausgesprochen unglücklich und irreführend. Autoflush in Perl vernichtet ja auch keine Daten. Insofern wäre ich auch mit purgeCache wesentlich glücklicher und ich glaube, damit erspart man sich auch viel Supportaufwand im Forum.

Patrick

Zitat von: CoolTux am 11 Januar 2017, 14:05:15
Wenn ich mich da mal zwischen drängeln darf. Bei mir sieht das nicht so aus wie bei Dir

Code Auswählen Erweitern


MariaDB [fhem]> show COLUMNS  from history;
+-----------+--------------+------+-----+-------------------+-----------------------------+
| Field     | Type         | Null | Key | Default           | Extra                       |
+-----------+--------------+------+-----+-------------------+-----------------------------+
| TIMESTAMP | timestamp    | NO   |     | CURRENT_TIMESTAMP | on update CURRENT_TIMESTAMP |
| DEVICE    | varchar(32)  | YES  | MUL | NULL              |                             |
| TYPE      | varchar(32)  | YES  |     | NULL              |                             |
| EVENT     | varchar(512) | YES  |     | NULL              |                             |
| READING   | varchar(32)  | YES  |     | NULL              |                             |
| VALUE     | varchar(32)  | YES  |     | NULL              |                             |
| UNIT      | varchar(32)  | YES  |     | NULL              |                             |
+-----------+--------------+------+-----+-------------------+-----------------------------+
7 rows in set (0.00 sec)


Ne Idee was nun "besser" oder "schlechter" ist?

Bei mir sieht die Datenbank so aus:
mysql> show COLUMNS  from history;
+-----------+--------------+------+-----+-------------------+-----------------------------+
| Field     | Type         | Null | Key | Default           | Extra                       |
+-----------+--------------+------+-----+-------------------+-----------------------------+
| TIMESTAMP | timestamp    | NO   | MUL | CURRENT_TIMESTAMP | on update CURRENT_TIMESTAMP |
| DEVICE    | varchar(64)  | YES  | MUL | NULL              |                             |
| TYPE      | varchar(64)  | YES  |     | NULL              |                             |
| EVENT     | varchar(512) | YES  |     | NULL              |                             |
| READING   | varchar(64)  | YES  | MUL | NULL              |                             |
| VALUE     | varchar(128) | YES  |     | NULL              |                             |
| UNIT      | varchar(32)  | YES  |     | NULL              |                             |
+-----------+--------------+------+-----+-------------------+-----------------------------+
7 rows in set (0.00 sec)

Zitat von: DS_Starter am 13 Januar 2017, 13:16:31
Bei der Gelegenheit werde ich die Entscheidung bzgl. Splitfn auch mit berücksichtigen wenn es eine gibt. Mal schauen.

Rudi hat mit Revision 13053 & 13054 eine Abwandlung von CallFn() eingecheckt, welche genau die von Loredo gewünschte Vorgehensweise umsetzt.

Anstatt CallFn() müsstest du nun CallInstanceFn() verwenden. Die Syntax für Parameter und Rückgabewerte sind identisch.

Ich habe beide Funktionen im Wiki beschrieben:
https://wiki.fhem.de/wiki/DevelopmentModuleAPI#CallInstanceFn
https://wiki.fhem.de/wiki/DevelopmentModuleAPI#CallFn

Ich denke das ist ein guter Kompromis für alle.

@Joe, Patrick ... nehme eure Anregung gerne auf

Zitat
# commitCache  -> schreiben in DB + leeren Cache
# purgeCache -> löschen Cache

und sehe das so vor. Habe mich auch mit der Begriffsfindung schwer getan.

@Markus, danke für die Info. baue ich so ein.

Grüße
Heiko

Zitat von: JoeALLb am 13 Januar 2017, 17:06:14
Ich habe mal mit 30 Minuten getestet und dabei 3600 Datensätze im Cache produziert.
Diese wurden in 1,2s in die DB geschrieben, auf einem eher langsamen Watt-optimierten Server (jedoch mit ssd).
Wenn ich also mit 300ms Speicherzeit alle 10 Minuten rechne, habe ich viel gewonnen und das System reagiert deutlich schneller.

Bei zu vielen Datensätzen hätte ich tatsächlich mal die Sorge, sie zu verlieren, wenn irgendein Modul abschmiert oder zu viel Speicher
nutzen möchte, aber 10 Minuten ist für mich ein durchaus denkbarer Wert wür eine noch kleinere RPI-Installation, die die Daten auf eine SD-Karte schreibt.
Da diese SD-Karten nicht gerne viele Schreibvorgänge mögen, wurde hier bisher immer eher FileLog empfohlen. Ich habe mit DbLog jedoch sehr gute und zuverlässige Erfahrungen gemacht!

Ich habe mal auf meinen Cubie mit 30min und 1800 Datensätze ca 51Sekunden zum wegschreiben benötigt.
Ich habe aber vermutlich zugroßen Index-Overheat.

Zitat von: stromer-12 am 13 Januar 2017, 19:57:26
Ich habe mal auf meinen Cubie mit 30min und 1800 Datensätze ca 51Sekunden zum wegschreiben benötigt.
Ich habe aber vermutlich zugroßen Index-Overheat.

Welche Festplatte?
Datenbank mit UTF8 oder mit normalem Zeichensatz angelegt?
MyISAM oder INNODB?
MySQL oder MariaDB?

Ich habe einiges getestet, um die Performance halbwegs ordentlich bei kleinem Ressourcenverbrauch hinzubekommen.
Der RPI 1 hatte einfach nicht viel Leistung :D

@Heiko: Sorry für die ganzen Wünsche... ich schuld Dir schon jede Menge Bier (oder Kaffee ;-))

Wunsch#3:
cacheEvents = 2
könnte immer nur ein Event generieren, wenn die Werte in die DB gespeichert werden. (Also zum Zeitpunkt, als CacheUsage am Maximum ist, also NextSync)

Dadurch kann ich die sql_processing_time mit den abzuspeichernden Datensätzen (CacheUsage ) mitloggen, um zu sehen, wie lange und wie viele Datensätze  die DB so im Schnitt abspeichert.

Zitat von: JoeALLb am 13 Januar 2017, 22:39:55
Welche Festplatte?
Datenbank mit UTF8 oder mit normalem Zeichensatz angelegt?
MyISAM oder INNODB?
MySQL oder MariaDB?

Ich habe einiges getestet, um die Performance halbwegs ordentlich bei kleinem Ressourcenverbrauch hinzubekommen.
Der RPI 1 hatte einfach nicht viel Leistung :D

Steht doch in meiner Signatur, Cubietruck mit MYSQL und Innodb auf SSD.

Hi,

ich bin mir nicht sicher, ob mein Problem am Ende auch auf das dblog Update zurückzuführen ist.

Ich nutze dblog mit postgresql.

Habe ein neues SVG Plot erstellt (dieses editiere ich ausschließlich manuell) mit dem ich mir die erkannte Bewegung meiner IP Kameras darstellen lassen möchte, habe dafür in fhem jeweils einen entsprechenden dummy dessen state ich über einen externen alarm server bei Bewegung jeweils auf 0 oder 1 setzen lasse.

Für diese neu erstellten dummy werden mir jedoch keine Werte in dem SVG angezeigt, daher übertrage ich per notify zusätzlich noch den jeweiligen state des dummys in ein neues reading "bewegung" und habe dieses in meine dblog definition aufgenommen.

Weiterhin werden mir jedoch keine Werte im SVG angezeigt, klicke ich auf den Devicenamen in der SVG Grafik erhalte ich folgende Fehlermeldung svg.js line 108:TypeError: selNode is undefined.

Dblog habe ich mit verbose mitloggen lassen und bin der Meinung, dass dieser Eintrag signalisiert, dass die Events in die Datenbank geschrieben werden?

2017.01.13 23:02:02.813 4: DbLog myDbLog -> ################################################################
2017.01.13 23:02:02.813 4: DbLog myDbLog -> ###              start of new Logcycle                       ###
2017.01.13 23:02:02.813 4: DbLog myDbLog -> ################################################################
2017.01.13 23:02:02.814 4: DbLog myDbLog -> amount of events received: 1 for device: dummy_bewegung_kamera_garten                  _hinten
2017.01.13 23:02:02.814 4: DbLog myDbLog -> check Device: dummy_bewegung_kamera_garten_hinten , Event: 0


Meine Datenbank läuft im dblogtype current/history.

Meine dblog Definition in Fhem (gekürzt):
/opt/fhem/db.conf (.*:(bewegung|loadpct|bcharge|timeleft).*)|(Heizungspumpe_A:o.*)|(Heizungspumpe_B:o.*)

Irgendwelche Hinweise?

Greetz
Eldrik

Hi eldrik,

der Logeintrag

Zitat2017.01.13 23:02:02.814 4: DbLog myDbLog -> check Device: dummy_bewegung_kamera_garten_hinten , Event: 0

sagt lediglich aus dass DbLog den event empfangen hat und nun bewertet (DbLogExclode usw.)

Wenn der Event geloggt werden soll, findest du darunter dann noch eine Zeile mit added:

DbLog LogDB -> added event - Timestamp: 2017-01-14 09:38:33, Device: sysmon.....

Ansonsten ist DbLog der Meinung dass du diesen Event nicht loggen möchtest aufgrund deiner Vorgaben.

Wenn Events (und wieviele in welche Tabelle) in die DB geschrieben werden siehst du mit verbose 5 in diesem Block:


2017.01.14 09:39:37.205 5: DbLog LogDB -> ################################################################
2017.01.14 09:39:37.205 5: DbLog LogDB -> ###              New database processing cycle               ###
2017.01.14 09:39:37.205 5: DbLog LogDB -> ################################################################
2017.01.14 09:39:37.205 5: DbLog LogDB -> MemCache contains 22 entries to process
2017.01.14 09:39:37.205 5: DbLog LogDB -> MemCache contains: 2017-01-14 09:38:33|sysmon|SYSMON|swap: Total: 1293.00 MB, Used: 64.54 MB,  4.99 %, Free: 1228.45 MB|swap|Total: 1293.00 MB, Used: 64.54 MB,  4.99 %, Free: 1228.45 MB|
.....
2017.01.14 09:39:37.249 5: DbLog LogDB -> 22 of 22 events successfully inserted into table history
2017.01.14 09:39:37.252 5: DbLog LogDB -> DbLog_PushAsync finished
2017.01.14 09:39:37.260 5: DbLog LogDB -> Start DbLog_PushAsyncDone


Schau mal ob du damit weiterkommst.
Ich stelle gleich noch eine neue Version hier ein. Eventuell magst du die dann gleich verwenden.

EDIT: Der Block "New database processing cycle" wird im asynchronen mode erzeugt !

Grüße
Heiko

Guten Morgen zusammen,

anbei die V2.9.1. Sie enthält neben der Ergänzung der Commandref noch die folgenden Anpassungen:

* flushCache wurde zu purgeCache umbenannt
* syncCache wurde zu commitCache umbenannt
* die Umstellung der SplitFn gemäß #281
* das Attribut CacheEvents kennt die Werte 0,1 und 2
   * cacheEvents=1: es werden Events für das Reading CacheUsage erzeugt wenn ein Event zum Cache hinzugefügt wurde.
   * cacheEvents=2: es werden Events für das Reading CacheUsage erzeugt wenn im asynchronen Mode der Schreibzyklus in die
                   Datenbank beginnt. CacheUsage enthält zu diesem Zeitpunkt die Anzahl der in die Datenbank zu schreibenden
               Datensätze.
               
@Joe, gute Idee.  Diese Unterscheidung reduziert nebenbei die CacheUsage-Events wenn man sie einschaltet (Bier ist nicht so mein
Fall, aber gegen einen guten Tropfen schottischen Singlemalt habe ich nichts einzuwenden  ;) )

Ich checke die Version im Laufe des Tages ein damit sie morgen per Update zur Verfügung steht.
Wenn ihr sie heute noch verwenden wollt, achtet bitte darauf dass die fhem.pl aktualisiert ist (heute früh), da sie eine neue
benötigte Funktion enthält.

@Loredo, schau mal ob deine Wünsche damit nun funktionieren.

viele Grüße
Heiko

Zitat von: DS_Starter am 14 Januar 2017, 09:55:03
@Joe [...] aber gegen einen guten Tropfen schottischen Singlemalt habe ich nichts einzuwenden  ;) )

Talisker ist seit der Hochzeitsreise unsere 1. Wahl. Die Verkostung dort war die Beste ;-)
Schick mal deine Adresse per PN....!

Zitat von: DS_Starter am 14 Januar 2017, 09:49:07
Hi eldrik,

der Logeintrag

sagt lediglich aus dass DbLog den event empfangen hat und nun bewertet (DbLogExclode usw.)

Wenn der Event geloggt werden soll, findest du darunter dann noch eine Zeile mit added:

Code Auswählen Erweitern

DbLog LogDB -> added event - Timestamp: 2017-01-14 09:38:33, Device: sysmon.....

Ansonsten ist DbLog der Meinung dass du diesen Event nicht loggen möchtest aufgrund deiner Vorgaben.

Wenn Events (und wieviele in welche Tabelle) in die DB geschrieben werden siehst du mit verbose 5 in diesem Block:

Code Auswählen Erweitern


2017.01.14 09:39:37.205 5: DbLog LogDB -> ################################################################
2017.01.14 09:39:37.205 5: DbLog LogDB -> ###              New database processing cycle               ###
2017.01.14 09:39:37.205 5: DbLog LogDB -> ################################################################
2017.01.14 09:39:37.205 5: DbLog LogDB -> MemCache contains 22 entries to process
2017.01.14 09:39:37.205 5: DbLog LogDB -> MemCache contains: 2017-01-14 09:38:33|sysmon|SYSMON|swap: Total: 1293.00 MB, Used: 64.54 MB,  4.99 %, Free: 1228.45 MB|swap|Total: 1293.00 MB, Used: 64.54 MB,  4.99 %, Free: 1228.45 MB|
.....
2017.01.14 09:39:37.249 5: DbLog LogDB -> 22 of 22 events successfully inserted into table history
2017.01.14 09:39:37.252 5: DbLog LogDB -> DbLog_PushAsync finished
2017.01.14 09:39:37.260 5: DbLog LogDB -> Start DbLog_PushAsyncDone


Schau mal ob du damit weiterkommst.
Ich stelle gleich noch eine neue Version hier ein. Eventuell magst du die dann gleich verwenden.

EDIT: Der Block "New database processing cycle" wird im asynchronen mode erzeugt !

Grüße
Heiko

Hi,
das Problem ist dieser Thematik einzuordnen https://forum.fhem.de/index.php/topic,28017.15.html (setreading erzeugt kein Event...) aber der Hinweis, auf die korrekte dblog Protokollierung, die für einen geloggten Eintrag steht hat mich auf die richtige Spur gebracht, danke!

Greetz
Eldrik

Zitat von: stromer-12 am 13 Januar 2017, 19:57:26
Ich habe mal auf meinen Cubie mit 30min und 1800 Datensätze ca 51Sekunden zum wegschreiben benötigt.
Ich habe aber vermutlich zugroßen Index-Overheat.

Gerade gesehen, ich hatte die Tage auf Current /History gestellt gehabt.

Edith: Nur mit History sind es knapp 2 Sekunden

Zitat von: stromer-12 am 14 Januar 2017, 13:29:40
Edith: Nur mit History sind es knapp 2 Sekunden

51 zu 2 Sekunden... das ist nicht gut ;-)
Ist das Reproduzierbar?

Generell ist die Current-Funktion nicht optimal gelöst, da ließe sich sicherlich noch einiges Optimieren, aber wer möchte da schon so viel zeit hineinstecken?!?
Vorallem da ich denke, dass die meisten Advanced-User dies abschalten!

Folgende Ansätze zum Verbessern sehe ich dort im Moment:
# innsert ignore anstatt getrenntes insert und anschließendes update
# aussortieren doppelter Eintrage aus dem Cache vor dem Insert in die langsame DB
# verlegen der current-Tabelle ausschließlich in den Cache (muss ja nicht permanent gespeichert werden)
# Entfernen der Tabelle und kreieren eines Views auf die Tabelle history. (dauert aber bei großen Tabellen wie bei mir >3s zum abrufen, was man für die
   Plot-Bearbeitung eventuell aufbringen könnte); dadürch müsste man die Nutzung dieser Funktion auch nicht global in den Einstellungen festlegen, sondern könnte es nutzen, wenn man "möchte"...

Ich nenne diese Ansätze nur zur Info, ich denke dass dies alles den Rahmen dieses Threads deutlich sprengt!

Ich habe bei der Current Tabelle keinen Index. Vielleicht liegt es daran.

Die current Tabelle ist i.d.r. Sehr klein. Nur soviel Einträge wie man Device /reading kombinationen plotten möchte.
Im text2speech nutze ich die current als nutzungslog für löschungen nicht genutzter files

Gesendet von meinem Leap mit Tapatalk

Zitat von: stromer-12 am 14 Januar 2017, 17:33:10
Ich habe bei der Current Tabelle keinen Index. Vielleicht liegt es daran.

Ein Insert ist mit index langsamer, nicht schneller. Das Update macht zwar einen Full-Table-Scan, der ist abe rbei kleinen Tabellen nicht langsamer als mit index.
Wieviele Datensätze hat deine Current-Tabelle denn?

Wenn Du experimentierfreudig bist wäre dieser Test spannend:

1. Lege einen Primary Key an, der doppelte Datensätze verhindert
ALTER TABLE `current` ADD INDEX `pri` (`TIMESTAMP`, `DEVICE`, `READING`);

2.
In Zeile 943 die Zeile
$sth_ic = $dbhp->prepare("INSERT INTO current (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)");
in
$sth_ic = $dbhp->prepare("INSERT IGNORE INTO current (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)");
ändern und ab Zeile 947 dafür sorgen, dass direkt INSERT anstatt zuerst update ausgeführt wird.
Wenn Du den neuen asynchronen Modus nutzt,  befinden sich die benötigten Zeilen weiter unten im Modul.
Dies sollte eigentlich deutlich flotter sein.... aber getestet habe ich es nie, da ich CURRENT nicht nutze.

Ich habe mal einen Index auf Device und Reading gelegt, danach war die Zeit auf 3,5 Sekunden gesunken (CacheUsage ca 1500)
Index wieder gelöscht ist die Zeit wieder bei 43Sekunden.

Als Index habe ich genommen:
ALTER TABLE fhem.current ADD INDEX Search_Idx (DEVICE, READING) USING BTREE;
Die InnoDB Tabellen sind einzeln Dateien.

Index nochmal erstellt, ist bei 1554 Datensätzen die sql_time wieder auf 4.3 Sekunden gesunken.

Edith: die CurrentTabelle hat hier 4724 Einträge.

Zitat von: stromer-12 am 14 Januar 2017, 18:46:58

Code Auswählen Erweitern

ALTER TABLE fhem.current ADD INDEX Search_Idx (DEVICE, READING) USING BTREE;

... das bringt nix, sorry. du scheinst experimentierfreudig zu sein, da du
Dinge gerne abwandelst und etwas eigenes Testest...  da kann ich dich dabei aber nicht unterstützen.
Zum Abschluss würde ich dir daher empfehlen, den Ursprungszustand (löschen des Index) wieder herzustellen.

Wie Joe schon geschrieben hat, bei einem insert ist ein Index eher hinderlich weil dieser noch zum eigentlichen insert gepflegt werden muss. 
Indexe sind nur für select und Updates hilfreich, können aber auch hinderlich sein
Kannst du in jedem SQL dummy Buch nachlesen.

Gesendet von meinem Leap mit Tapatalk

Ich arbeite eigentlich nur mit der history-Tabelle,
aber das der Zeitunterschied bei der current-Tabelle
ohne Index zu mit Index bei den wenigen Datensätzen
so extrem ausfällt hätte ich nicht gedacht.

Der Index in der Current wird ja nur bei einen neu angelegten Reading erneuert.
Die Current Tabelle hält ja jede Device/Reading Kombination nur einmal vor.

Edith: Ich hatte deswegen auch den Timestamp nicht mit in den Index genommen.

Zitat von: Tobias am 14 Januar 2017, 19:16:15
Indexe sind nur für select und Updates hilfreich, können aber auch hinderlich sein

Habe jetzt mal in das Modul an genanter Stelle geschaut und da ist das Update mit
WHERE (DEVICE=?) AND (READING=?)
ausgeführt, also greift da mein erstellter Index.

Zitat von: JoeALLb am 14 Januar 2017, 19:08:14
... das bringt nix, sorry. du scheinst experimentierfreudig zu sein, da du
Dinge gerne abwandelst und etwas eigenes Testest...  da kann ich dich dabei aber nicht unterstützen.
Zum Abschluss würde ich dir daher empfehlen, den Ursprungszustand (löschen des Index) wieder herzustellen.

Also 40 Sekunden geringere SQL-Time mit Index gegenüber ohne Index.
Ich habe den Timestamp nicht in den Index aufgenommen, da der sich bei jeden Update ändert und damit der Index nicht verändert werden braucht.

Hallo zusammen,

seit dem letzten Update habe ich folgende Meldungen im Log:
2017.01.15 13:19:04.989 2: DbLog logdb -> Error: DBD::mysql::st execute_array failed: executing 11 generated 4 errors at ./FHEM/93_DbLog.pm line 1234.

Woran kann das liegen?

Gruß
Torsten

plots gehen mit dme letzten update (heute ) auch nciht mehr sauber. man kann keine devices aus dem dblog wählen und somit ist es nicht möglich ein plot zu erstellen.
eine vorschau des dblog wird im svg auch nicht mehr angezeigt

Hallo Torsten,

mach mal verbose 5 an und schau ob noch weitere Meldungen im Log gibt.
Interessant ist der Block:


2017.01.15 13:40:36.304 5: DbLog LogDB -> ################################################################
2017.01.15 13:40:36.304 5: DbLog LogDB -> ###              New database processing cycle               ###
2017.01.15 13:40:36.305 5: DbLog LogDB -> ################################################################
2017.01.15 13:40:36.305 5: DbLog LogDB -> MemCache contains 21 entries to process
2017.01.15 13:40:36.305 5: DbLog LogDB -> MemCache contains: 2017-01-15 13:40:24|SMA_Energymeter|SMAEM|Bezug_WirkP_Zaehler_Diff: 0.0060|Bezug_WirkP_Zaehler_Diff|0.0060|
......
2017.01.15 13:40:36.351 5: DbLog LogDB -> 21 of 21 events successfully inserted into table history
2017.01.15 13:40:36.367 5: DbLog LogDB -> DbLog_PushAsync finished


Das sollte Aufschluß geben.

@Chris ...Bitte das Attribut DbLogType auf "Current/History" setzen falls nicht gesetzt. Die Current-Tablle ist für die Auswahl "zuständig".

Gruß
Heiko

mit der neuen version ist es auch recht witzig wenn man sein plot room mal aktualisiert. die plots sehen immer anderst aus.  ;D

Zitat von: DS_Starter am 15 Januar 2017, 13:44:30
@Chris ...Bitte das Attribut DbLogType auf "Current/History" setzen falls nicht gesetzt. Die Current-Tablle ist für die Auswahl "zuständig".

ist gesetzt

Zitatmit der neuen version ist es auch recht witzig wenn man sein plot room mal aktualisiert. die plots sehen immer anderst aus.  ;D

Kann ich so nicht bestätigen. Sehen bei mir immer gleich aus. :)

https://forum.fhem.de/index.php/topic,64900.msg561632.html#msg561632

bin nicht alleine. habe sie nochmal geladen, attribut neu gesetzt ohne erfolg. keine einträge im ploteditor,plots hören mittendrin auf (12:00, um 04:00 usw usw), sehen nahc refresh immer anderst aus.

mit der version  93_DbLog.pm          13039 2017-01-10 22:19:58Z DS_Starter  keine probleme!

Das macht mich aber langsam echt stutzig.
Welche DB setzt du ein ?
Und ich gehe davon aus, dass es nachwie vor mit dem Logging keine Sorgen gibt, richtig ?

Zitat von: chris1284 am 15 Januar 2017, 13:58:19
mit der version  93_DbLog.pm          13039 2017-01-10 22:19:58Z DS_Starter  keine probleme!

Ist das reproduzierbar?
Wenn ich mir das Changelog
https://svn.fhem.de/trac/changeset?reponame=&new=13063%40trunk%2Ffhem%2FFHEM%2F93_DbLog.pm&old=13039%40trunk%2Ffhem%2FFHEM%2F93_DbLog.pm
so ansehe, erkenne ich dort keinen Code, der dafür verantwortlich sein sollte...

Wenn Du im Plot auf "show preprocessed imput" klickts, kommen da sämtliche Daten oder sind dort die Lücken ebenfalls vorhanden?
im svg.js wurden ebenfalls Dinge geändert, aber auch dort sehe ich im Moment keine Ursache...

Hi Joe,

du hast doch auch keine Sorgen mit den SVG's bzw. Vorschauwerten nehme ich an ?

@Chris ... bitte test nochmal die V2.9 aus #265, wie es mit der ausieht.  Dort hatte ich das Problem mit "MySQL has gone" erldigt.

Zitat von: JoeALLb am 14 Januar 2017, 18:17:45
Ein Insert ist mit index langsamer, nicht schneller. Das Update macht zwar einen Full-Table-Scan, der ist abe rbei kleinen Tabellen nicht langsamer als mit index.
Wieviele Datensätze hat deine Current-Tabelle denn?

Wenn Du experimentierfreudig bist wäre dieser Test spannend:

1. Lege einen Primary Key an, der doppelte Datensätze verhindert

Code Auswählen Erweitern

ALTER TABLE `current` ADD INDEX `pri` (`TIMESTAMP`, `DEVICE`, `READING`);

2.
In Zeile 943 die Zeile

Code Auswählen Erweitern

$sth_ic = $dbhp->prepare("INSERT INTO current (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)");
in

Code Auswählen Erweitern

$sth_ic = $dbhp->prepare("INSERT IGNORE INTO current (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)");
ändern und ab Zeile 947 dafür sorgen, dass direkt INSERT anstatt zuerst update ausgeführt wird.
Wenn Du den neuen asynchronen Modus nutzt,  befinden sich die benötigten Zeilen weiter unten im Modul.
Dies sollte eigentlich deutlich flotter sein.... aber getestet habe ich es nie, da ich CURRENT nicht nutze.

(Edith: DbLog Version 2.9.1)

Ich habe jetzt bei mir in der Tabelle Current eine Primarindex auf Device und Reading angelegt.
Sowie in der DbLog in Zeile 947 und 1213 ein ON DUPLICATE KEY UPDATE DEVICE = VALUES(DEVICE), READING = VALUES(READING)
an den INSERT angefügt, mehr nicht.

Damit werden in der Current keine dopperlten Device+Reading Einträge mehr erzeugt und ich erhalte keine Fehlermeldung.

Hallo Heiko,

Zitat von: DS_Starter am 15 Januar 2017, 14:44:57
du hast doch auch keine Sorgen mit den SVG's bzw. Vorschauwerten nehme ich an ?

Nein, bei mir alles gut! Daher interessiert mich die Info aus "show preprocessed imput", denn dann sieht man ob das Modul DbLog alle Daten liefert.
Wenn es alle Daten liefert, könnte eben ein Fehler in der Anzeige sein, also im svg.js oder anderen Modulen, die in letzter Zeit auch aktualisiert wurden.

Zitat von: JoeALLb am 15 Januar 2017, 14:38:21
Ist das reproduzierbar?

ja.

Zitat"show preprocessed imput" klickts, kommen da sämtliche Daten oder sind dort die Lücken ebenfalls vorhanden?

alle daten da.
das lustige ist: im room ist der plot unvollständig (mal stopt zb nur der hum-graph , mal der temp). das wechselt dann zwischen den plots je öfter man refreshed.
in der ploteditor ansicht werden die graphen weiter gezeichnet

schalte ich plotfork aus, gehts. offenbar kommt irgendwas damit nicht klar

Hallo Chris,

ich habe die aktuelle Version mit und ohne plotfork hoch und runter probiert und keinerlei Probleme mit Plots oder Vorschauenwerten festgestellt.
Hmm ... Browsercache mal geleert ?

Zitat von: DS_Starter am 15 Januar 2017, 16:04:16
Hmm ... Browsercache mal geleert ?

ja

Ich könnte mir vorstellen, dass die Anzeige der Plots, und nicht unbedingt DbLog daran "schuld" ist...

Ich hatte es gerade in einem Test jedoch geschafft, dass mein ganzes System nicht mehr funktionierte. Es lies sich nicht mehr starten,
ohne nennenswerte Logeinträge.
Geholfen hat letztlich nur ein revert der fhem.pl auf den Stand von gestern...

Da ich jetzt weg muss, kann ich es leider nicht mehr detailierter testen, aber in diesem Modul hat
heute bisher alles funktioniert!

Hallo Chris,

kann die Feststellung von Joe auch bestätigen ... funktioniert bei mir alles bestens.
Trotzdem ... bitte teste nochmal die V2.9 aus #265, wie es mit der ausieht. Da hatte ich die MySQL-Meldung erledigt die versch. User hatten.
Danach kamen nur kleine Ergänzungen.

Und deine Daten sind ja auch alle da. Das Logging ist also auch ok.....

Zitat von: DS_Starter am 15 Januar 2017, 16:25:37
l die V2.9 aus #265

hat das selbe problem

verwende SQLite version 3.8.7.1

Ich habe das mal so eingebaut mit IGNORE, da wird das Log mit
2017.01.15 17:51:14.282 2: DbLog myDbLog -> Failed to insert into current: ...
geflutet.

Zitat von: JoeALLb am 14 Januar 2017, 18:17:45
Ein Insert ist mit index langsamer, nicht schneller. Das Update macht zwar einen Full-Table-Scan, der ist abe rbei kleinen Tabellen nicht langsamer als mit index.
Wieviele Datensätze hat deine Current-Tabelle denn?

Wenn Du experimentierfreudig bist wäre dieser Test spannend:

1. Lege einen Primary Key an, der doppelte Datensätze verhindert

Code Auswählen Erweitern

ALTER TABLE `current` ADD INDEX `pri` (`TIMESTAMP`, `DEVICE`, `READING`);

2.
In Zeile 943 die Zeile

Code Auswählen Erweitern

$sth_ic = $dbhp->prepare("INSERT INTO current (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)");
in

Code Auswählen Erweitern

$sth_ic = $dbhp->prepare("INSERT IGNORE INTO current (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)");
ändern und ab Zeile 947 dafür sorgen, dass direkt INSERT anstatt zuerst update ausgeführt wird.
Wenn Du den neuen asynchronen Modus nutzt,  befinden sich die benötigten Zeilen weiter unten im Modul.
Dies sollte eigentlich deutlich flotter sein.... aber getestet habe ich es nie, da ich CURRENT nicht nutze.

Hallo Chris1284,

teste bitte die hier angehängte Version 93_DbLog_V2.9.2_Chris.
Ich habe sie bei mir allen mir möglichen Variatioen getestet und läuft nach wie vor einwandfrei mit MySQL.
Bitte schau die das unter SQLite an, ob das Problem bei dir weg ist.

Grüße
Heiko

Zitat von: stromer-12 am 15 Januar 2017, 18:00:38
Ich habe das mal so eingebaut mit IGNORE, da wird das Log mit

Code Auswählen Erweitern

2017.01.15 17:51:14.282 2: DbLog myDbLog -> Failed to insert into current: ...
geflutet.

Aber nur wenn bei einen commit ein neuer Datensatz mehrmals auftaucht, danach nicht mehr.

keine besserung. anbei mal ein screenshot der plots, danach einer nach einem einfachen f5 in paint neben den ersten gelegt. danach ein screen vom plot im detail (wo lles schick ist). im IE siehts genau so aus, auf allen tablets auch.
gehe ich zurück auf die alte version, alles top

Hallo Chris,

bitte nochmal.

leider nein

Jetzt habe ich aber alles so nach und nach zurückgedreht ....
Hats du eigentlich immer restartet ?  neme mal an ja.
Arbeitest du mit dem normalen synchronen Modus ?

Hallo Chris,

jetzt habe ich in der Zwischenzeit meine SQLte Test-DB wieder belebt und mit der eingecheckten Version 2.9.1 durchgespielt.
Auch damit ist bei mir alles ok, d.h. die Device:Reading Vorschaufelder sind gefüllt. der Graph wird gezeichnet und "show preprocessed input" ist ebenfalls
gefüllt. Alles mit SQLite.
Stehe momentan vor einem Rätsel ...

Moin Heiko,

leider kann ich das von Chris auch bestätigen.
Nutze auch SQLite auf BPi und RPi2.
DbLogType Current/History
asyncMode 0
Vorher nur "DbLogType History"

Werde mal die "Chris Versionen" testen.

LG
sunny

Moin Heiko,

leider keine Besserung mit "93_DbLog_V2.9.2_Chris.pm"aus Antwort #329 am: Heute um 20:15:34 (https://forum.fhem.de/index.php/topic,62998.msg561989.html#msg561989)

LG
sunny

Hallo sunny,

hmm .... das Ergebnis ist einerseits gut weil die Änderungen bzgl. des MySQL-Fehlers nicht "schuld" sind.
Ich mache gleich noch eine V ...

Hallo Sunny,

auch diese Version läuft problemlos bei mir. MySQL und SQLite.
Schalte bitte auch mal um in asynch ob sich dadurch Änderungen ergeben . Glaube ich aber nicht.

Moin Heiko,

habe asyncMode 0
gelöscht und Deine "93_DbLog_V2.9.2_Test.pm" getestet.
Auf Win10/Firefox und Android/Firefox.
Sieht GUT aus. (Nach kurzem testen)  8)

DANKE für Deine Zeit/Know How!

Mit gefüllten SVG Grüßen
sunny

Hallo sunny,

danke, das ist wirklich schön nur kann ich es fast nicht glauben  ;) Kannst du bitte noch einen Negativtest
machen ? Wäre hilfreich für mich.

Grüße
Heiko

Moin Heiko,

mit "93_DbLog_V2.9.2_Test2.pm" tritt der Fehler wieder auf.
Was möchtest Du jetzt an Daten haben?

Sorry, aber Heute wird es nix mehr.
Muss in die Falle.
Aber morgen kann ich dann versuchen die Daten  zu erstellen.

Mit müden Grüßen
sunny

Hallo sunny,

auch für mich ist es heute schon zu spät. Ich muß die Ergebnisse in Ruhe sichten.
Heute wird das auch nichts mehr.
Morgen wieder .... danke für die Unterstützung !

Grüße
Heiko

Ich sehe gerade das Attribut verbose4Devs und lese, dass in DbLog automatisch das globale Logfile für Geräte mit verbose 4 geloggt wird.

Das ich hinsichtlich des globalen Logfiles konservativ bin benötige ich keine Einträge in die Datenbank, da sie bei einem FHEM Absturz oder DB-Fehler nicht leicht verfügbar sind.

Das globale Logfile kann ich per Texteditor einsehen, häufig auch wenn die Datenbank nicht zugänglich ist.

Könnte ich zum Abschalten  verbose4Devs none setzen, wenn das Gerät "none" nicht existiert? Oder prüft DbLog, ob ein globales Logfile als FileLog-Gerät definiert ist?

Hallo Ellert,

vielleicht ist die Beschreibung des Attributs etwas mißverständlich ausgedrückt.
Wenn man in DbLog verbose4 einstellt werden ja unter Umständen sehr viele EInträge im Logfile mit "Logcycle..." auftreten, je nachdem wieviele Geräte man mit DbLog so logged. Um die Lesbarkeit der Ausgaben in diesem Fall zu verbessern, kann man mit diesem Attribut nicht interessierende Geräte von der verbose 4 Ausgabe (in DbLog) ausnehmen.
Das ist alles was dieses Attribut macht, ist nur eine kleine Hilfe um verbose 4 in DbLOg etwas übersichtlicher zu machen wenn Bedarf besteht.

Grüße
Heiko

Danke für die Aufklärung.

Hallo zusammen,

ohne jetzt den ganzen Thread durchgelesen zu haben  :-[, hier mal die Frage, ob das Performance-Problem, das bei DbLog im Zusammenspiel mit dem Wunderground-Modul auftritt, hier bereits bekannt ist?
(siehe https://forum.fhem.de/index.php/topic,59646.msg529392.html#msg529392)

Ich habe gestern mal wieder ein update gemacht und in der Hoffnung, dass dieses Problem hier evtl.  schon gelöst wurde. Allerdings scheint das Problem nach wie vor zu bestehen, egal, ob DbLog im asynchronen Modus läuft oder nicht. Die Freezes beim update vom Wunderground-Modul bestehen nach wie vor:


2017.01.16 09:00:24 3: Wunderground set wuMain update
2017.01.16 09:00:31 1: Perfmon: possible freeze starting at 09:00:26, delay is 5.691
2017.01.16 09:02:39 3: Wunderground set wuMain update
2017.01.16 09:02:47 1: Perfmon: possible freeze starting at 09:02:42, delay is 5.444


Schalte ich DbLog ab, dann habe ich keine Freezes beim Wunderground-update.

Eventuell könnt ihr ja mal Loredos Theorie aus dem o.a. Thread überprüfen. Nachdem hier v.a. an der Performance-Schraube gedreht wird, könnte sich, wenn sich das bestätigt und abstellen lässt, evtl. ein nicht unerheblicher Performance-Gewinn für das DbLog-Modul generell erzielen lassen. ;)

Wenn ich was dazu beitragen kann (Tests, Logs, Lists, ...), natürlich gerne!

Danke und Gruß
Benni.

Sorry - auf die Gefahr, dass ich hier total falsch bin - ich habe mal auf die aktuelle Version des DbLog aktualisiert, habe dann aber das Problem, dass ich von Devices, die z.B. alle 15 Minuten
gepollt/abgerufen werden alle Änderungen in dem Zeitraum dann zum Abrufzeitpunkt eingetragen bekomme, d.h. z.b. den Temperaturverlauf mit allen Temperaturen zur Abrufzeit, anstelle
zu den tatsächlichen Zeiten der Ereignisse und nicht zur der einen Event-Zeit des Abrufs. Über Nacht führt dies Beispielsweise bei einem meiner Sensoren dazu, dass dann der kpl. Temperaturverlauf der Nacht auf den Abruf um 7:00 gelegt wird. Damit sind natürlich die Daten und auch die Plots im Eimer.

Gibt es eine Möglichkeit das "alte" Verhalten wiederherzustellen? Ich bin aktuell erst mal auf eine DbLog-Version aus dem Oktober zurück - so bin ich dann über die Suche auch hierhin gelangt.

Zitat von: h3llsp4wn am 16 Januar 2017, 16:29:29
Sorry - auf die Gefahr, dass ich hier total falsch bin - [...]

Mehrere Fragen dazu:
# 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?

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

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
sql_processing_time = 0.0609
alle 10 Minuten, was mein System deutlich performanter macht und die SSD deutlich länger leben lässt!!!!

Chapeau!

Also...

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


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:


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:


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:


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):

Zitat von: Loredo am 27 November 2016, 11:44:03
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  8)


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. :o


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.  :-\

@JoeALLb

Zitat
# 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.

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

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.

Zitat von: DS_Starter am 16 Januar 2017, 20:33:26
@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!

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.....

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


@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.

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.

ZitatIch 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.

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:

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?

Zitat von: DS_Starter am 16 Januar 2017, 19:05:54

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

diese version läuft!

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

@Amenophis86

Zitat
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

Alles klar. Danke für die Info.

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

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.

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


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


Irgendeine Idee FHEM ist auf heutigem Update Stand.

VG


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


ZitatWide character in subroutin

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

VG

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

Wunsch zur Verdeutlichung in der Doku:
    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.

Hallo Heiko,

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

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.

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

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  :o:


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


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  :-\

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

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

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.  :D 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

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...

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.  :D 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.

Zitat von: Benni am 20 Januar 2017, 16:12:28
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?

Ich habe mit der 2.10.2 ebenfalls einen Timeout mit Datenverlust, wenn die Datenbank blockiert war.
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

Zitat von: JoeALLb am 20 Januar 2017, 16:16:33
was steht bei Dir bei den 4 "event-on.*" Attributen?

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


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


Zitat von: Benni am 20 Januar 2017, 18:49:42

Code Auswählen Erweitern


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


Aber jetzt war CacheUsage aktuell?!?

Zitat von: DS_Starter am 19 Januar 2017, 22:32:47
@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

@stromer-12 ...

ZitatTimeout 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

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

Zitat von: JoeALLb am 20 Januar 2017, 19:01:10
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!

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

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

Hallo friesenjung,

sorry, deine Frage hatte ich fast vergessen.

Zitatgab 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

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:


          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:


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:


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.

Hi Benni,

ZitatSehr 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

Auch auf die Gefahr hin lästig zu werden...  :-[

Irgendwie hat es mir doch keine Ruhe gelassen ;D

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

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


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.

Hi Benni,

ZitatAuch auf die Gefahr hin lästig zu werden...  :-[

wirst du nicht ...   :D

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

Grüße
Heiko

Zitat von: DS_Starter am 21 Januar 2017, 13:35:59
Hallo friesenjung,

sorry, deine Frage hatte ich fast vergessen.

...

Hallo Heiko, hört sich gut an. Ich warte gespannt. VG...

Zitat von: DS_Starter am 21 Januar 2017, 13:35:59
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.

Wäre es nicht einfacher/übersichtllicher/besser, das nicht über db.conf, sondern über Atribute machen?
Dann wäre die Reihenfolge so:  Attribut > Default .
Später könnte man dann die Internals einfach noch mit einbinden: Die neue Reihenfolge wäre dann: Attribut > ausgelesenes Internal > Default.
Ich denke das wäre lesbarer und auch für die Zukunft einfacher zu handhaben. Und direkt beim initialisieren der DB-Verbinmdung wird
die Feldlänge ja noch nicht benötigt.

Mir gefällt es besser, die Config "zentral" in FHEM zu haben und nicht allzuviele externe Stellen mit einbeziehen (die die db.conf).
Zusätzlich kann man Attribute besser in Scripten auslesen und dort ebenfalls verwenden.... just my 5 cents ;-)

Hi Joe,

ZitatWäre es nicht einfacher/übersichtllicher/besser, das nicht über db.conf, sondern über Atribute machen?

Also ich bin da offen. Für Attribute spricht, dass ich hier auch eine Prüfroutine für die Verwendung von Ziffern einbauen die gleich einen Popup erzeugen falls man danebenhaut.
Das Configfile ist allerdings auch sehr einfach zu handhaben und ist den Usern ja bekannt.

Vielleicht gibt es diebezüglich noch ein paar Meinungen.

Schönen Abend !

LG
Heiko

Ich wäre auch für Attribute, da es schon Sinn macht alles aus Fhem heraus im Blick zu haben.
VG

Vielen Dank für das tolle Modul und deren Weiterentwicklung.
Bin auch für Attribute, ich glaube das wurde wie configDB gelöst und da braucht man es in einem extra file.

Zitat von: Christian Uhlmann am 21 Januar 2017, 17:27:58
Bin auch für Attribute, ich glaube das wurde wie configDB gelöst und da braucht man es in einem extra file.

Ich hab' den Satz jetzt ungefähr 10 mal gelesen und werde einfach nicht schlau draus  :-\

Grundsätzlich finde ich auch, dass das Verhalten über Attribute (über-)steuerbar sein sollte. Das Vorgehen an sich kann aber gerne, wie ursprünglich angedacht bleiben. Sprich lesen der Feldlängen aus der DB (falls nicht per Attribut anders definiert) -> Feldlängen aus Config-File (falls dort welche definiert sind und nicht aus DB gelesen, entweder weil nicht gewünscht oder nicht möglich) -> Defaults, wie bisher

Per Attribut dann nur noch steuern, ob die Option "Lesen der Feldlängen aus DB" überhaupt wahrgenommen werden soll, der Rest ergibt sich dann ja von selbst.

Hi, ich habe heute ein komplettes Update von FHEM vorgenommen. Leider startet FHEM danach nicht mehr aufgrund der 93_DbLog.

Fehler:
2017.01.21 18:12:30 5: Triggering myDBLog (2 changes)
DBD::SQLite::db prepare failed: attempt to prepare on inactive database handle at ./FHEM/93_DbLog.pm line 955.

Anschließend hab ich die ältere Version wiederhergestellt ($Id: 93_DbLog.pm 11825 2016-07-21 05:40:59Z) -> FHEM startet wieder. Debian und CPAN wurden ebenfalls mit aktualisiert.

Internals:
   CONFIGURATION /opt/fhem/db.conf
   DBMODEL    SQLITE
   DEF        /opt/fhem/db.conf .*:.*
   NAME       myDBLog
   NR         20
   NTFY_ORDER 50-myDBLog
   PID        5307
   REGEXP     .*:.*
   STATE      connected
   TYPE       DbLog
   dbconn     SQLite:dbname=/opt/db_fhem/fhem-db
   dbuser
   Helper:
     Dblog:
       State:
         Mydblog:
           TIME       1485020572.97598
           VALUE      connected
   Readings:
     2017-01-21 18:42:52   state           connected
Attributes:
   DbLogType  Current/History
   verbose    1

Habe ich bei der Umstellung etwas übersehen?

Viele Grüße
Martin

Hallo Martin,

soweit ich sehe sollte alles passen, außer dass in dem Fall wohl keine Verbindung zur DB aufgebaut werden konnte.
In dem Fall gäbe es aber noch mehr Einträge im Log.
Nimm am Besten gleich die V2.10.3 aus  #384 , restarte FHEM und berichte bitte ob du damit noch dieses beschriebene Problem hast.

Grüße
Heiko

Hallo zusammen,

nachdem ich heute meine FHEM Instanz von Wheezy auf eine Jessie-lite Neuinstallation und neue SD-Karte (Raspi 2) umgezogen habe ist mir folgendes aufgefallen. Bei jedem Zugriff auf die DB erhalte ich folgende Meldungen im fhem.log:


2017.01.21 21:39:36 3: Connecting to database mysql:database=fhem;host=localhost;port=3306 with user fhemsql
2017.01.21 21:39:36 3: Connection to db mysql:database=fhem;host=localhost;port=3306 established for pid 1250
2017.01.21 21:41:37 3: Connecting to database mysql:database=fhem;host=localhost;port=3306 with user fhemsql
2017.01.21 21:41:37 3: Connection to db mysql:database=fhem;host=localhost;port=3306 established for pid 1288
2017.01.21 21:41:37 3: Connecting to database mysql:database=fhem;host=localhost;port=3306 with user fhemsql
2017.01.21 21:41:37 3: Connection to db mysql:database=fhem;host=localhost;port=3306 established for pid 1288
Waiting for data... (interrupt to abort)


Was meine ich mit DB Zugriff: wenn ich im FHEMWEB ein Plot anzeigen lasse, welches sich die Daten aus der DB holt, tauchen obige Meldungen im fhem.log auf. Ist das Absicht? Kann man das abstellen?

Hier ein List meiner DBlog:


Internals:
   CONFIGURATION ./db.conf
   DBMODEL    MYSQL
   DEF        ./db.conf .*:.*
   MODE       asynchronous
   NAME       logDB
   NR         33
   NTFY_ORDER 50-logDB
   PID        517
   REGEXP     .*:.*
   STATE      connected
   TYPE       DbLog
   VERSION    2.9.2
   dbconn     mysql:database=fhem;host=localhost;port=3306
   dbuser     fhemsql
   Helper:
   Readings:
     2017-01-21 21:48:57   CacheUsage      10
     2017-01-21 21:44:45   NextSync        2017-01-21 21:54:45
     2017-01-21 21:44:45   background_processing_time 0.1644
     2017-01-21 21:02:04   countCurrent    37
     2017-01-21 21:02:04   countHistory    322
     2017-01-21 21:44:45   sql_processing_time 0.1480
     2017-01-21 21:44:45   state           connected
   Cache:
     index      52
     Memcache:
       43         2017-01-21 21:45:37|temp.dg.diffmessure.t2|CUL_HM|temperature: 22.5|temperature|22.5|°C
       44         2017-01-21 21:45:57|Buderus|BDKM|PowerModulation: 61|PowerModulation|61|
       45         2017-01-21 21:45:57|Buderus|BDKM|HC1InputTemp: 40.3125|HC1InputTemp|40.3125|
       46         2017-01-21 21:45:57|Buderus|BDKM|HC1ReturnTemp: 35.9375|HC1ReturnTemp|35.9375|
       47         2017-01-21 21:48:28|energie_strom_waschmaschine_Pwr|CUL_HM|energy: 25849.7|energy|25849.7|
       48         2017-01-21 21:48:34|temp.dg.diffmessure.t2|CUL_HM|temperature: 22.5|temperature|22.5|°C
       49         2017-01-21 21:48:57|Buderus|BDKM|PowerModulation: 61|PowerModulation|61|
       50         2017-01-21 21:48:57|Buderus|BDKM|OutdoorTemp: -10.4|OutdoorTemp|-10.4|
       51         2017-01-21 21:48:57|Buderus|BDKM|HC1InputTemp: 40.4375|HC1InputTemp|40.4375|
       52         2017-01-21 21:48:57|Buderus|BDKM|HC1ReturnTemp: 35.9375|HC1ReturnTemp|35.9375|
Attributes:
   DbLogSelectionMode Include
   DbLogType  Current/History
   asyncMode  1
   room       Zentrale
   showproctime 1
   shutdownWait 2
   syncInterval 600
   webCmd     listCache

Die DB ist eine MariaDB 10.0.28, welche lokal auf dem Raspi mit FHEM läuft.

Danke und Gruß

Hallo Jorge3711,

ZitatIst das Absicht? Kann man das abstellen?

Das sind Informationen dass eine Verbindung zur DB neu aufgebaut/refreshed wurde. Abstellen kannst du es mit verbose=2.

Allgemein entwickeln wir zur Zeit beständig weiter. Nutze bitte gleich die  V2.10.3 aus  #384.

viele Grüße

OK, danke für die Rückinfo. Ich verfolge den Thread als stiller Mitleser sehr interessiert. Nachdem ich wegen HW Problemen inkl. DB Problemen auf der alten FHEM Installation die Neuinstallation durchführte, war ich etwas erschrocken und dachte die DB hat schon wieder einen Hau weg.

Hallo zusammen,

es hat sich eine Mehrheit dafür ausgesprochen die Feldlängenanpassung im Modul über Attribute vorzunehmen.
Das habe ich so umgesetzt und die Feldlängen von EVENT, READING, VALUE mit der angehängten V2.10.4 anpassbar gemacht.

Dazu gibt es die neuen Attribute colEvent, colReading, colValue.

Im Internal "COLUMNS" findet man eine Zusammenfassung der Feldlängen die das DbLog-Device aktuell benutzt:

field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32

FHEM Restart ist nötig.

Bitte testet diese Version bei euch auch unter anderen Gesichtspunkten wie Plot, Vorschlagswerte mit Current/History, usw. mit euren DB-Typen.
Ich würde diese Version gern einchecken bzw. Tobias bitten es zu tun. Seit der letzten eingecheckten Version ist doch schon so Einiges weiterentwickelt/angepasst worden.

@Benni ... für deine Eventgeschichte habe ich noch keine gute Lösung gefunden. Habe es mit direktem Setzen von $defs{$name}{READINGS}{CacheUsage} probiert, aber das ist nicht gut. Vielleicht hast du noch eine zündende Idee wie man den Mechanismus abändern könnte. Ich denke auch
noch weiter darüber nach.

viele Grüße
Heiko

Hallo Heiko,

Zitat von: DS_Starter am 22 Januar 2017, 10:29:03
@Benni ... für deine Eventgeschichte habe ich noch keine gute Lösung gefunden. Habe es mit direktem Setzen von $defs{$name}{READINGS}{CacheUsage} probiert, aber das ist nicht gut. Vielleicht hast du noch eine zündende Idee wie man den Mechanismus abändern könnte.

Nun, man könnte ja auch argumentieren, dass ein setzen von CachUsage ohne Event sowieso keinen Sinn macht, weil es dann ja auch keiner mitbekommt. (frei nach Schrödinger ;))

So gesehen könnte man den else-Zweig in DbLog_Log an der kritischen stelle auch tatsächlich einfach weglassen, zumindest dann, wenn im Asynch-Modus für cacheEvents 2 gewählt ist. Das ist ja "nur" die Stelle, an der der Wert für CacheUsage ganz allgemein bei jedem Log gesetzt wird, das ist in diesem Fall aber eher uninteressant.
Beim setzen von CacheUsage in DbLog_execmemcache wird der Wert ($memcount) vor dem setzen des Readings dort ja sowieso nochmal neu ermittelt, so dass für das Event dann auch dort der korrekte Wert geliefert wird.

VG Benni.

Hallo Benni,

habe das mal probiert. Hatte den Nachteil dass CacheUsage dann u.U. keinen Wert anzeigt obwohl listCache einen Inhalt listet.
Das führt stiftet dann wieder Verwirrung und Fragen ....

Aber dein Satz:

ZitatSo gesehen könnte man den else-Zweig in DbLog_Log an der kritischen stelle auch tatsächlich einfach weglassen, zumindest dann, wenn ...

hat mich inspieriert und vielleicht zur Lösung gebracht  :)
Ich habe mir über den HELPER ein Sperrbit gesetzt wenn execmemcache den Event setzen will. Der relevante Else-Zweig im DbLog_Log wird dann an der Ausführung gehindert (für diesen kurzen Moment). Passiert ja nur alle x-Sekunden wenn der Db-Sync läuft.
Probier mal die angehängte V2.10.5 bei dir ob das so zieht wie beabsichtigt. Ich merke keinen Unterschied zu vorher.

viele Grüße
Heiko

Hallo Heiko,

danke, hat funktioniert.

Gruß Martin

Zitat von: DS_Starter am 21 Januar 2017, 19:55:24
Hallo Martin,

soweit ich sehe sollte alles passen, außer dass in dem Fall wohl keine Verbindung zur DB aufgebaut werden konnte.
In dem Fall gäbe es aber noch mehr Einträge im Log.
Nimm am Besten gleich die V2.10.3 aus  #384 , restarte FHEM und berichte bitte ob du damit noch dieses beschriebene Problem hast.

Grüße
Heiko

Hallo Martin,

prima ... danke für die  Rückmeldung.

VG
Heiko

Zitat von: DS_Starter am 22 Januar 2017, 15:56:18
Probier mal die angehängte V2.10.5 bei dir ob das so zieht wie beabsichtigt.

Hallo Heiko,

leider nein!  :(

Die race condition bleibt anscheinend dieselbe: DbLog_Log kommt und das Sperr-Bit in HELPER ist zu dem Zeitpunkt noch nicht verfügbar.

Eine weitere Möglichkeit wäre evtl. ein Attribut um das eventlose update von CacheUsage in DbLog_Log im Asynch-Mode auf (User-)Wunsch abzuschalten. Dazu ist das Problem aber vllt. auch zu speziell. ;)

Übrigens: Die Moduldatei meldet sich in den Internals noch als Version V2.10.4

Gruß Benni.

Hi Benni,

komm, einen Versuch machen wir noch. Habe das Sperrbit in execmemcache etwas früher gesetzt und später gelöscht.
Das sollte doch ziehen ...
Die interne V ist auch korrigiert.

Grüße
Heiko

Zitat von: DS_Starter am 22 Januar 2017, 17:03:00
komm, einen Versuch machen wir noch.

Leider immer noch negativ  :(

ZitatLeider immer noch negativ  :(

Schade ... der Versuch war es noch wert. Ich werde dann erstmal die 2.10.4 einchecken.
Vielleicht kriegen wir das noch anders hin.

Grüße
Heiko

Mahlzeit!

Zunächst erneut vielen Dank für die Updates. Ich logge ziemlich großzügig und lasse permanent apptime laufen. Da sieht man sehr gut, wie im asynchronen Modus nahezu sämtliche Laufzeiten deutlich nach unten gehen.

Hierzu eine Frage:
Was genau passiert im Fall eines fehlerhaften Datenbank-Connects im asynchronen Modus, d. h.:

2017.01.20 06:13:20.002 3: DbLog DbLog: Error DBLog_execmemcache - DBI connect('database=fhem;host=mysql.prdom;port=3306','fhem',...) failed: Can't connect to MySQL server on 'mysql.prdom' (111) at ./FHEM/93_DbLog.pm line 1102.

Das passiert bei mir wenn ich Paketupdates des MySQL-Dienstes durchführe. Wird der Cache dann beim nächsten Connect erneut an die DB geschickt?

Patrick

Hallo Patrick,

ZitatWird der Cache dann beim nächsten Connect erneut an die DB geschickt?

So ist es. DbLog erkennt im asynchronen Modus bevor die Daten an den Hintergrundprozess gesendet werden dass die DB nicht erreichbar ist und hält die Daten im Cache. Wenn sie wieder verfügbar ist, werden sie in die DB geschrieben.
Du darfst natürlich FHEM in der Zeit nicht restarten. Der Cache ist im RAM und flüchtig.

Grüße
Heiko

Moin
Jetzt muss ich leider auch mal nachfragen. Ich habe vorhin ein update gemacht, und jetzt (vielleicht auch schon vorher?) kann ich keine SVG's mehr editieren! Es gibt keine dropdowns fuer die Werte mehr. Da meine DB recht gross (14GB) ist, ist alles was ich darauf mache sehr langsam. Ein Count hat ca. 30 Minuten gedauert, Als ich dann das Problem entdeckt hatte habe ich ein reopen  gemacht, danach war fhem dann tot. Irgendwie hat zweimal reboot des RPI das fhem wieder erweckt. Im LOG stand folgendes:
DBD::SQLite::db prepare failed: unable to open database file at ./FHEM/93_DbLog.pm line 955.
Ich wuerde die DB ja gerne einschrumpfen, aber momentan ist mir das sehr suspekt. Kann ich gefahrlos auf async umstellen? Soll ich lieber eine neue DB erstellen, und wenn ja wie?
Gruss Christoph

Hallo Heiko,

vielen Dank für die Weiterentwicklung!!!

Läuft bisher ohne Auffälligkeiten, folgendes ist mir jedoch aufgefallen:
#1 Die Version von 2.10.5 wird intern noch als 2.10.4 angezeigt ;-)
# Wie bekannt, habe ich ja in der Datenbank einen PK eingefügt und bekomme daher Fehlermeldungen, die
   natürlich nichts mit dem Modul zu tun haben. Trotzdem habe ich dazu eine Frage:
DBD::mysql::st execute_array failed: Duplicate entry 'temp.wz.innen-empfehlung-2017-01-22 20:05:41' for key 'PRIMARY' [err was 1062 now 2000000000] executing 176 generated 21 errors at ./FHEM/93_DbLog.pm line 1326.
Was passiert mit diesem Datensatz? Vermutlich wird nur dieser eine nicht in die Datenbank eingetragen? Da das Modul ja Fehler erkennt, hännte ich nun erwartet, dass dieser Datensatz im Cache verbleibt und
beim nächsten Zyklus wieder versucht wird, einzutragen. Dem ist aber nicht so. Löscht das Modul also Fehler dieses Typs?
Prinzipiell nutze ich diese Fehlerlogs gerade, um alle fehlerhaften Devices zu erkennen dort mich für eine Fehlerbereinigung einzusetzen... es macht ja keinen Sinn, gewisse Readings 2x zur selben Zeit mit dem selben Reading zu setzen....

Zitat von: pc1246 am 22 Januar 2017, 20:19:01
Ich wuerde die DB ja gerne einschrumpfen, aber momentan ist mir das sehr suspekt. Kann ich gefahrlos auf async umstellen? Soll ich lieber eine neue DB erstellen, und wenn ja wie?

Versuch doch mal bitte die neuere Version aus Post #407, so viel ich verstanden habe könnte diese das schon beheben...

Halllo Christoph,

ZitatEs gibt keine dropdowns fuer die Werte mehr

Stelle bitte das Attr "DbLogType" auf "Current/History". Dann bekommst du auch die Drop-Down. Die 2.10.4 aus  #401 ist der letzte Stand.
Die 2.10.5 war nur für ein paar Versuche mit Benni.

ZitatDBD::SQLite::db prepare failed: unable to open database file at ./FHEM/93_DbLog.pm line 955.

Sagt aber tatsächlich dass deine DB nicht zugreifbar ist. Schau mal ob die vielleicht durch einen äußeren Prozess geblockt ist. Bei mir ist dass z.B. der Fall wenn ich meine Test-SQLite mit einem externen SQL-Editor öffne.

Hi Joe,

Zitat#1 Die Version von 2.10.5 wird intern noch als 2.10.4 angezeigt

Ja, das war nur ein Test mit Benni wegen seinen Events.

Grüße
Heiko

Hi Joe,

ZitatDa das Modul ja Fehler erkennt, hännte ich nun erwartet, dass dieser Datensatz im Cache verbleibt und
beim nächsten Zyklus wieder versucht wird, einzutragen. Dem ist aber nicht so.

Momentan bin ich soweit, dass bei Nichtverfügbarkeit der DB oder wie bei Christoph die DB gelockt ist, dieser Zusatnd erkannt wird und dementsprechend die Daten im Cache verbleiben unm sie päter wieder einzufügen.
Andere Zustände die "tiefer" liegen kann ich momentan noch nicht abfangen, sondern nur als als Info bzw. Log ausgeben.

Grüße
Heiko

Zitat von: DS_Starter am 22 Januar 2017, 20:46:35
Momentan bin ich soweit, dass bei Nichtverfügbarkeit der DB oder wie bei Christoph die DB gelockt ist, dieser Zusatnd erkannt wird und dementsprechend die Daten im Cache verbleiben unm sie päter wieder einzufügen.
Andere Zustände die "tiefer" liegen kann ich momentan noch nicht abfangen, sondern nur als als Info bzw. Log ausgeben.

Danke für die Erklärung. Bedeutet das dann aber, dass in solch einem Fall alle Datensätze des Arrays nicht eingefügt werden können, oder nur eben der eine, der den Fehler aufwirft.

Im Beispiel
DBD::mysql::st execute_array failed: Duplicate entry 'temp.wz.innen-empfehlung-2017-01-22 20:05:41' for key 'PRIMARY' [err was 1062 now 2000000000] executing 176 generated 21 errors at ./FHEM/93_DbLog.pm line 1326.
würde ich mir dann eigentlich 21 solcher Fehlermeldungen erwarten.... ich bekomme aber nur eine.

Hi Joe,

der bei denen der Fehler auftritt.
Mach dir doch mal verbose 5 an. Es sollte dann ersichtlich sein wieviele Datansätze (Ist/Soll) in die DB eingefügt wurden.
Probiers mal ...

LG
Heiko