93_DbLog - Umstellung Log-Funktion auf non-blocking

[DS_Starter]

Hallo Daniel,

die Attribute für die Feldlängen funktionieren! Hab die 2.10.4 am WE getestet und soweit läuft alles stabil!

Das einzige was mir aufgefallen ist, dass z.B. bei einem FHEM-Update mit verbundenem Restart anfänglich noch Werte mit den "kurzen" Feldlängen in die DB geschrieben werden. Das sind bei mir pro Update 1-2 Datensätze, die "abgehackt" werden. Scheinbar wirken die Attribute nicht schnell genug. Vlt. könnte man da noch etwas nachjustieren...

Vielen Dank für die Rückinfo !
Ich schau mal dass ich das noch verbessern kann.

viele Grüße
Heiko

[JoeALLb]

das Logging der V2.10.4 entspricht übrigens der 2.10.5 die du in #413 schon erfolgreich getestet hast. Kann IMHO nur an der schon vermuteten Sache liegen. Aber excludeDevs auf dein DbLog-Device setzen ist auch keine schlechte Idee.

#1 da die Speicherzeiten anfangs nur langsam ansteigen, kann es sein, dass ich das gestern in meinem Test übersehen habe.
#2 excludeDevs nutze ich im Moment nicht, um die Grafik zu generieren, die mich auf das Performanceproblem gebracht hat. Ich nutze aber

Code Auswählen Erweitern

DbLogInclude sql_processing_time,background_processing_time,CacheUsage
und

Code Auswählen Erweitern

cacheEvents 2
#3 Die "events successfully"-Einträge werden ordentlich eingetragen!

Code Auswählen Erweitern


...
2017.01.16 16:53:09 5: DbLog myDbLogSQL -> 22 of 22 events successfully inserted into table history
2017.01.16 16:53:52 5: DbLog myDbLogSQL -> 18 of 18 events successfully inserted into table history
2017.01.16 17:00:43 5: DbLog myDbLogSQL -> 18 of 18 events successfully inserted into table history

2017.01.23 16:29:55 5: DbLog myDbLogSQL -> 9 of 9 events successfully inserted into table history
2017.01.23 16:30:03 5: DbLog myDbLogSQL -> 3 of 3 events successfully inserted into table history
2017.01.23 16:30:03 4: DbLog myDbLogSQL -> 1 of 1 events successfully inserted into table history
2017.01.23 16:30:03 4: DbLog myDbLogSQL -> 2 of 2 events successfully inserted into table history
...


Ich würde demnach für den Moment einfach nur "insert ignore" hinzufügen und das ganze bis morgen wieder laufen lassen.
Falls Du noch etwas benötigst oder fragen hast... gerne!!


Was mir im Moment noch nicht ganz klar ist:
# Warum sehe ich die fehlerhaften (doppelten) Einträge nicht mit listCache? Dort waren immer nur neue Einträge sichtbar. Kurz vor dem Commit ist die Zahl jedoch (manchmal oder immer?)
stark angestiegen... Kann es sein, dass diese erst zum Commit wieder hinzugefügt werden?

[DS_Starter]

Was mir im Moment noch nicht ganz klar ist:
# Warum sehe ich die fehlerhaften (doppelten) Einträge nicht mit listCache? Dort waren immer nur neue Einträge sichtbar. Kurz vor dem Commit ist die Zahl jedoch (manchmal oder immer?)
stark angestiegen... Kann es sein, dass diese erst zum Commit wieder hinzugefügt werden?

Hmm ... Das sie erst zum Commit wieder hinzugefügt werden können wir ausschließen. Sie können ja nicht aus dem Nichts kommen. Und es gibt niur den einen Cache. Aber zum Zeitpunkt wenn der Hintergrundprozess gestartet wird, wird der Cacheinhalt übergeben und wird 0 bzw. neue Events die danach eintreffen. Wenn der Hintergrundprozess auf Fehler läuft (nicht jeden fange ich momentan ab) gibt er die Daten wieder an den Cach ezurück. Das ist auch eine Weiterentwicklung zur 2.9.2 damit die Daten möglichst nicht verloren gehen (siehe auch stromer-12).

Möglicherweise ist deine Beobachtung so zu erklären. Kann heute nicht mehr so viel darüber nachdenken ... muß morgen zeitig raus 

Grüße
Heiko

[pc1246]

Hallo Heiko
Vielen Dank fuer Deinen Tipp. Jetzt kann ich meine logs wieder editieren. Wie wirkt sich denn die Umstellung von Synchron auf Asynchron aus? Bisher hatte ich ueberflogen, dass das nicht zwingend hilfreich ist? Ich habe leider eine sehr grosse DB und leider auch wenig Ahnung im Umgang mit DBs. Wenn ich count laufen lasse dann dauert das schon ca. 30 Minuten, und fhem ist blockiert. Wenn ich das aendern koennte waere ich schon gluecklich. Auch ein reducelog ist ein schwieriges Unterfangen!
Gruss, und nochmal Danke
Christoph

[DS_Starter]

Hallo Christoph,

schön das es wieder klappt 
Asynchron heißt dass der Schreibvorgang in die DB von den restlichen Abläufen abgekoppelt wird mit dem Nebeneffekt dass die Daten gecacht werden wenn die DB aus irgendwelchen Gründen nicht verfügbar ist. Das heißt das Log-Vorgang passiert erstmal nur im Hauptspeicher und ist deshalb (normalerweise) sehr schnell. Du kannst es ausprobieren und schauen ob es für dich Vorteile bringt.
Das betrifft aber nur das Logging an sich. Die Funktionen count, reducelog laufen wie bisher blockierend. Für die Countfunktion kannst du alternativ 93_DbRep verwenden. Arbeitet nicht blockierend. Reducelog ist natürlich schwioerig, keine Frage.

Nur so als Idee... wenn du ein zweites System hast könntest du dir deine große DB dorthin verchieben und auf deinem Hauptsystem eine neue leere DB anlegen. Dann könntest du auf deinem Zweitsystem Reducelog laufen lassen .... dauert dann sicher sehr,sehr lange. Wenn das durch ist könntest du den reduzierten Datenpool exportieren (geht auch mit DbRep oder einem Tool deiner Wahl) und diesen Export in deine Haupt-DB wieder importieren.

Kannst du ja mal durchdenken. Muß leider für heuete Schluß machen ... die Nacht ist kurz.
Vllt. hat Joe auch noch einen guten Einfall.

viele Grüße
Heiko

[ioT4db]

Nabend allerseits,

ich habe heute Abend eine Datenbankoptimierung angestoßen. Es dauerte etwa 20 Minuten, in denen auch die DB "blockiert" war.

Der Cache lief bei DbLog auch voll, nur wurde er zwischendrinn immer wieder geleert > konnte man in FHEM beobachten. Leider ohne in die DB zu schreiben. Für diese 20 Minuten gibt es keine Einträge in der Datenbank!?

Das sollte doch im async-Modus nicht passieren oder sehe ich das falsch?

Diese Felermeldungen waren im FHEM-Log:

Code Auswählen Erweitern


2017.01.23 21:20:52 1: Timeout for DbLog_PushAsync reached, terminated process 6161
2017.01.23 21:20:52 2: DbLog DBLogging -> DbLog_PushAsync timed out
2017.01.23 21:22:52 1: Timeout for DbLog_PushAsync reached, terminated process 6164
2017.01.23 21:22:52 2: DbLog DBLogging -> DbLog_PushAsync timed out
2017.01.23 21:24:54 1: Timeout for DbLog_PushAsync reached, terminated process 6167
2017.01.23 21:24:54 2: DbLog DBLogging -> DbLog_PushAsync timed out
2017.01.23 21:26:57 1: Timeout for DbLog_PushAsync reached, terminated process 6173
2017.01.23 21:26:57 2: DbLog DBLogging -> DbLog_PushAsync timed out
2017.01.23 21:29:58 1: Timeout for DbLog_PushAsync reached, terminated process 6182
2017.01.23 21:29:58 2: DbLog DBLogging -> DbLog_PushAsync timed out
2017.01.23 21:31:58 1: Timeout for DbLog_PushAsync reached, terminated process 6184
2017.01.23 21:31:58 2: DbLog DBLogging -> DbLog_PushAsync timed out
2017.01.23 21:34:28 1: Timeout for DbLog_PushAsync reached, terminated process 6186
2017.01.23 21:34:28 2: DbLog DBLogging -> DbLog_PushAsync timed out
2017.01.23 21:36:28 1: Timeout for DbLog_PushAsync reached, terminated process 6189
2017.01.23 21:36:28 2: DbLog DBLogging -> DbLog_PushAsync timed out
2017.01.23 21:38:28 1: Timeout for DbLog_PushAsync reached, terminated process 6190
2017.01.23 21:38:28 2: DbLog DBLogging -> DbLog_PushAsync timed out
2017.01.23 21:40:28 1: Timeout for DbLog_PushAsync reached, terminated process 6192
2017.01.23 21:40:28 2: DbLog DBLogging -> DbLog_PushAsync timed out


VG
Daniel

[stromer-12]

Dazu ist das Attribut timeout da, da diese Situation laut DS_Starter nicht anders abgefangen werden kann.
timeout auf 1500 hätte da geholfen.

[ioT4db]

Ah, sehr cool, danke für die schnelle Antwort! Ich lese zwar fleißig mit und jetzt wo Dus schreibst! Habs eigentlich auch schonmal gelesen, nur nicht mehr aufm Schirm gehabt...Manchmal sind die Nächte einfach zu lang

Grüße...

[JoeALLb]

Dazu ist das Attribut timeout da, da diese Situation laut DS_Starter nicht anders abgefangen werden kann.
timeout auf 1500 hätte da geholfen.

2017.01.23 21:22:52 2: DbLog DBLogging -> DbLog_PushAsync timed out
2017.01.23 21:24:54 1: Timeout for DbLog_PushAsync reached, terminated process 6167

Ich vermute, ihr verwendet innodb als Tabellentyp? Ich habe für Loggingtabellen deutlich bessere Erfahrungen mit MyISAM(MySQL) oder Aria(MariaDB) gemacht.
Wäre interessant wenn das jemand von euch testen kann/möchte?!

[JoeALLb]

Bisher hatte ich ueberflogen, dass das nicht zwingend hilfreich ist? Ich habe leider eine sehr grosse DB und leider auch wenig Ahnung im Umgang mit DBs. Wenn ich count laufen lasse dann dauert das schon ca. 30 Minuten, und fhem ist blockiert.

Hallo Christoph,
Wenn Du etwas "experimentierfreudig" bist und auch mal kurz ohne Plots in FHEM leben kannst, habe ich schon Ideen, wie das ganze bei Dir besser laufen kann! Wenn Du also lust hast, schreibe ich Dir ein paar Schritte zusammen die du testen kannst! Keine Sorge, Daten gehen dabei nicht verloren, du brauchst dazu auch keinen zweiten Rechner.
Auf welcher Hardware läuft das ganze denn bei Dir? Selbst auf einem schwachen RPI funktioniert das in der Regel tadellos!

schöne Grüße
Joe

@Heiko: Da würde bei mir wieder ein Wunsch für später aufploppen  :  Es wäre schön, wenn ich ReduceLog, etc. auf eine andere Tabelle als die History ausführen könnte

[ioT4db]

Ich vermute, ihr verwendet innodb als Tabellentyp? Ich habe für Loggingtabellen deutlich bessere Erfahrungen mit MyISAM(MySQL) oder Aria(MariaDB) gemacht.
Wäre interessant wenn das jemand von euch testen kann/möchte?!

Hallo JoeALLb,
in der Tat ist der Tabellentyp bei mir InnoDB (siehe Anhang). Ich nutze MariaDB auf einer Synology. FHEM läuft auf nem RPI.

Der Umstieg von FileLog auf DbLog war mein Weihnachtsprojekt . Habe bis letztes WE getestet und am WE selbst alle FileLogs in die DB importiert. Alles läuft soweit. Der Umstieg ist also grundsätzlich geglückt. Alle Daten sind da und die Plots angepasst.
Trotzdem war ich etwas enttäuscht bzgl. der Performance. Ich hoffte schon schneller als mit FileLog die Plots erstellen zu können. Nachdem ich auch den Index erzeugt hatte, gings schon etwas flotter, aber wenn Du noch weitere Optimierungsvorschläge hast, nur her damit!

Wie würde denn so ein Umstieg von InnoDB nach Aria vonstatten gehen? Warum ist das besser?

An den Schritten, die Du Christoph an die Hand geben möchtest, wäre ich auch interessiert, wenn ich damit die Performance und Konsistenz meiner DB für die Zukunft sichern kann

Danke schonmal...
Daniel

[Tedious]

Naja, ich sags mal so - lagere die Datenbank aus wenn möglich. Jeder Rechner im Netzwerk ist um Welten schneller bei DB-Zugriffen als eine lokale MySQL-DB auf dem Raspberry. Ideal ist eine FHEM-Installation auf einem Nuc bzw. Derivat. Ich habe in einem Raum 9 Plots mit Temperatur, Luftfeuchte und Taupunkt. Die sind bei einem Klick auf den raum in unter 1 Sekunde aufgebaut, quasi verzögerungsfrei "da" - und das ohne SSD, sondern mit einer normalen 2,5'' HDD.

Es gibt da einen passenden Spruch - "man kann aus einer alten Frau kein junges Mädchen machen nur weil man ihr einen Minirock anzieht" Will sagen - ja, man kann immer optimieren, ggf. etwas schneller werden. Eine Signifikanz wird kaum gegeben sein wenn die Hardware limitiert.

[pc1246]

Hallo Christoph,
Wenn Du etwas "experimentierfreudig" bist und auch mal kurz ohne Plots in FHEM leben kannst, habe ich schon Ideen, wie das ganze bei Dir besser laufen kann! Wenn Du also lust hast, schreibe ich Dir ein paar Schritte zusammen die du testen kannst! Keine Sorge, Daten gehen dabei nicht verloren, du brauchst dazu auch keinen zweiten Rechner.
Auf welcher Hardware läuft das ganze denn bei Dir? Selbst auf einem schwachen RPI funktioniert das in der Regel tadellos!
schöne Grüße
Joe

Hallo Joe
Ich habe keine Angst um den Datenverlust. Momentan laeuft es auf einem RPI2, aber ein 3er steht in den Startloechern! Theoretisch haette ich ein xpenology-NAS, wo die DB auch laufen koennte, wenn ich denn wuesste wie! Experimentieren will ich gerne, nur muss ich vorab wissen, wie ich im Ernstfall eine neue DB erstelle, da ich die aktuelle nicht kopieren will! (15GB auf dem RPI) Heute Abend kann ich mich daran machen.
Gruss Christoph

[JoeALLb]

in der Tat ist der Tabellentyp bei mir InnoDB (siehe Anhang). Ich nutze MariaDB auf einer Synology. FHEM läuft auf nem RPI.

Wie würde denn so ein Umstieg von InnoDB nach Aria vonstatten gehen? Warum ist das besser?

Hallo Ihr zwei,

nun, innodb benötigt mehr speicher und hat mehr funktionen, für eine simple Loggingtabelle werden diese meist jedoch nicht benötigt.
Prinzipiell hat innoDB sogar vorteile, jedoch in der täglichen Anwendung ist für mich Aria deutlich besser, performanter und einfacher in der Wartung.

Probiert es doch einfach aus, man kann ja danach wieder zurückwechseln, wenn nötig.

Ich bin mir noch unsicher, wie weit ich meine Vorschläge hier mache, denn manche sind durchauch "advanced"..
Ich betreibe übrigens die SQL-Datenbank selbst ebenfalls auf dem RPI, da er für meine Verhältnisse genügend Leistung bietet.
Ich denke da auch an Stromverbrauch und dauerhafte Verfügbarkeit. Bei 2 getrennten Geräten kann im Hausgebrauch schnell mal eines nicht dauerhaft verfügbar sein.
Meine DB dort (ich habe mehrere Systeme) ist aktuell 24GB groß.

Anbei die Anleitung für Experimentierfreudige:

Sammelt ein paar Messungen, die jetzt besonders lange dauern und deren Zeiten du kennst. (Count benötigt man ja selten )
zB wäre dies eine Abfrage, die man benutzen kann um unnötig geloggte Devices zu erkennen!

Code Auswählen Erweitern

select timestamp, device, reading, value, count(*) as Nr from history group by device, reading order by Nr DESC, device;
Bei Einschränkung auf 1/7 der Daten, benötigt diese Abfrage auf meinem ATOM 21 Sekunden.
Auf dem RPI3 sind es für 34Mio Datensätze 2:37 Minuten, also ~216.560 Datensätze pro Sekunde (und als Ergebnis 4662 DS)

Oder eine typische Abfrage aus den Plots:

Code Auswählen Erweitern

SELECT DATE_FORMAT(TIMESTAMP, '%Y-%m-%d %H:%i:%s'), DEVICE, READING, VALUE FROM history WHERE 1=1 AND DEVICE  = 'Heizung' AND READING = 'actuator' AND TIMESTAMP >= STR_TO_DATE('2017-01-23 00:00:00', '%Y-%m-%d %H:%i:%s') AND TIMESTAMP < STR_TO_DATE('2017-01-24 00:00:01', '%Y-%m-%d %H:%i:%s') ORDER BY TIMESTAMP limit 100;
Diese dauert bei mir bei kalter (frisch gestarteter) Datenbank 0,28s und eignet sich prinzipiell natürlich besonders gut für Tests, das Ergebnis ist aber fast schon zu schnell um genaue Aussagen machen zu können. Es ist aber sehr Praxisbezogen. (Achting, Device und Reading natürlich anpassen!)

Für einen ersten Versuch würde ich dir folgende Schritte, die ich gerade aus einem anderen Thread kopiert habe (DbRep), vorschlagen.

1. Erzeuge eine leere History-Tabelle mit neuem Namen
    --> Frage an Dich: Benötigst Du Unicode? Die Performance ohne ist besser und ich kenne keine Devices (ausser Webradio und Chat), die Unicodes abspeichern müssen.
    Im Beispiel nutze ich mal NICHT unicode, kann aber geändert werden.
2. Benenne die aktuelle history-tabelle um und platziere eine neue, leere Tabelle dort. Dies funktioniert ohne Unterbrechung.
3. Korrigiere/Bereinige die Einträge in der Umbenannten Tabelle: FHEM kann somit völlig ungestört weiterarbeiten.
4. Benenne die Tabellen zurück um:
5. Kopiere die neuen Werte aus der "Temporären leeren History-Tabelle" wieder zurück in die Haupttabelle
6. Lösche die Einträge der temporären History-Tabelle.
7. ggf. PlotFork aktivieren.

zu 1:
Nutzt ihr DbRep? Diese Tabellen haben auch den Index für DbRep, der ggf. entfernt werden kann... gebenchmarked habe ich diesen noch nie.

Code Auswählen Erweitern

CREATE TABLE `historyNEW` (
`TIMESTAMP` DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00',
`DEVICE` VARCHAR(64) NOT NULL DEFAULT '',
`TYPE` VARCHAR(32) NULL DEFAULT NULL,
`EVENT` VARCHAR(512) NULL DEFAULT NULL,
`READING` VARCHAR(64) NOT NULL DEFAULT '',
`VALUE` VARCHAR(64) NULL DEFAULT NULL,
`UNIT` VARCHAR(32) NULL DEFAULT NULL,
        INDEX `DbLogDefault` (`DEVICE`, `READING`, `TIMESTAMP`),
INDEX `Reading_Time_Idx` (`READING`, `TIMESTAMP`) USING BTREE
)
COLLATE='latin1_swedish_ci'
ROW_FORMAT=DYNAMIC
PARTITION BY RANGE (WEEKDAY(timestamp))
(PARTITION mon VALUES LESS THAN (1) ENGINE = Aria,
PARTITION tue VALUES LESS THAN (2) ENGINE = Aria,
PARTITION wed VALUES LESS THAN (3) ENGINE = Aria,
PARTITION thu VALUES LESS THAN (4) ENGINE = Aria,
PARTITION fri VALUES LESS THAN (5) ENGINE = Aria,
PARTITION sat VALUES LESS THAN (6) ENGINE = Aria,
PARTITION sun VALUES LESS THAN (7) ENGINE = Aria);


zu 2: Achtung! Beide Befehle in einer Zeile gemeinsam ausführen, damit es zu keiner Unterbrechung kommt.

Code Auswählen Erweitern

rename table history to historyOLD; rename table historyNEW to history;

Jetzt hast Du eine neue leere History-Tabelle in die alles neue geloggt wird. Jetzt kannst Du die alte Tabelle so verändern, bereinigen, etc. bis sie ok ist und Du sie wieder
an Original-stelle zurück spielst.

zu 3: In diesem Fall würde ich eine weitere neue Tabelle (statt "alter table") nutzen:

Code Auswählen Erweitern

CREATE TABLE `historyWORK` (
`TIMESTAMP` DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00',
`DEVICE` VARCHAR(64) NOT NULL DEFAULT '',
`TYPE` VARCHAR(32) NULL DEFAULT NULL,
`EVENT` VARCHAR(512) NULL DEFAULT NULL,
`READING` VARCHAR(64) NOT NULL DEFAULT '',
`VALUE` VARCHAR(64) NULL DEFAULT NULL,
`UNIT` VARCHAR(32) NULL DEFAULT NULL,
PRIMARY KEY (`DEVICE`, `READING`, `TIMESTAMP`),
INDEX `Reading_Time_Idx` (`READING`, `TIMESTAMP`) USING BTREE
)
COLLATE='latin1_swedish_ci'
ROW_FORMAT=DYNAMIC
PARTITION BY RANGE (WEEKDAY(timestamp))
(PARTITION mon VALUES LESS THAN (1) ENGINE = Aria,
PARTITION tue VALUES LESS THAN (2) ENGINE = Aria,
PARTITION wed VALUES LESS THAN (3) ENGINE = Aria,
PARTITION thu VALUES LESS THAN (4) ENGINE = Aria,
PARTITION fri VALUES LESS THAN (5) ENGINE = Aria,
PARTITION sat VALUES LESS THAN (6) ENGINE = Aria,
PARTITION sun VALUES LESS THAN (7) ENGINE = Aria);


dann

Code Auswählen Erweitern

insert ignore into historyWORK select * from historyOLD;
um die Daten in die neue Tabelle zu bringen. Das wird natürlich eine Weile dauern! ich hoffe Du hast genügend freien Festplattenspeicher.
Hinweis: Je nach DB-Server kann es hier bei InnoDB zu einem Fehler kommen bezüglich Dateihandles. Wenn dem so ist, melde dich nochmal und wir finden einen
Weg.

Führe jetzt mal den Befehl von oben aus und schau, wie lange er jetzt benötigt:

Code Auswählen Erweitern

select timestamp, device, reading, value, count(*) as Nr from historyWORK group by device, reading order by Nr DESC, device;
Und versuche es jetzt nochmal so:

Code Auswählen Erweitern

select timestamp, device, reading, value, count(*) as Nr from historyWORK partition(mon) group by device, reading order by Nr DESC, device;

Zu AriaDB vs. InnoDB:
Meine DB mit ~34Mio Datensätze hat in InnoDB 7GB, in AriaDB 2,3GB.

So, genug für den Moment, weitere Schritte würde ich später nochmal beschreiben, ok?!

Grüße Joe

Edit1: PRIMARY Key in historyNEW durch normalen index getauscht, um im Modul  93_DbRep.pm nicht auf "insert into" umstellen zu müssen. GGf. ändere ich dies später nochmal.
Edit2: Index umbenannt, um Probleme zu vermeiden.
Edit3: Zweites Beispiel für benchmarks ergänzt.
Edit4: Bewertung für 1. Benchmark ergänzt.
Edit5: "select *" ergänzt

[ioT4db]

Hallo und danke für die schnellen Infos!

Klingt interessant und ich möchte das gern ausprobieren. Da es nicht zwischen Tür und Angel machen möchte, werde ich es am WE angehen.

Vorschlag: Wollen wir nicht eine neues Thema aufmachen? "Optimierung Log-Datenbank für DbLog" oder so? Dann kann es hier weiter um die Umstellung der DBLog gehen...

VG...