93_DbLog - Umstellung Log-Funktion auf non-blocking

[JoeALLb]

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

Wunsch#3:

Code Auswählen Erweitern

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.

[stromer-12]

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

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

[eldrik]

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

Code Auswählen Erweitern

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?

Code Auswählen Erweitern

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):

Code Auswählen Erweitern

/opt/fhem/db.conf (.*:(bewegung|loadpct|bcharge|timeleft).*)|(Heizungspumpe_A:o.*)|(Heizungspumpe_B:o.*)

Irgendwelche Hinweise?

Greetz
Eldrik

[DS_Starter]

Hi eldrik,

der Logeintrag

2017.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:

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

[DS_Starter]

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

[JoeALLb]

@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....!

[eldrik]

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

[stromer-12]

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

[JoeALLb]

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!

[stromer-12]

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

[Tobias]

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

[JoeALLb]

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

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.

[stromer-12]

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:

Code Auswählen Erweitern

ALTER TABLE fhem.current ADD INDEX Search_Idx (DEVICE, READING) USING BTREE;
Die InnoDB Tabellen sind einzeln Dateien.

[stromer-12]

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.

[JoeALLb]

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.