DBlog Error

[DS_Starter]

Naja, eher nicht sooo prickelnd  Und das sind die Zeiten jetzt wo dein System normal läuft. Nun stelle ich mir vor wie sich die Zeiten und die CPU-Belastung entwickeln wenn plötzlich mehrere tausend Datensätze weggeschrieben werden sollen. Das passt dann schon ins Bild was du ganz am Anfang mal erwähnt hast.

Schauen wir mal ...

Aber

Ich logg die Werte auch mal - da sich die Readings ja nicht dynamisch ändern ....

Wie meinst du das ? Diese Readings werfen doch auch regelmäßig einen Event.

[Kai-Alfonso]

Naja, eher nicht sooo prickelnd  Und das sind die Zeiten jetzt wo dein System normal läuft. Nun stelle ich mir vor wie sich die Zeiten und die CPU-Belastung entwickeln wenn plötzlich mehrere tausend Datensätze weggeschrieben werden sollen. Das passt dann schon ins Bild was du ganz am Anfang mal erwähnt hast.

Schauen wir mal ...

Aber Wie meinst du das ? Diese Readings werfen doch auch regelmäßig einen Event.

Vergiß es - get DBRep srvinfo geben auch 2 Readings raus, die background_processing_time und sql_processing_time heißen. Aber halt nur wenn man ein get macht. Hatte erst auf den 2.Blick die gleichen Readings bei DBLog gesehen

[DS_Starter]

ok. Dann sind wir für morgen früh "well prepared" würde ich sagen und lassen uns überraschen.

Erstmal schönen Nachmittag noch !
Heiko

[Kai-Alfonso]

ok. Dann sind wir für morgen früh "well prepared" würde ich sagen und lassen uns überraschen.

Erstmal schönen Nachmittag noch !
Heiko

danke, dir auch Heiko . ich melde mich morgen und danke noch mal für deine Zeit

[Kai-Alfonso]

Moin,

ich hab dir die relevanten Logs mal als Zip angehangen. Verbose 5 hatte ich von 23:58 bis 02:00 auf das DbLog Device


Grüße

Kai

[DS_Starter]

Moin,

"Übeltäter" identifiziert würde ich sagen. Ich habe mal die relevante Stelle rausgezogen.

Code Auswählen Erweitern


2018.01.14 00:10:04 5: DbLog DBLog -> processing event Timestamp: 2018-01-14 00:10:01, Device: doif.Datenvolumenzaehler, Type: DOIF, Event: GesamtGB_Tag: 0, Reading: GesamtGB_Tag, Value: 0, Unit:
2018.01.14 00:10:04 5: DbLog DBLog -> processing event Timestamp: 2018-01-14 00:10:01, Device: doif.Datenvolumenzaehler, Type: DOIF, Event: GesamtGB_Tag: 0, Reading: GesamtGB_Tag, Value: 0, Unit:
2018.01.14 00:10:06 2: DbLog DBLog -> Error table history - DBD::mysql::st execute_array failed: Duplicate entry '2018-01-14 00:10:01-doif.Datenvolumenzaehler-DOIF-GesamtGB_Tag: ' for key 'TIMESTAMP' [err was 1062 now 2000000000]
executing 247 generated 214 errors at ./FHEM/93_DbLog.pm line 1958.


2018.01.14 00:06:05 2: DbLog DBLog -> Error table history - DBD::mysql::st execute_array failed:
executing 148 generated 108 errors at ./FHEM/93_DbLog.pm line 1958.

2018.01.14 00:08:06 2: DbLog DBLog -> Error table history - DBD::mysql::st execute_array failed:
Duplicate entry '2018-01-14 00:08:01-doif.Datenvolumenzaehler-DOIF-GesamtGB_Tag: ' for key 'TIMESTAMP' [err was 1062 now 2000000000]
executing 208 generated 154 errors at ./FHEM/93_DbLog.pm line 1958.


Der störende Datensatz setzt dann den Prozess in Gang.

Das Attribut "commitMode = ac:off_ta:on" könnte helfen die Situation zu entschärfen. Allerdings wundert es mich, dass der doppelte Eintrag mit den gleichen Werten für TIMESTAMP, READING, VALUE bei dir zum Problem führt, da du doch ohne einen primary key arbeitest:

Code Auswählen Erweitern


2018.01.14 00:10:04 4: DbLog DBLog -> AutoCommit mode: ON, Transaction mode: OFF
2018.01.14 00:10:04 5: DbLog DBLog -> Primary Key used in fhem.history: none
2018.01.14 00:10:04 5: DbLog DBLog -> Primary Key used in fhem.current: none


Oder er wird nicht erkannt. Das wäre natürlich schlecht, weil das Modul, wenn es die Verwendung eines PK registriert, die Statements abändert um die Verwendung eines PK zu unterstützen.

Als Massnahme würde ich nun das genannte Attribut setzen.
Aber darüber hinaus müssten wir noch ergründen wieso sich deine DB sich an dem doppelten Datensatz mit Duplicate entry '2018-01-14 00:08:01-doif.Datenvolumenzaehler-DOIF-GesamtGB_Tag: ' for key 'TIMESTAMP' stört. Normalerweise ist sowas kein Problem, im Gegenteil klagen etlicher Nutzer die ohne PK arbeiten (Normalfall) darüber, dass sie doppelte Datensätze im System haben die sie gerne loswerden möchten.
Du hattest ja auch geschrieben, du konntest die DB aus irgendwelchen Gründen nicht auf UTF-8 umstellen, warum eigentlich ?

Ich habe dir mal zum Vergleich auf die Schnelle einen Screenshot aus phpMyAdmin meiner MariaDB Strukturdefinition angehängt. Ich arbeite mit PK, deswegen der Schlüssel an den Feldnamen.

EDIT: Jetzt habe ich mir noch die Performance-Entwicklung angeschaut. Da sieht man ganz deutlich wie deine DB kämpft, im Worst Case Fall waren das so ca. 7 Minuten für einen Schreibvorgang mit 11407 Datensätzen. Da dein FHEM aber offensichtlich weiterhin funktioniert, ist das ein gutes Zeichen, so soll es sein

LG,
Heiko

[Kai-Alfonso]

Moin,

"Übeltäter" identifiziert würde ich sagen. Ich habe mal die relevante Stelle rausgezogen.


Der störende Datensatz setzt dann den Prozess in Gang.

Ah, gut zu wissen - das erklärt auch, wieso dies um kurz nach 0:00 passiert - da resettet die Fritzbox den Counter wieder zurück auf 0. Wieso der Datensatz dann doppelt ist, entzieht sich auch meiner Kenntnis.

Das Attribut "commitMode = ac:off_ta:on" könnte helfen die Situation zu entschärfen. Allerdings wundert es mich, dass der doppelte Eintrag mit den gleichen Werten für TIMESTAMP, READING, VALUE bei dir zum Problem führt, da du doch ohne einen primary key arbeitest:

Habe ich mal gesetzt - was ist der Unterschied zwischen den beiden Commit Modi?

Code Auswählen Erweitern


2018.01.14 00:10:04 4: DbLog DBLog -> AutoCommit mode: ON, Transaction mode: OFF
2018.01.14 00:10:04 5: DbLog DBLog -> Primary Key used in fhem.history: none
2018.01.14 00:10:04 5: DbLog DBLog -> Primary Key used in fhem.current: none





Oder er wird nicht erkannt. Das wäre natürlich schlecht, weil das Modul, wenn es die Verwendung einer PK registriert, die Statements abändert um die Verwendung eines PK zu unterstützen.

Soweit ich weiß, habe ich nur einen Index (siehe Screenshot)

eschrieben, du konntest die DB aus irgendwelchen Gründen nicht auf UTF-8 umstellen, warum eigentlich ?

Also, ich wollte laut configCheck die Feldlängen erhöhen. Bei dem Feld Event sollte es auf 512 Zeichen erhöht werden. Das ging mit utf8 nicht - es kam eine Fehlermeldung bezüglich maximale Größe. Sorry, die Fehlermeldung habe ich mir dummerweise nicht gemerkt - aber unter Latin ist es kein Problem. (Vorsicht, Halbwissen!!! ). Ist es besser, wieder zu utf8 zu wechseln? Hab ich durch Latin nachteile? Soll ich nen Primarykey auf Timestamp setzen?

[DS_Starter]

Habe ich mal gesetzt - was ist der Unterschied zwischen den beiden Commit Modi?

Mit "ac:on" (das ist der default) wird das Commit-Mangement der DB überlassen. Mit "ac:off" steuere ich das Commitment selber im Modul und kann so besser auf bestimmte Situationen reagieren, das ist so eine. So ist jedenfalls der Plan 

Soweit ich weiß, habe ich nur einen Index (siehe Screenshot)

Hmm, jetzt habe ich noch die Idee ob der Index vielleicht als "Unique" definiert ist ? Soll nur "Index" sein. Außerdem enthält er zu viele Spalten. Das ist überflüssig und verbraucht nur Platz. Sieh mal meinen Screenshot als Vergleich.

Das ging mit utf8 nicht - es kam eine Fehlermeldung bezüglich maximale Größe

Komisch, kann ich aber im Moment nix mit anfangen.

Ist es besser, wieder zu utf8 zu wechseln? Hab ich durch Latin nachteile?

Nachteile hast du mit Latin nicht. Es ist manchmal so, dass du z.B. "°C" in der DB gespeichert hast und du mit phpMyAdmin diesen Wert dann nicht so angezeigt bekommst. Also Sonderzeichen, Umlaute etc. sind das Thema. Aber sonst geht es auch so, man muß ja nicht utf-8 einsetzen.

Soll ich nen Primarykey auf Timestamp setzen?

Nein, nicht nur auf TIMESTAMP. Wenn dann so:

Code Auswählen Erweitern


ALTER TABLE `history` ADD PRIMARY KEY(TIMESTAMP, DEVICE, READING);


Wenn in deiner history-Tabelle schon doppelte Datensätze sind die den PK verletzen (wahrscheinlich), geht die Anlage nicht.
Dann könntest du es so versuchen:

Code Auswählen Erweitern


ALTER IGNORE TABLE `history` ADD PRIMARY KEY(TIMESTAMP, DEVICE, READING);


Wenn du damit nicht weiterkommst, kannst du mal hier: https://forum.fhem.de/index.php/topic,65860.0.html eine Mitteilung machen. JoeAllb und auch andere Mitstreiter sind da SQL-Experten.

Als weitere Variante könntest du diesen Datensatz auch vom Logging ausschließen. Dazu kann man das Attribut "valueFn" benutzen. Wie das geht zeige ich dir wenn du das machen möchtest.

LG,
Heiko

[Kai-Alfonso]

Hoi,

mein search.ldx sieht genauso aus, aber ich habe noch ein weiteren Index TIMESTAMP mit ziemlich vielen Spalten und der ist unique. Der ist bei current und bei history. Kein Plan, wo der herkommt - soll ich den löschen?

[DS_Starter]

Hi Kai,

denke da haben wir die Wurzel des Übels gefunden 

Den Index TIMESTAMP  löschen, ja, in beiden Tabellen !  In der current brauchst du ohnehin keinerlei Index.

Aber vorher würde ich versuchen den PK anzulegen wie vorhin geschrieben. Aber nur wenn du mit PK arbeiten willst. Hätte den Vorteil dass die DB doppelte Sätze von sich aus unterbindet.
Wenn du das nicht willst, einfach den Index nur löschen.

EDIT: Wie groß ist eigentlich deine DB ?

Grüße
Heiko

[Kai-Alfonso]

Ich dachte mir das, als du das mit unique index erwähnt hattest. Hab jetzt einen primary key mit

Code Auswählen Erweitern

ALTER IGNORE TABLE `history` ADD PRIMARY KEY(TIMESTAMP, DEVICE, READING);

angelegt, weil der sonst den doppelten Datensatz angemeckert hat.

Und die beiden Indexe gelöscht - sieht jetzt so aus, wie es soll meine ich (siehe Screenshot)

mal heute abend schauen  - aber der Fehler klingt logisch

[DS_Starter]

Das sieht gut aus   

Theoretisch brauchst du den Search_Idx jetzt auch nicht mehr wenn du den PK hast, aber ich muss gestehen bei mir ist er auch noch drin.
Jetzt mit PK, setzt du dir verbose im DbLog am Besten auf 2. Sonst bekommst du "Fehlermitteilungen" im Log wenn der PK zuschlägt und das Schreiben eines doppelten Datensatzes verhindert ... also dran denken wenn sowas kommt !

Also ich wette mit dir, dass das Problem jetzt erledigt ist ... 

LG,
Heiko

[Kai-Alfonso]

 

Also ich wette mit dir, dass das Problem jetzt erledigt ist ... 

LG,
Heiko

Ich glaube auch  - vielen Dank für deine Hilfe und Geduld

[DS_Starter]

Gern geschehen, war ja auch ein interressanter Problemfall. 
Ich nehme auch noch etwas mit ... nämlich dass ich in den configCheck versuche eine Prüfung einzubauen ob der User irgendwelche Indizes angelegt hat die "Unique" sind. Dann würde es nämlich gleich dort auffallen.

LG,
Heiko

[Kai-Alfonso]

Guten Morgen 

Gute Nachrichten - die DB ist nicht mehr all fucked up ab 0:00, sondern läuft locker flockig durch. Wie Du schon vermutet hattest, war der Fehler eher datenbankseitig zu sehen. Verfluchter index 


Soll ich irgendwelche Attribute, die wir (testweise) gesetzt hatten, wieder zurücksetzen/löschen (cacheLimit zum Beispiel)?

Code Auswählen Erweitern

Attributes:
   DbLogSelectionMode Include
   DbLogType  Current/History
   asyncMode  1
   cacheEvents 2
   cacheLimit 100000
   commitMode ac:off_ta:on
   group      Datenbank
   room       Konfiguration
   showproctime 1
   shutdownWait 3
   syncInterval 120
   useCharfilter 1
   verbose    2