FHEM Forum

FHEM => Sonstiges => Thema gestartet von: WhyTea am 18 März 2020, 13:18:04

Titel: DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 18 März 2020, 13:18:04
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 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. 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 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
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 18 März 2020, 18:36:25
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
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 19 März 2020, 10:03:50
Hallo Heiko,

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

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


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
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.
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?
root@mariadb2:~# du -h /var/lib/mysql/fhem/
3,1G /var/lib/mysql/fhem/


Gruß
Daniel
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 19 März 2020, 10:09:28
ZitatKann 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
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 19 März 2020, 11:10:20
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.
      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.
DBD::mysql::st execute failed: MySQL client ran out of memory at /var/fhem/FHEM/93_DbLog.pm line 5121.


Gruß
Daniel
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 19 März 2020, 11:13:20
Ein reduceLogNbl 200 lief ohne Probleme innerhalb weniger Sekunden durch. :-/ 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
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 19 März 2020, 11:22:00
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 ...
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 19 März 2020, 12:35:11
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?
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 19 März 2020, 12:40:47
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
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 19 März 2020, 12:45:23
ZitatWas 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

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
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 19 März 2020, 14:17:14
Ok ein DBRep Device habe ich schon.

Wenn ich also die  Attribute
attr <name> timeDiffToNow = d:115
attr <name> timeOlderThan = d:112
attr <name> allowDeletion 1

setze und ein
set <name> reduceLog
ausführe wäre das das gleiche wie ein 
reduceLogNbl 112:115

richtig?

Und wenn ich ein
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?
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 19 März 2020, 14:21:13
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
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 19 März 2020, 14:43:50
gesagt getan...

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

Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 19 März 2020, 14:49:07
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.
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: Wernieman am 19 März 2020, 14:55:09
Wennn Datensätze gelöscht werden sollen, braucht man da ein "ORDER BY TIMESTAMP ASC"?
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 19 März 2020, 14:57:32
Hi Werner,

ZitatWennn Datensätze gelöscht werden sollen, braucht man da ein "ORDER BY TIMESTAMP ASC"?
nein, hat er ja auch nicht, sondern reduceLog ausgeführt.
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: Frank_Huber am 19 März 2020, 14:58:17
Sehe ich das im Log richtig dass bei beiden Befehlen keine "Antwort" kommt?
Oder erscheint die nur in den Readings und nicht im Log?

Beim count ist im Log z.B. nach dem SQLexecute Schluss.
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 19 März 2020, 14:59:05
Ja, mit verbose 5 wäre auch das Ergebnis zu sehen, aber das wäre jetzt too much  ;)
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 19 März 2020, 15:00:39
Aber zumindest sehe ich jtzt schon etwas mehr...
801623 fhemuser 192.168.6.113:44396 fhem Query 1118 Creating sort index 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

Allerdings kanni ch den Process nicht mit

set sqlCmd kill 801623

beenden
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 19 März 2020, 15:03:24
Warum nicht ? Irgendwelche Meldung im Log bzw. state ?
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 19 März 2020, 15:13:04
Nein leider nicht. :-(

Das Einzige was man sieht ist
LASTCMD sqlCmd kill 801623

Muss nun auch leider abbrechen. Morgen versuche ich dann die Datensätze zu löschen.
Ich werde berichten!

Bis hierher schon mal vielen Dank für Eure Hilfe!

Daniel
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 19 März 2020, 15:15:45
Na dann bis morgen. Benutze auf jeden Fall die aktuellste Version

  FVERSION  93_DbRep.pm:v8.32.4-s21429/2020-03-15

bzw. die neuste Entwicklungsversion aus dem oben angegebenen Thread.
Die Möglichket für kill habe ich auch noch nicht allzu lange eingebaut.

LG,
Heiko
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: Wernieman am 19 März 2020, 16:04:28
Ich hatte den SQL Befehl aus Seiner Logausgabe ... und da erscheint der "Order by" ... kenne mich aber jetzt mit dem Modul selber zuwenig aus. War deshalb nur eine "Anmerkung"
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 20 März 2020, 08:53:56
Guten Morgen!  :)

Also ich benutze die Version 
FVERSION 93_DbRep.pm:v8.32.4-s21429/2020-03-15

Heute Morgen habe ich erfolgreich ein reduzeLog 100-110 durchführen können.
2020.03.20 08:37:37 3: DbRep DbRep_Device - ################################################################
2020.03.20 08:37:37 3: DbRep DbRep_Device - ###                    new reduceLog run                     ###
2020.03.20 08:37:37 3: DbRep DbRep_Device - ################################################################
2020.03.20 08:37:37 4: DbRep DbRep_Device - -------- New selection ---------
2020.03.20 08:37:37 4: DbRep DbRep_Device - Command: reduceLog
2020.03.20 08:37:37 4: DbRep DbRep_Device - timeDiffToNow - year: , day: 110, hour: , min: , sec:
2020.03.20 08:37:37 4: DbRep DbRep_Device - Year 2020 is leap year
2020.03.20 08:37:37 4: DbRep DbRep_Device - startMonth: 11 endMonth: 2 lastleapyear: 2020 baseYear: 2019 diffdaylight:0 isdaylight:0
2020.03.20 08:37:37 4: DbRep DbRep_Device - timeOlderThan - year: 0, day: 100, hour: 0, min: 0, sec: 0
2020.03.20 08:37:37 4: DbRep DbRep_Device - Year 2020 is leap year
2020.03.20 08:37:37 4: DbRep DbRep_Device - startMonth: 3 endMonth: 11 lastleapyear: 2020 baseYear: 2019 diffdaylight:0 isdaylight:0
2020.03.20 08:37:37 4: DbRep DbRep_Device - FullDay option: 0
2020.03.20 08:37:37 4: DbRep DbRep_Device - Time difference to current time for calculating Timestamp begin: 9590401 sec
2020.03.20 08:37:37 4: DbRep DbRep_Device - Timestamp begin human readable: 2019-11-30 08:37:36
2020.03.20 08:37:37 4: DbRep DbRep_Device - Time difference to current time for calculating Timestamp end: 8726401 sec
2020.03.20 08:37:37 4: DbRep DbRep_Device - Timestamp end human readable: 2019-12-10 08:37:36
2020.03.20 08:37:37 4: DbRep DbRep_Device - SQL execute: SELECT TIMESTAMP,DEVICE,'',READING,VALUE FROM history where  TIMESTAMP >= '2019-11-30 08:37:36' AND TIMESTAMP <= '2019-12-10 08:37:36' ORDER BY TIMESTAMP ASC;
2020.03.20 08:37:37 3: DbRep DbRep_Device - reduce data older than: 2019-12-10 08:37:36, newer than: 2019-11-30 08:37:36
2020.03.20 08:37:37 3: DbRep DbRep_Device - reduceLog requested with options:  INCLUDE -> Devs: % Readings: %
2020.03.20 08:37:37 3: DbRep DbRep_Device - reduceLog deleting 9649 records of day: 2019-11-30


Das bestärkt mich in der Annahme das das Problem zwischen 113 und 116 liegt. Dieser reduzeLog läuft gerade und ich muss warten bis er vor die Wand läuft da wieder gigantische Tempdateien angelegt werden. Also melde ich mich in ca. 1 stunde wieder. Danach versuche ich direkt ein delEntries 113-116 und hoffe das Problem damit beseitigt zu haben.

Wobei mir gerade einfällt kann ich 113-116 vorher extraieren um im Nachgang das eigentlich Problem analysieren zu können?

Gruß
Daniel
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 20 März 2020, 09:41:10
Moin Daniel,

ZitatWobei mir gerade einfällt kann ich 113-116 vorher extraieren um im Nachgang das eigentlich Problem analysieren zu können?
Ja, mit

  set <name> exportToFile

Exportiert die Daten in ein oder mehrere CSV-Dateien. Comref beschreibt genau die Benutzung.

Grüße,
Heiko
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 20 März 2020, 12:24:29
Ich habe ein export versucht.
exportToFile /tmp/export.csv
dies Attribute waren gesetzt.
timeDiffToNow d:116
timeOlderThan d:113

Leider ohne  Erfolg.

Im Dateisytem der Fhem-VM wird die Datei /tmp/export.csv erstellt. Aber sie bleibt leer und der Vorgang bricht nach wenigen Minuten ab.
2020.03.20 12:03:50 4: DbRep DbRep_Device - Export data to file: /tmp/export.csv
2020.03.20 12:03:50 4: DbRep DbRep_Device - SQL execute: SELECT TIMESTAMP,DEVICE,TYPE,EVENT,READING,VALUE,UNIT FROM history where TIMESTAMP >= '2019-11-24 12:03:49' AND TIMESTAMP <= '2019-11-27 12:03:49' ORDER BY TIMESTAMP;
2020.03.20 12:06:44 1: Cannot fork: Cannot allocate memory
2020.03.20 12:06:44 1: Cannot fork: Cannot allocate memory
Out of memory (Needed 2963536 bytes)
2020.03.20 12:06:47 2: DbRep DbRep_Device - DBD::mysql::st execute failed: MySQL client ran out of memory at /var/fhem/FHEM/93_DbRep.pm line 5745.


Die Fhem-VM hat 2GB Ram zugewiesen wovon im normalbetrieb nur 150MB belegt werden. Der Export der Daten aus den vier Tagen kann niemals so groß sein. Ich kann es mir so erklären das die fehlerhaften Daten in der Datenbank beim SELECT eine Art Datenloop verursachen sodaß im Endeffekt unendlich Daten entstehen.

Das ist jetzt nur eine eher laienhafte Vermutung meinerseits da ich mich nicht wirklich mit SQL Datenbanken auskenne.
Anders kann ich mir das Verhalten allerdings nicht mehr erklären.
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: Wernieman am 20 März 2020, 12:36:07
Da es eine mySQL DB (MariaDB),
mal ein "optimize" Table probiert? Nicht das irgendwo etwas "verspult" ist ...
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 20 März 2020, 12:46:26
Irgendwas scheint an den Daten in diesem Bereich sehr faul zu sein. Du kannst auch noch probieren, die CSV in diesem Bereich in noch kleineren Zeitscheiben zu exportieren. Geht ja im Prinzip stundenweise.
Damit du hinterher das mal analysieren kannst was da problematisch war.
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 20 März 2020, 13:26:10
Ein Optimize lief sauber durch.

2020.03.20 12:43:09 3: DbRep DbRep_Device - ################################################################
2020.03.20 12:43:09 3: DbRep DbRep_Device - ###          New optimize table / vacuum execution           ###
2020.03.20 12:43:09 3: DbRep DbRep_Device - ################################################################
2020.03.20 12:43:09 3: DbRep DbRep_Device - Searching for tables inside database fhem....
2020.03.20 12:43:09 3: DbRep DbRep_Device - Size of database fhem before optimize (MB): 3123.67
2020.03.20 12:43:09 3: DbRep DbRep_Device - Optimizing tables
2020.03.20 12:43:09 3: DbRep DbRep_Device - Optimizing table `current` (MYISAM). It will take a while.
2020.03.20 12:43:09 3: DbRep DbRep_Device - Table 1 `current` optimized successfully.
2020.03.20 12:43:09 3: DbRep DbRep_Device - Optimizing table `history` (MYISAM). It will take a while.
2020.03.20 12:56:05 3: DbRep DbRep_Device - Table 2 `history` optimized successfully.
2020.03.20 12:56:05 3: DbRep DbRep_Device - 2 tables have been optimized.
2020.03.20 12:56:05 3: DbRep DbRep_Device - Size of database fhem after optimize (MB): 3115.10
2020.03.20 12:56:05 3: DbRep DbRep_Device - Optimize tables of database fhem finished - total time used (hh:mm:ss): 00:12:55
2020.03.20 12:56:05 3: DbRep DbRep_Device - Optimize tables finished successfully.


Ein anschließender Export nicht.
2020.03.20 13:26:41 4: DbRep DbRep_Device - Export data to file: /tmp/export.csv
2020.03.20 13:26:41 4: DbRep DbRep_Device - SQL execute: SELECT TIMESTAMP,DEVICE,TYPE,EVENT,READING,VALUE,UNIT FROM history where TIMESTAMP >= '2019-11-24 13:26:40' AND TIMESTAMP <= '2019-11-27 13:26:40' ORDER BY TIMESTAMP;
Out of memory (Needed 2963536 bytes)
2020.03.20 13:29:37 2: DbRep DbRep_Device - DBD::mysql::st execute failed: MySQL client ran out of memory at /var/fhem/FHEM/93_DbRep.pm line 5745.
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: Wernieman am 20 März 2020, 13:37:15
@DS_Starter
Weißt Du die exacten SQL-Statements? WÜrde sonst mal vorschlagen, direkt über einen mysql-Client das Problem zu bearbeiten
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 20 März 2020, 13:52:39
Hallo Werner, nein. Es ist nicht nur eins, sondern wird Situationsbezogen zusammengebaut und abgearbeitet.
Ein möglicher Weg ist verbose 5 einzuschalten. Dann sieht man im Log alle generierten und abgearbeiteten Statements sowie Ergebnisse.
Achtung: wird wahrscheinlich sehr unfangreich !
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 20 März 2020, 13:55:37
@Daniel

ZitatEin anschließender Export nicht.
Das sind zwei paar Schuhe und nicht vergleichbar.

Ich würde versuchen noch kleinteileger zu exportieren, stundenweise wie oben angegeben. Mit eingeschalteten verbose 5 kann man später auch sehen bei welcher Zeitscheibe er aussteigt.
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: WhyTea am 20 März 2020, 15:45:23
Ein delEntries mit den Attributen hat funktioniert.
timeDiffToNow d:116
timeOlderThan d:113


2020.03.20 13:33:02 4: DbRep DbRep_Device - -------- New selection ---------
2020.03.20 13:33:02 4: DbRep DbRep_Device - Command: delEntries
2020.03.20 13:33:02 4: DbRep DbRep_Device - timeDiffToNow - year: , day: 116, hour: , min: , sec:
2020.03.20 13:33:02 4: DbRep DbRep_Device - Year 2020 is leap year
2020.03.20 13:33:02 4: DbRep DbRep_Device - startMonth: 10 endMonth: 2 lastleapyear: 2020 baseYear: 2019 diffdaylight:0 isdaylight:0
2020.03.20 13:33:02 4: DbRep DbRep_Device - timeOlderThan - year: 0, day: 113, hour: 0, min: 0, sec: 0
2020.03.20 13:33:02 4: DbRep DbRep_Device - Year 2020 is leap year
2020.03.20 13:33:02 4: DbRep DbRep_Device - startMonth: 3 endMonth: 10 lastleapyear: 2020 baseYear: 2019 diffdaylight:0 isdaylight:0
2020.03.20 13:33:02 4: DbRep DbRep_Device - FullDay option: 0
2020.03.20 13:33:02 4: DbRep DbRep_Device - Time difference to current time for calculating Timestamp begin: 10108801 sec
2020.03.20 13:33:02 4: DbRep DbRep_Device - Timestamp begin human readable: 2019-11-24 13:33:01
2020.03.20 13:33:02 4: DbRep DbRep_Device - Time difference to current time for calculating Timestamp end: 9849601 sec
2020.03.20 13:33:02 4: DbRep DbRep_Device - Timestamp end human readable: 2019-11-27 13:33:01
2020.03.20 13:33:02 4: DbRep DbRep_Device - Aggregation: no
2020.03.20 13:33:02 4: DbRep DbRep_Device - SQL execute: delete FROM history where TIMESTAMP >= '2019-11-24 13:33:01' AND TIMESTAMP <= '2019-11-27 13:33:01' ;
2020.03.20 14:01:08 3: DbRep DbRep_Device - Entries of fhem.history deleted: /--/--30773508


Ein anschließendes reduceLogNbl 100 auch.
2020.03.20 15:40:34 3: DbLog mylogdb: reduceLogNbl requested with DAYS=100
2020.03.20 15:40:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-04-23
2020.03.20 15:40:48 3: DbLog mylogdb: reduceLogNbl deleting 2 records of day: 2019-04-28
2020.03.20 15:40:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-04-30
2020.03.20 15:40:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-02
2020.03.20 15:40:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-03
2020.03.20 15:40:48 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-07
2020.03.20 15:40:49 3: DbLog mylogdb: reduceLogNbl deleting 2 records of day: 2019-05-12
2020.03.20 15:40:49 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-14
2020.03.20 15:40:49 3: DbLog mylogdb: reduceLogNbl deleting 3 records of day: 2019-05-16
2020.03.20 15:40:49 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-19
2020.03.20 15:40:49 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-21
2020.03.20 15:40:49 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-23
2020.03.20 15:40:49 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-27
2020.03.20 15:40:49 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-05-28
2020.03.20 15:40:49 3: DbLog mylogdb: reduceLogNbl deleting 3 records of day: 2019-05-31
2020.03.20 15:40:50 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-06-04
2020.03.20 15:40:50 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-06-11
2020.03.20 15:40:50 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-06-16
2020.03.20 15:40:50 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-06-24
2020.03.20 15:40:50 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-06-25
2020.03.20 15:40:50 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-06-27
2020.03.20 15:40:51 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-07-02
2020.03.20 15:40:51 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-07-09
2020.03.20 15:40:51 3: DbLog mylogdb: reduceLogNbl deleting 1 records of day: 2019-07-16
2020.03.20 15:40:56 3: DbLog mylogdb: reduceLogNbl deleting 7769 records of day: 2019-11-27
2020.03.20 15:40:57 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-27 is: 1000
2020.03.20 15:40:57 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-27 is: 2000
2020.03.20 15:40:58 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-27 is: 3000
2020.03.20 15:40:58 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-27 is: 4000
2020.03.20 15:40:59 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-27 is: 5000
2020.03.20 15:40:59 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-27 is: 6000
2020.03.20 15:41:00 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-27 is: 7000
2020.03.20 15:41:00 3: DbLog mylogdb: reduceLogNbl deleting 17027 records of day: 2019-11-28
2020.03.20 15:41:01 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 1000
2020.03.20 15:41:02 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 2000
2020.03.20 15:41:02 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 3000
2020.03.20 15:41:03 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 4000
2020.03.20 15:41:03 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 5000
2020.03.20 15:41:04 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 6000
2020.03.20 15:41:04 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 7000
2020.03.20 15:41:05 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 8000
2020.03.20 15:41:05 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 9000
2020.03.20 15:41:06 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 10000
2020.03.20 15:41:06 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 11000
2020.03.20 15:41:07 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 12000
2020.03.20 15:41:07 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 13000
2020.03.20 15:41:08 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 14000
2020.03.20 15:41:08 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 15000
2020.03.20 15:41:09 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 16000
2020.03.20 15:41:09 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-28 is: 17000
2020.03.20 15:41:10 3: DbLog mylogdb: reduceLogNbl deleting 20543 records of day: 2019-11-29
2020.03.20 15:41:10 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 1000
2020.03.20 15:41:11 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 2000
2020.03.20 15:41:11 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 3000
2020.03.20 15:41:12 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 4000
2020.03.20 15:41:12 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 5000
2020.03.20 15:41:13 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 6000
2020.03.20 15:41:13 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 7000
2020.03.20 15:41:14 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 8000
2020.03.20 15:41:14 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 9000
2020.03.20 15:41:15 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 10000
2020.03.20 15:41:15 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 11000
2020.03.20 15:41:16 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 12000
2020.03.20 15:41:16 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 13000
2020.03.20 15:41:17 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 14000
2020.03.20 15:41:17 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 15000
2020.03.20 15:41:18 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 16000
2020.03.20 15:41:19 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 17000
2020.03.20 15:41:19 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 18000
2020.03.20 15:41:20 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 19000
2020.03.20 15:41:20 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-29 is: 20000
2020.03.20 15:41:21 3: DbLog mylogdb: reduceLogNbl deleting 6434 records of day: 2019-11-30
2020.03.20 15:41:21 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-30 is: 1000
2020.03.20 15:41:22 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-30 is: 2000
2020.03.20 15:41:22 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-30 is: 3000
2020.03.20 15:41:23 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-30 is: 4000
2020.03.20 15:41:23 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-30 is: 5000
2020.03.20 15:41:24 3: DbLog mylogdb: reduceLogNbl deletion progress of day: 2019-11-30 is: 6000
2020.03.20 15:41:24 3: DbLog mylogdb: reduceLogNbl finished. Rows processed: 1162304, deleted: 51803, time: 50.00sec


Ich habe zwar jetzt 4 Tage Daten verloren aber zumindest funktioniert es jetzt wieder.

Danke für die umfangreiche Hilfe! Ich hoffe ich kann mich bei Gelegenheit mal revanchieren. ;-)
Titel: Antw:DbLog / DbLog_reduceLogNbl - schreibt Dateisystem voll
Beitrag von: DS_Starter am 20 März 2020, 15:48:37
Gratulation  :D  :D  8)