DbLog: Ausreisser bei Laufzeiten

[PatrickR]

Hallo zusammen,

ich stellte vor einiger Zeit von FileLog auf DbLog um. Die Hoffnung war ein Performancegewinn und natürlich eine strukturiertere Datenablage. Während ich die Funktionalität zu schätzen gelernt habe, habe ich vereinzelt Performanceprobleme. Sowohl bei Verwendung von sqlite als auch bei MySQL habe ich Ausreisser bei der Laufzeit, die sich in Einträgen wie dem folgenden äußern:

Code Auswählen Erweitern


name             function       max   count    total          average maxDly
DbLog            DbLog_Log  6031  70744   3037086    42.93      0         HASH(DbLog); HASH(OG.WO.VR100)


Der Durchschnittwert ist mit knapp 43ms durchaus akzeptabel, der Maximalwert mit 6000ms jedoch nicht. Um das Dateisystem als Quelle des Problems auszuschließen setzte ich testweise main.synchronous bei sqlite auf 0, hatte jedoch immer noch Ausreisser über 2000s. Nun mit MySQL bekomme ich die oben gezeigten 6000ms, die sogar die 5s Sicherheitsmarge im wdTimer meines HM-CFG-LAN überschreiten. Mit verbose 5 auf dem DbLog-Device hatte ich leider lediglich Meldungen, welche Werte aktuell in die DB geschrieben werden, jedoch nichts für das Debugging Hilfreiches.

Zum Setup:
FHEM und der MySQL Server laufen auf zwei virtuellen Maschinen via KVM auf einem Debian Host. Das Netz zwischen den vms ist gebridged. mysqltuner ist voll zufrieden mit der Performance.

Habt Ihr einen Tipp, wie ich das Problem näher eingrenzen kann?

Patrick

[limats]

Hallo Patrick,

hatte vor einiger Zeit ein ähnliches Problem.
Bei mir lag das daran, dass die Spaltenlängen für Device-Name und Reading-Name in der DB auf 32 Zeichen begrenzt sind.
Die DB schneidet längere Strings beim Schreiben einfach ab.
DbLog sucht vor dem Schreiben in die CURRENT Tabelle nach der Device-Reading-Kombination und will diese updaten, wenn sie bereits existiert.
Bei Device- bzw. Reading-Name, die länger als 32 Zeichen sind, führt das dazu, dass er die (abgeschnittenen) Zeilen nicht findet und immer wieder eine neue anlegt. Und beim Update auch alle gleichzeitig Updaten will. Das dauert dann so lange.
Schau einfach mal, ob in deiner Current Tabelle doppelte Einträge (Device + Reading) sind.
Falls das der Fall ist: Entweder Spaltenbreiten in der DB vergrößern oder deine Devices umbenennen. Anschließend alle doppelten Einträge aus der Current Tabelle löschen.

Wenn dir das nicht weiterhilft:
Bau die selbst ein paar Log-Statements in das DbLog ein, die den SQL-Befehl rausloggen. Wenn du zusätzlich noch eine Logmeldung vor und nach dem Absetzen des SQL-Befehls einbaust, kannst du sehr gut sehen, wo die Zeit verbraten wird.
Die bereits eingebauten Log-Meldungen helfen da tatsächlich nicht viel.

[justme1968]

schau dir mal DbLogType an und setz es auf History.

dann wird die curtent tablle gar nicht mehr benutzt. unabhängig von der spaltenbreite spart das einiges an an io und aufräumen.

gruss
  andre

[PatrickR]

Danke für die Antworten!

DbLogType steht schon auf History. Sorry, hatte ich nicht erwähnt.

Da ich wegen der Virtualisierung auf ein Problem mit der Disk I/O tippe, werde ich mir mal innodb_flush_method genauer ansehen, vermutlich gepaart mit dem aufgebohrten Logging.

Patrick


Von unterwegs gesendet.

[PatrickR]

Mahlzeit!

Mal ein kleines Update. Habe diverse portenzielle Fehlerquellen ausgeschlossen

• innodb_flush_method O_DIRECT, O_DSYNC
• Diverse Versuche, die Disk-I/O der KVMs zu tunen
• DNS
• Versuch ohne Index auf der DB.

Festzustellen ist, dass ich sehr viel logge. Da DbLog in einem Aufruf über alle zu erstellenden Einträge iteriert, summieren sich die Zeiten auf, wie man an den folgenden (zusätzlichen) Log-Einträgen (ausschließlich die Ausreißer) sieht:

2015.10.24 03:40:16.411 5: DbLog: DbLog_Log: Finished, 3 operation(s) took 3.46s (1.07s,2.00s,0.39s).
2015.10.24 04:15:03.622 5: DbLog: DbLog_Log: Finished, 6 operation(s) took 3.13s (0.56s,0.71s,0.39s,0.16s,0.53s,0.78s).
2015.10.24 08:40:26.416 5: DbLog: DbLog_Log: Finished, 3 operation(s) took 3.09s (2.20s,0.60s,0.29s).
2015.10.24 10:05:26.032 5: DbLog: DbLog_Log: Finished, 3 operation(s) took 3.06s (2.00s,0.65s,0.41s).
2015.10.24 10:55:24.847 5: DbLog: DbLog_Log: Finished, 1 operation(s) took 3.00s (3.00s).

Die Zeiten in Klammern sind die Einzellaufzeiten der DbLog_Push-Aufrufe eines(!) DbLog_Log-Durchlaufs.
Der zweite Eintrag wurde ohne die oben genannte Schleife nicht ins Gewicht fallen, der letzte Eintrag zeigt jedoch, dass auch bei exakt einer Zeile pro DbLog_Log Ausreisser vorkommen. Die Zeiten der DbLog_Push-Aufrufe resultieren im Wesentlichen aus der Dauer des commits.

Weitere Ideen?

Patrick

[PatrickR]

Mahlzeit!

Mal ein Update. Ich konnte durch Änderung der MySQL-Config die Laufzeit massiv senken:

Code Auswählen Erweitern


innodb_flush_log_at_trx_commit = 2

Den Performance-Boost gibt es natürlich nicht umsonst sondern auf Grund von (in meinen Augen im FHEM-Umfeld akzeptablen) Einbußen der Daten-Integrität: https://dba.stackexchange.com/questions/12611/is-it-safe-to-use-innodb-flush-log-at-trx-commit-2/12612

Patrick

[PatrickR]

Mahlzeit!

Noch ein kleines Update: Ich konnte die Laufzeiten durch Wechsel von InnoDB auf MyISAM noch einmal drastisch reduzieren:

Code Auswählen Erweitern

ALTER TABLE history ENGINE = MyISAM;

Die Notwendigkeit der oben angegebenen Config-Änderung entfällt dann natürlich auch.

Die Nachteile (im Wesentlichen die fehlende ACID-Konformität) stören mich nicht wirklich und sind für den Einsatzzweck m. E. auch nicht dramatisch. Vermutlich kann man auch aus InnoDB noch etwas herausholen. Dem Vernehmen nach - ich bin kein Datenbankexperte - hängen die INSERT-Zeiten bei InnoDB u. a. von Existenz und konkreter Ausgestaltung des Primärschlüssels ab.

Patrick

[JoeALLb]

Man könnte beim insert auf die Transaktion verzichten,  macht meiner Meinung nach beim logging keinen Sinn.

MariaDB war im meinem Test auch besser als Mysql.
Index habe ich auch angepasst, ist dadurch aber nicht schneller geworden, manche Abfragen wurden aber beschleunigt.

Edit: und das umstellen von UTF 8 auf einen normalen Zeichensatz bringt auch einiges.

[PatrickR]

Man könnte beim insert auf die Transaktion verzichten,  macht meiner Meinung nach beim logging keinen Sinn.

MariaDB war im meinem Test auch besser als Mysql.
Index habe ich auch angepasst, ist dadurch aber nicht schneller geworden, manche Abfragen wurden aber beschleunigt.

Mein Problem war eigentlich das Schreiben. Mein exzessives Logging in Kombination mit der Commit-nach-jeder-Zeile-Implementierung war wohl zu viel...

Patrick

[JoeALLb]

Wie oben ergänzt : denk mal über Unicode nach...  Das ist hier auch nicht nötig.