DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll

[WhyTea]

Hallo
Ich habe aktuell das Problem das die Funktion reduceLobNbl das Fileystem des Maridb-Servers voll schreibt und abbricht.
Die History-Tabelle ist im MyISAM utf8_bin Format und hat aktuell 40.921.621 Datensätze und eine Gesamtgröße von 3,0 GiB.
Das Dateisystem des MariaDB Servers hat aktuell 19 GB frei.
Wenn ich ein

Code Auswählen Erweitern

set mylogdb reduceLogNbl 100 wird eine Tempdatei angelegt die bis zur vollen Größe des verfügbaren Speichers wächst bis der Prozess schließlich abbricht.

Code Auswählen Erweitern

2020.03.18 09:16:14 2: DbLog mylogdb -> DbLog_reduceLogNbl - DBD::mysql::st execute failed: Error writing file '/tmp-mysql/MYpWzFCu' (Errcode: 28 "No space left on device") at /var/fhem/FHEM/93_DbLog.pm line 5121.

Ein

Code Auswählen Erweitern

mysqlcheck -p --check --all-databases
meldet keine Fehler.

Ich weis nicht wo ich ansetzen soll um das Problem zu beheben und hoffe auf Ideen.

Gruß
Daniel

[DS_Starter]

Hallo Daniel,

die DB baut temporäre File(s) für Sortiervorgänge auf. Die Größe ist abhängig von der Anzahl der selektierten Datensätze.
Die freie Größe des Dateisystems von 19GB ist nicht unbedingt aussagefähig.
Relevant ist das Verzeichnis auf den die MySQL Variable my.cnf zeigt:

tmpdir = /whatewer/you/want

Ich hatte zu Ursachen und Lösungsansätzen schon mal etwas geschrieben ->  https://forum.fhem.de/index.php/topic,90597.msg830701.html#msg830701

Vielleicht hilft es dir.

Grüße,
Heiko

[WhyTea]

Hallo Heiko,

danke für Deine Hilfe.
Ich stimme Dir zu das die Aussage etwas unpräzise von mir war.

Code Auswählen Erweitern

datadir         = /var/lib/mysql
tmpdir          = /tmp-mysql


Code Auswählen Erweitern

root@mariadb2:~# df -H /tmp-mysql/
Dateisystem    Größe Benutzt Verf. Verw% Eingehängt auf
/dev/vda1        26G    6,2G   19G   26% /
root@mariadb2:~#


Wie Du siehst werden die temporären Dateinen in /tmp-mysql abgelegt und der Pfad hat aktuell ca. 19GB zur Verfügung.
Wenn ich den Befehl

Code Auswählen Erweitern

set mylogdb reduceLogNbl 100
ausführe kann ich auch live beobachten das in dem Pfad eine temporäre Datei angelegt wird und diese stetig wächst bis kein freier Speicherplatz mehr verfügbar ist. Das dauert ca. 1:30 Minuten.

Code Auswählen Erweitern

2020.03.19 02:05:00 3: DbLog mylogdb: reduceLogNbl requested with DAYS=100
2020.03.19 02:06:29 2: DbLog mylogdb -> DbLog_reduceLogNbl - DBD::mysql::st execute failed: Error writing file '/tmp-mysql/MYhMD6lr' (Errcode: 28 "No space left on device") at /var/fhem/FHEM/93_DbLog.pm line 5121.


Kann es denn sein das bei diesem Prozess temporäre Dateien > 19 GB angelegt werden obwohl die gesamte Datenbank nur 3,1 GB hat?

Code Auswählen Erweitern

root@mariadb2:~# du -h /var/lib/mysql/fhem/
3,1G /var/lib/mysql/fhem/


Gruß
Daniel

[DS_Starter]

Kann es denn sein das bei diesem Prozess temporäre Dateien > 19 GB angelegt werden obwohl die gesamte Datenbank nur 3,1 GB hat?

Also ich bin da auch überrascht, aber bin nicht Spezialist genug um die DB-internen Vorgänge tiefgründig zu untermauern. Da müsste man sich mit dem Thema Sortierung mehr auseinandersetzen.
Möglich wäre sicherlich dass die Daten mehrfach abgelegt werden um Sortiervorgänge durchzuführen.

Versuche doch dich dem Thema zu nähern indem du kleinere Zeitscheiben verwendest, zum Beispiel mit der Zeitangabe:  100:200

Grüße,
Heiko

[WhyTea]

Okay das werde ich als nächstes Versuchen.

Aktuell habe ich eine NFS-share nach /tmp-mysql gemounted und ein reduceLogNbl 100 gestartet.

Das läuft jetzt schon 60 Minuten. Es wurden zwischenzeitlich mehrere Dateien von bis zu 24GB abgelegt.
Und wieder verworfen. Keine Ahnung das da passiert. Ich lasse das jetzt mal einfach laufen und berichte.

Code Auswählen Erweitern

      14 -rw-------  1 mysql   mysql    24G Mär 19 10:30  .nfs000000000000000e00000001
      16 -rw-------  1 mysql   mysql    24G Mär 19  2020  .nfs000000000000001000000003



Wie stoppe ich ein reduceLobNbl?

Just in diesem Moment wurde der Vorgang mit einem Fehler abgebrochen.

Code Auswählen Erweitern

DBD::mysql::st execute failed: MySQL client ran out of memory at /var/fhem/FHEM/93_DbLog.pm line 5121.


Gruß
Daniel

[WhyTea]

Ein reduceLogNbl 200 lief ohne Probleme innerhalb weniger Sekunden durch. :-/

Code Auswählen Erweitern

2020.03.19 11:11:40 3: DbLog mylogdb: reduceLogNbl requested with DAYS=200
2020.03.19 11:11:47 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-04-23
2020.03.19 11:11:47 3: DbLog mylogdb: reduceLogNbl deleting 2 records of day: 2019-04-28
2020.03.19 11:11:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-04-30
2020.03.19 11:11:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-02
2020.03.19 11:11:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-03
2020.03.19 11:11:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-07
2020.03.19 11:11:48 3: DbLog mylogdb: reduceLogNbl deleting 2 records of day: 2019-05-12
2020.03.19 11:11:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-14
2020.03.19 11:11:48 3: DbLog mylogdb: reduceLogNbl deleting 3 records of day: 2019-05-16
2020.03.19 11:11:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-19
2020.03.19 11:11:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-21
2020.03.19 11:11:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-23
2020.03.19 11:11:49 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-27
2020.03.19 11:11:49 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-28
2020.03.19 11:11:49 3: DbLog mylogdb: reduceLogNbl deleting 3 records of day: 2019-05-31
2020.03.19 11:11:49 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-06-04
2020.03.19 11:11:49 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-06-11
2020.03.19 11:11:49 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-06-16
2020.03.19 11:11:50 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-06-24
2020.03.19 11:11:50 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-06-25
2020.03.19 11:11:50 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-06-27
2020.03.19 11:11:50 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-07-02
2020.03.19 11:11:50 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-07-09
2020.03.19 11:11:50 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-07-16
2020.03.19 11:11:52 3: DbLog mylogdb: reduceLogNbl finished. Rows processed: 649669, deleted: 30, time: 12.00sec

reduceLogNbl 180 lief ohne Probleme
reduceLogNbl 160 lief ohne Probleme
reduceLogNbl 140 lief ohne Probleme
reduceLogNbl 120 lief ohne Probleme
reduceLogNbl 110 produziert wieder gigantische temporäre Dateien und läuft noch

[DS_Starter]

Hmm ... ja also vermutilich hast du in deiner DB irgendwo in dem Zeitbereich älter 100 Tage und neuer 200 Tage ein "ungeheure" Menge an Daten die selektiert, sortiert und konsolidiert werden müssen. Das passt auch zu dem Memory Out auf dem Client.
Ich würde dir wirklich empfehlen, jetzt diesen Bereich in mehren Zeitscheiben zu reduzieren , z.B. 100:110, 110:120, 120:130 ...  und so weiter um die Daten in diesem Bereich erstmal klein zu kriegen. Später sollte das nicht mehr nötig sein wenn die Menge reduziert ist.

Ist schon recht merkwürdig  weil so extrem finde ich ...

[WhyTea]

reduceLogNbl 115:120 lief ohne Probleme durch

reduceLogNbl 113:120 produziert wieder gigantische temporäre Dateien und läuft noch

Was mich wieder zu der Frage führt wie breche ich das am sinnvollsten ab?

[WhyTea]

Ich gehe mittlerweile von fehlerhaften Datensätzen in der Datenbank aus die zu diesem Verhalten führen.

Kann ich mit deleteOldDaysNbL auch einzelne Tage löschen?

z.B. deleteOldDaysNbl 112:115

[DS_Starter]

Was mich wieder zu der Frage führt wie breche ich das am sinnvollsten ab?

Mach dir ein DbRep-Device per Kopie falls du schon eins hast, sonst anlegen. In dem dann

get ... procinfo

ausführen. Du siehst im Ergebnisreading ProcessList in der Spalte ID die Processid des laufenden select , z.B. 1341.

Den killst du dann mit dem DbRep mit

set sqlCmd kill 1341

Das DbLog geht dann auf Fehler und du kannst neu starten. Du kannst das reduceLog auch generell in einem DbRep laufen lassen. Im Thread hatte ich erst wieder eine neue Version bereitgestellt:
https://forum.fhem.de/index.php/topic,53584.msg1032788.html#msg1032788

Code Auswählen Erweitern

Kann ich mit deleteOldDaysNbL auch einzelne Tage löschen?
Nein, sowas geht aber alles mit einem DbRep-Device. Hier momentan über Attribute eingestellt. Ich arbeite an einer Erweiterung zur dynamischeren Nutzungsmöglichkeit.

Grüße,
Heiko

[WhyTea]

Ok ein DBRep Device habe ich schon.

Wenn ich also die  Attribute

Code Auswählen Erweitern

attr <name> timeDiffToNow = d:115
attr <name> timeOlderThan = d:112
attr <name> allowDeletion 1
setze und ein

Code Auswählen Erweitern

set <name> reduceLog
ausführe wäre das das gleiche wie ein 

Code Auswählen Erweitern

reduceLogNbl 112:115

richtig?

Und wenn ich ein

Code Auswählen Erweitern

set <name> delEntries
ausführe würde er alle Einträge die älter als 112 Tage und jünger als 115 tage sind löschen.

richtig?

[DS_Starter]

Ja, richtig. Du kannst vorab zum Check ein countEntries ausführen mit verbose 4. Im Log siehst du dann das SQL-Statement und kannst vorab kontrollieren ob du die Zeitgrenzen richtig gesetzt hast und das Modul es auch so umsetzt. Falls man sich unsicher ist, ist es ein probater Weg.

In der Enwicklungsversion geht auch

  reduceLog 112:115

im DbRep

[WhyTea]

gesagt getan...

Code Auswählen Erweitern

2020.03.19 14:35:27 4: DbRep DbRep_Device - -------- New selection ---------
2020.03.19 14:35:27 4: DbRep DbRep_Device - Command: countEntries history
2020.03.19 14:35:27 4: DbRep DbRep_Device - timeDiffToNow - year: , day: 115, hour: , min: , sec:
2020.03.19 14:35:27 4: DbRep DbRep_Device - Year 2020 is leap year
2020.03.19 14:35:27 4: DbRep DbRep_Device - startMonth: 10 endMonth: 2 lastleapyear: 2020 baseYear: 2019 diffdaylight:0 isdaylight:0
2020.03.19 14:35:27 4: DbRep DbRep_Device - timeOlderThan - year: 0, day: 112, hour: 0, min: 0, sec: 0
2020.03.19 14:35:27 4: DbRep DbRep_Device - Year 2020 is leap year
2020.03.19 14:35:27 4: DbRep DbRep_Device - startMonth: 3 endMonth: 10 lastleapyear: 2020 baseYear: 2019 diffdaylight:0 isdaylight:0
2020.03.19 14:35:27 4: DbRep DbRep_Device - FullDay option: 0
2020.03.19 14:35:27 4: DbRep DbRep_Device - Time difference to current time for calculating Timestamp begin: 10022401 sec
2020.03.19 14:35:27 4: DbRep DbRep_Device - Timestamp begin human readable: 2019-11-24 14:35:26
2020.03.19 14:35:27 4: DbRep DbRep_Device - Time difference to current time for calculating Timestamp end: 9763201 sec
2020.03.19 14:35:27 4: DbRep DbRep_Device - Timestamp end human readable: 2019-11-27 14:35:26
2020.03.19 14:35:27 4: DbRep DbRep_Device - Aggregation: no
2020.03.19 14:35:27 4: DbRep DbRep_Device - SQL execute: SELECT COUNT(*) FROM history where TIMESTAMP >= '2019-11-24 14:35:26' AND TIMESTAMP <= '2019-11-27 14:35:26' ;
2020.03.19 14:37:57 3: DbRep DbRep_Device - ################################################################
2020.03.19 14:37:57 3: DbRep DbRep_Device - ###                    new reduceLog run                     ###
2020.03.19 14:37:57 3: DbRep DbRep_Device - ################################################################
2020.03.19 14:37:57 4: DbRep DbRep_Device - -------- New selection ---------
2020.03.19 14:37:57 4: DbRep DbRep_Device - Command: reduceLog
2020.03.19 14:37:57 4: DbRep DbRep_Device - timeDiffToNow - year: , day: 115, hour: , min: , sec:
2020.03.19 14:37:57 4: DbRep DbRep_Device - Year 2020 is leap year
2020.03.19 14:37:57 4: DbRep DbRep_Device - startMonth: 10 endMonth: 2 lastleapyear: 2020 baseYear: 2019 diffdaylight:0 isdaylight:0
2020.03.19 14:37:57 4: DbRep DbRep_Device - timeOlderThan - year: 0, day: 112, hour: 0, min: 0, sec: 0
2020.03.19 14:37:57 4: DbRep DbRep_Device - Year 2020 is leap year
2020.03.19 14:37:57 4: DbRep DbRep_Device - startMonth: 3 endMonth: 10 lastleapyear: 2020 baseYear: 2019 diffdaylight:0 isdaylight:0
2020.03.19 14:37:57 4: DbRep DbRep_Device - FullDay option: 0
2020.03.19 14:37:57 4: DbRep DbRep_Device - Time difference to current time for calculating Timestamp begin: 10022401 sec
2020.03.19 14:37:57 4: DbRep DbRep_Device - Timestamp begin human readable: 2019-11-24 14:37:56
2020.03.19 14:37:57 4: DbRep DbRep_Device - Time difference to current time for calculating Timestamp end: 9763201 sec
2020.03.19 14:37:57 4: DbRep DbRep_Device - Timestamp end human readable: 2019-11-27 14:37:56
2020.03.19 14:37:58 4: DbRep DbRep_Device - SQL execute: SELECT TIMESTAMP,DEVICE,'',READING,VALUE FROM history where  TIMESTAMP >= '2019-11-24 14:37:56' AND TIMESTAMP <= '2019-11-27 14:37:56' ORDER BY TIMESTAMP ASC;
2020.03.19 14:37:58 3: DbRep DbRep_Device - reduce data older than: 2019-11-27 14:37:56, newer than: 2019-11-24 14:37:56
2020.03.19 14:37:58 3: DbRep DbRep_Device - reduceLog requested with options:  INCLUDE -> Devs: % Readings: %

Wie Du siehst habe ich zunächst den Zeitraum gecheckt und dann ein reduceLog ausgeführt.

Leider mit dem selben Ergebnis.

[DS_Starter]

Naja, ein anderes Ergebnis hätte ich jetzt noch nicht erwartet. Wolltest du nicht die Daten in diesen tagen löschen ?

Aber du hast jetzt noch mehr Möglichkieten. Du kannst das reduceLog nur über bestimmte Device und/oder Readings laufen lassen. Dazu setzt du dir die Attr device und reading entsprechend der commandref. Da gibt es sehr viele Varianten.

[Wernieman]

Wennn Datensätze gelöscht werden sollen, braucht man da ein "ORDER BY TIMESTAMP ASC"?