FHEM Forum

FHEM => Automatisierung => Thema gestartet von: g.carls am 05 Juni 2014, 08:26:38

Titel: DbLog: Lang laufende SQL Queries durch Full Table Scans
Beitrag von: g.carls am 05 Juni 2014, 08:26:38
Ich möchte gerne einige Optimierungen für DbLog mit diesem Post anregen.

Das dem DbLog Modul beigefügte Datenbankschema enthält weder eine Definition eines Primary Keys noch eine Index Definition.
Ich verfüge über eine ganze Reihe von 1-wire Sensoren, die Temperaturen protokollieren. Schon nach 3-4 Monaten haben sich 2,5 Mio Datensätze in meiner mySQL Datenbank angesammelt und die Datenbankzugriffe wurden immer langsamer, was sich besonders auf nicht so leistungsfähigen embedded Rechnern bemerkbar macht.

Indizien für die Ursache lassen sich schliesslich mit den Hausmitteln von mySQL sammeln.
In der my SQL Konfiguration (i.d.R. /etc/mysql/my.cfg) folgende Parameter setzen:

log_slow_queries        = /var/log/mysql/mysql-slow.log
long_query_time = 2
log-queries-not-using-indexes


Anschliessend Restart der mySQL Datenbank durchführen.
Ruft man anschliessend in FHEM ein paar Plots (z.B. Temperaturverläufe) auf und schaut anschliessend in diese Log Datei, wird man auf langlaufende nicht indizierte Queries hingewiesen, die Datensätze in der history Tabelle abfragen.

Die Abfragen verwenden dabei immer die Felder DEVICE, READING und TIMESTAMP als Suchkriterien.

Ich habe daher das Tabellenschema wie folgt angepasst:

CREATE TABLE `history` (
  `TIMESTAMP` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `DEVICE` varchar(32) COLLATE utf8_bin NOT NULL DEFAULT '',
  `TYPE` varchar(32) COLLATE utf8_bin DEFAULT NULL,
  `EVENT` varchar(64) COLLATE utf8_bin DEFAULT NULL,
  `READING` varchar(32) COLLATE utf8_bin NOT NULL DEFAULT '',
  `VALUE` varchar(32) COLLATE utf8_bin DEFAULT NULL,
  `UNIT` varchar(32) COLLATE utf8_bin DEFAULT NULL,
  PRIMARY KEY (`DEVICE`,`READING`,`TIMESTAMP`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin
PARTITION BY KEY ()
PARTITIONS 24;


Dieses Schema verwendet die drei Felder DEVICE, READING und TIMESTAMP als Primärschlüssel.
Zusätzlich wird die Tabelle partitioniert, damit große Datenmengen besser gehandhabt werden können.
Mit diesen Änderungen wird man keine Einträge mehr in der mysql-slow.log Datei finden.

Man sollte desweiteren regelmässig in mysql das Kommando

analyze table history;

ausführen, damit die Ermittlung des besten Ausführungsplans für SQL Queries auch nach dem hinzufügen vieler Datensätze noch korrekt erfolgt.

Ich bin dann anschliessend allerdings im fhem Log sporadisch über folgende Fehlermeldungen (insbesondere nach einem restart von fhem) gestolpert:

2014.06.01 06:30:37 2: DbLog: Failed to insert new readings into database: DBD::mysql::st execute failed: Duplicate entry 'E_WS1-isRaining-2014-06-01 06:30:37' for key 'PRIMARY' at ./FHEM/93_DbLog.pm line 447.

Das ist eine Primary Key Constraint Verletzung.
Eigentlich sollte dies ein undenkbarer Fall sein, denn dieser Sensor liefert definitiv keine zwei Messwerte innerhalb der selben Sekunde.
Scheinbar stauen sich jedoch einige Messwerte in der TCP-Queue, wenn der Rechner unter Last ist. Die Queue wird anschliessend innerhalb einer Sekunde abgearbeitet. Da die Zeitstempel nicht vom Sensor kommen sonder direkt von der mySQL Datenbank generiert werden, führt dies zu identischen Zeitstempeln für mehrere Messwerte und damit zu diesem Fehler.
Der Fehler ist jedoch nicht weiter schlimm, denn zwei Messwerte mit identischem Zeitstempel machen ohnehin keinen Sinn.
FHEM setzt seine Arbeit auch fort. Das DBLog Modul sorgt dann für einen Rollback baut allerdings nach dem Rollback jedes Mal die Datenbankverbindung erneut auf, was mir nicht sehr sinnvoll erscheint:

2014.06.01 06:30:37 3: Connecting to database mysql:database=fhem;host=localhost;port=3306 with user fhem
2014.06.01 06:30:37 3: Connection to db mysql:database=fhem;host=localhost;port=3306 established for pid 22833
2014.06.01 06:30:37 3: Connection to db mysql:database=fhem;host=localhost;port=3306 established


Ich möchte daher gerne folgende Erweiterung im Sinne eines Exception Handlings für das DBLog Modul vorschlagen.
Bei Primary Key Constraint Verletzungen erzeugt mySQL den Fehlercode 1062. Diesen kann man also wie folgt abfangen.

Ab Zeile 460 im 93_DbLog.pm Modul sieht es dann wie folgt aus:

if ($@) {
    if ($sth_ih->err() != 1062) {
       Log3 $hash->{NAME}, 2, "DbLog: Failed to insert new readings into database: $@";
       Log3 $hash->{NAME}, 2, "DbLog: err()=".$sth_ih->err();
       # reconnect
       $dbh->rollback();
       $dbh->disconnect(); 
       DbLog_Connect($hash);
    } else {
       $dbh->rollback();
    }
  }
  else {
    $dbh->commit();
    $dbh->{RaiseError} = 0;
    $dbh->{PrintError} = 1;
  }


Diese Änderung führt ledig. dazu, dass nach wie vor ein Rollback durchgeführt wird, jedoch die Datenbankverbindung bei Fehlercode 1063 nicht jedes Mal neu aufgebaut wird.

Den angepassten Code habe ich beigefügt.


Titel: Antw:DbLog: Lang laufende SQL Queries durch Full Table Scans
Beitrag von: stromer-12 am 05 Juni 2014, 10:50:04
Funktioniert das auch mit sqlite?
Titel: Antw:DbLog: Lang laufende SQL Queries durch Full Table Scans
Beitrag von: betateilchen am 05 Juni 2014, 12:35:09
Für sqlite geht das mit der Analyse so einfach nicht.

Was ich aber an der ganzen Sache nicht verstehe: Genau aus diesen Performancegründenliegt doch auf der history normalerweise ein Index, der genau die Felder (Device, Reading, Timestamp). Zumindest wenn man sein DbLog nach den Anweisungen zur Installation eingerichtet hat.