DbLog reduceLog Fehler

[Virsacer]

Hallo,
ich habe jetzt schon öfters gesehen, dass reduceLog nicht immer alles löscht.
Hatte es dann mehrmals manuell ausgeführt, bis alles in Ordnung war und meine automatische Ausführung auf 2x hintereinander gestellt, aber das bringt auch nur bedingt etwas...

Kann man den Fehler irgendwie etwas genauer lokalisieren?

Code Auswählen Erweitern

2018.10.07 23:56:00 3: DbLog DBLOG: reduceLogNbl requested with DAYS=7, AVERAGE=HOUR, EXCLUDE=Heatermeter.*,Shutter:pct,Thermostat.*:desired-temp,Watermeter.*
2018.10.07 23:56:21 3: DbLog DBLOG: reduceLogNbl deleting 738 records of day: 2018-09-23
2018.10.07 23:56:21 3: DbLog DBLOG: reduceLogNbl ! FAILED ! for day 2018-09-23
2018.10.07 23:56:22 3: DbLog DBLOG: reduceLogNbl deleting 5936 records of day: 2018-09-24
2018.10.07 23:56:22 3: DbLog DBLOG: reduceLogNbl ! FAILED ! for day 2018-09-24
2018.10.07 23:56:22 3: DbLog DBLOG: reduceLogNbl deleting 5971 records of day: 2018-09-25
2018.10.07 23:56:22 3: DbLog DBLOG: reduceLogNbl ! FAILED ! for day 2018-09-25
2018.10.07 23:56:23 3: DbLog DBLOG: reduceLogNbl deleting 5959 records of day: 2018-09-26
2018.10.07 23:56:23 3: DbLog DBLOG: reduceLogNbl ! FAILED ! for day 2018-09-26
2018.10.07 23:56:23 3: DbLog DBLOG: reduceLogNbl deleting 5935 records of day: 2018-09-27
2018.10.07 23:56:23 3: DbLog DBLOG: reduceLogNbl ! FAILED ! for day 2018-09-27
2018.10.07 23:56:24 3: DbLog DBLOG: reduceLogNbl deleting 5281 records of day: 2018-09-28
2018.10.07 23:56:24 3: DbLog DBLOG: reduceLogNbl ! FAILED ! for day 2018-09-28
2018.10.07 23:56:24 3: DbLog DBLOG: reduceLogNbl deleting 5962 records of day: 2018-09-29
2018.10.07 23:56:24 3: DbLog DBLOG: reduceLogNbl ! FAILED ! for day 2018-09-29
2018.10.07 23:56:24 3: DbLog DBLOG: reduceLogNbl deleting 5220 records of day: 2018-09-30
2018.10.07 23:56:24 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-30 is: 1000
2018.10.07 23:56:25 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-30 is: 2000
2018.10.07 23:56:25 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-30 is: 3000
2018.10.07 23:56:25 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-30 is: 4000
2018.10.07 23:56:25 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-30 is: 5000
2018.10.07 23:56:25 3: DbLog DBLOG: reduceLogNbl (hourly-average) updating 189 records of day: 2018-09-30
2018.10.07 23:56:25 3: DbLog DBLOG: reduceLogNbl (hourly-average) updating progress of day: 2018-09-30 is: 100
2018.10.07 23:56:25 3: DbLog DBLOG: reduceLogNbl finished. Rows processed: 248691, deleted: 41002, updated: 189, excluded: 148601, time: 25.00sec


Code Auswählen Erweitern


2018.10.07 23:57:00 3: DbLog DBLOG: reduceLogNbl requested with DAYS=7, AVERAGE=HOUR, EXCLUDE=Heatermeter.*,Shutter:pct,Thermostat.*:desired-temp,Watermeter.*
2018.10.07 23:57:21 3: DbLog DBLOG: reduceLogNbl deleting 738 records of day: 2018-09-23
2018.10.07 23:57:21 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-23 is: 100
2018.10.07 23:57:21 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-23 is: 200
2018.10.07 23:57:21 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-23 is: 300
2018.10.07 23:57:21 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-23 is: 400
2018.10.07 23:57:21 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-23 is: 500
2018.10.07 23:57:21 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-23 is: 600
2018.10.07 23:57:21 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-23 is: 700
2018.10.07 23:57:21 3: DbLog DBLOG: reduceLogNbl (hourly-average) updating 27 records of day: 2018-09-23
2018.10.07 23:57:22 3: DbLog DBLOG: reduceLogNbl deleting 5936 records of day: 2018-09-24
2018.10.07 23:57:22 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-24 is: 1000
2018.10.07 23:57:22 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-24 is: 2000
2018.10.07 23:57:22 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-24 is: 3000
2018.10.07 23:57:22 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-24 is: 4000
2018.10.07 23:57:22 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-09-24 is: 5000
2018.10.07 23:57:22 3: DbLog DBLOG: reduceLogNbl (hourly-average) updating 216 records of day: 2018-09-24
2018.10.07 23:57:22 3: DbLog DBLOG: reduceLogNbl (hourly-average) updating progress of day: 2018-09-24 is: 100
2018.10.07 23:57:22 3: DbLog DBLOG: reduceLogNbl (hourly-average) updating progress of day: 2018-09-24 is: 200
2018.10.07 23:57:23 3: DbLog DBLOG: reduceLogNbl deleting 5971 records of day: 2018-09-25
2018.10.07 23:57:23 3: DbLog DBLOG: reduceLogNbl ! FAILED ! for day 2018-09-25
2018.10.07 23:57:23 3: DbLog DBLOG: reduceLogNbl deleting 5959 records of day: 2018-09-26
2018.10.07 23:57:23 3: DbLog DBLOG: reduceLogNbl ! FAILED ! for day 2018-09-26
2018.10.07 23:57:24 3: DbLog DBLOG: reduceLogNbl deleting 5935 records of day: 2018-09-27
2018.10.07 23:57:24 3: DbLog DBLOG: reduceLogNbl ! FAILED ! for day 2018-09-27
2018.10.07 23:57:24 3: DbLog DBLOG: reduceLogNbl deleting 5281 records of day: 2018-09-28
2018.10.07 23:57:24 3: DbLog DBLOG: reduceLogNbl ! FAILED ! for day 2018-09-28
2018.10.07 23:57:24 3: DbLog DBLOG: reduceLogNbl deleting 5962 records of day: 2018-09-29
2018.10.07 23:57:24 3: DbLog DBLOG: reduceLogNbl ! FAILED ! for day 2018-09-29
2018.10.07 23:57:25 3: DbLog DBLOG: reduceLogNbl finished. Rows processed: 243474, deleted: 35782, updated: 243, excluded: 148602, time: 25.00sec

PS: Davor mach ich immer noch ein "deleteOldDays" und danach ein "userCommand VACUUM" und ein "reopen"

[yersinia]

Ich kann dieses Verhalten bestätigen. Wenn ich average mit angebe, werden die Einträge nicht auf eine Stunde gemittelt sondern ganz gelöscht. Ich hatte dies auf das nicht numerische Speichern der Werte zurückgeführt - von einem String kann man schlecht ein Durchschnitt bilden.
Seither lass' ich average weg, damit bleibt der erste Eintrag pro Device und Stunde stehen, was mir genügt.

[DS_Starter]

Hallo zusammen,

die Mitteilung "! FAILED !" ist eine Meldung der Datenbankschnittstelle die ich momentan noch nicht sicher einordnen kann, sondern nur eine Vermutung habe. Ich gehe jetzt mal stark davon aus dass ihr SQLite einsetzt ?

Damit man etwas mehr sieht, habe ich die Ausgaben für reduceLogNbl erweitert und eine Version von DbLog im contrib zum Download bereitgestellt:

https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

Über den Downloadbutton nach .../FHEM laden und danach reload bzw. restart ausführen.

Wenn ihr dann reduceLogNbl ausführt, sollte damit nicht nur "FAILED" ausgeschrieben werden, sondern auch eine konkretere Fehlermitteilung.

LG,
Heiko

[Virsacer]

Danke für die schnelle Hilfe

Vor den $err fehlte noch ein "my"...

Und reduceLog lief jetzt natürlich ohne Fehler durch

Werde es jetzt erstmal so laufen lassen und die nächsten Tage dann nochmal schauen/berichten...

[DS_Starter]

Wie das Leben so spielt 

Ja, Mist mit dem "my". Habe es korrigiert und lade das Modul wieder nach contrib.

[Virsacer]

So, jetzt hab ich was, die Datenbank ist manchmal anscheinend noch gesperrt:

Code Auswählen Erweitern

2018.10.14 23:56:00 3: DbLog DBLOG: reduceLogNbl requested with DAYS=7, AVERAGE=HOUR, EXCLUDE=Heatermeter.*,Shutter:pct,Thermostat.*:desired-temp,Watermeter.*
2018.10.14 23:56:23 3: DbLog DBLOG: reduceLogNbl deleting 740 records of day: 2018-09-30
2018.10.14 23:56:23 2: DbLog DBLOG - reduceLogNbl ! FAILED ! for day 2018-09-30: DBD::SQLite::st execute failed: database is locked at ./FHEM/93_DbLog.pm line 4286.

2018.10.14 23:56:23 3: DbLog DBLOG: reduceLogNbl deleting 5990 records of day: 2018-10-01
2018.10.14 23:56:23 2: DbLog DBLOG - reduceLogNbl ! FAILED ! for day 2018-10-01: DBD::SQLite::st execute failed: database is locked at ./FHEM/93_DbLog.pm line 4286.

2018.10.14 23:56:24 3: DbLog DBLOG: reduceLogNbl deleting 5926 records of day: 2018-10-02
2018.10.14 23:56:24 2: DbLog DBLOG - reduceLogNbl ! FAILED ! for day 2018-10-02: DBD::SQLite::st execute failed: database is locked at ./FHEM/93_DbLog.pm line 4286.

2018.10.14 23:56:24 3: DbLog DBLOG: reduceLogNbl deleting 5917 records of day: 2018-10-03
2018.10.14 23:56:24 2: DbLog DBLOG - reduceLogNbl ! FAILED ! for day 2018-10-03: DBD::SQLite::st execute failed: database is locked at ./FHEM/93_DbLog.pm line 4286.

2018.10.14 23:56:25 3: DbLog DBLOG: reduceLogNbl deleting 6016 records of day: 2018-10-04
2018.10.14 23:56:25 2: DbLog DBLOG - reduceLogNbl ! FAILED ! for day 2018-10-04: DBD::SQLite::st execute failed: database is locked at ./FHEM/93_DbLog.pm line 4286.

2018.10.14 23:56:25 3: DbLog DBLOG: reduceLogNbl deleting 5956 records of day: 2018-10-05
2018.10.14 23:56:25 2: DbLog DBLOG - reduceLogNbl ! FAILED ! for day 2018-10-05: DBD::SQLite::st execute failed: database is locked at ./FHEM/93_DbLog.pm line 4286.

2018.10.14 23:56:26 3: DbLog DBLOG: reduceLogNbl deleting 6007 records of day: 2018-10-06
2018.10.14 23:56:26 2: DbLog DBLOG - reduceLogNbl ! FAILED ! for day 2018-10-06: DBD::SQLite::st execute failed: database is locked at ./FHEM/93_DbLog.pm line 4286.

2018.10.14 23:56:26 3: DbLog DBLOG: reduceLogNbl deleting 5223 records of day: 2018-10-07
2018.10.14 23:56:26 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-10-07 is: 1000
2018.10.14 23:56:26 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-10-07 is: 2000
2018.10.14 23:56:26 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-10-07 is: 3000
2018.10.14 23:56:26 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-10-07 is: 4000
2018.10.14 23:56:26 3: DbLog DBLOG: reduceLogNbl deletion progress of day: 2018-10-07 is: 5000
2018.10.14 23:56:26 3: DbLog DBLOG: reduceLogNbl (hourly-average) updating 189 records of day: 2018-10-07
2018.10.14 23:56:26 3: DbLog DBLOG: reduceLogNbl (hourly-average) updating progress of day: 2018-10-07 is: 100
2018.10.14 23:56:26 3: DbLog DBLOG: reduceLogNbl finished. Rows processed: 263202, deleted: 41775, updated: 189, excluded: 160828, time: 26.00sec

Zeile 4286 ist bei mir hier:

Code Auswählen Erweitern

                            eval {
    my $i = 0;
my $k = 1;
my $th = ($#dayRows <= 2000)?100:($#dayRows <= 30000)?1000:10000;
                                for my $delRow (@dayRows) {
                                    if($day != 00 || $delRow->[0] !~ /$lastHour/) {
                                        Log3($name, 4, "DbLog $name: DELETE FROM history WHERE (DEVICE=$delRow->[1]) AND (READING=$delRow->[3]) AND (TIMESTAMP=$delRow->[0]) AND (VALUE=$delRow->[4])");
/*4286*/                                        $sth_del->execute(($delRow->[1], $delRow->[3], $delRow->[0], $delRow->[4]));
$i++;
if($i == $th) {
    my $prog = $k * $i;
    Log3($name, 3, "DbLog $name: reduceLogNbl deletion progress of day: $processingDay is: $prog");
$i = 0;
$k++;
}
                                    }
                                }
                            };

Bei der 2. Ausführung direkt danach ist er diesmal wieder komplett durchgelaufen...

[DS_Starter]

So, jetzt hab ich was, die Datenbank ist manchmal anscheinend noch gesperrt:

Das ist absolut richtig und ich hatte es vermutet und wollte aber die Bestätigung erhalten:

Code Auswählen Erweitern


reduceLogNbl ! FAILED ! for day 2018-10-03: DBD::SQLite::st execute failed: database is locked


SQLite ist leider nicht so "gentle" wie zum Beispiel MySQL/MariaDB was gleichzeitige Schreibvorgänge betrifft. Der konkurrierende Schreibzugriff wird durch das normale logging der Events verursacht.

Du kannst zur Lösung des Problems die DB vorübergehend mit "set ... reopen 3600" (Zeit entsprechend der voraussichtilichen Dauer des reduceLog) für das Logging sperren. Da du DbLog im asynchronen Mode betreibst gehen dir auch keine Events verloren das sie gecacht werden. Nach der Aktion mit "set ... reopen" wieder öffnen.

Derzeit arbeite ich daran reduceLog im DbRep einzubauen. Dort hat man dann neben besseren Zeiteingrenzungsmöglichkeiten über Attribute ebenfalls die Möglichkeit einen Vor- bzw. Nach-Befehl abzusetzen. Dann kann der Ablauf integrativ mit diesen reopen-Befehlen abgearbeitet werden.

Grüße
Heiko

[Virsacer]

Ah, ok danke, das schau ich mir mal genauer an

Ja, dass sqlite nicht mit mysql mithalten kann ist klar...
Ich dachte wegen einer Tabelle auf der kleinen Box ist mysql dann etwas wie mit den Kanonen und Spatzen

[DS_Starter]

Ich dachte wegen einer Tabelle auf der kleinen Box ist mysql dann etwas wie mit den Kanonen und Spatzen

Da liegst du mit Sicherheit nicht falsch. Aber wenn man die Möglichkeit hat, ist MySQL eben einfach besser im Handling. Zumindest meiner Meinung nach. Und den Luxus gönn ich mir

LG,
Heiko

[Virsacer]

Also mit dem "reopen 300" vorweg hat er jetzt wunderbar löschen können

Aber kann es sein, dass ein erneutes "reopen" den Timer nicht stoppt?
Oder muss ich dazu "reopen 0" oder so ähnlich machen?

[DS_Starter]

Aber kann es sein, dass ein erneutes "reopen" den Timer nicht stoppt?
Oder muss ich dazu "reopen 0" oder so ähnlich machen?

Nein, reopen reicht.
Wieso meinst du wird der Timer nicht gestoppt ?

[Virsacer]

Naja, ich hab "reopen 300", deleteOldDays, reduceLogNbl, vacuum und "reopen" gemacht und das steht jetzt im Log:

Code Auswählen Erweitern


2018.10.21 23:55:00 2: DbLog DBLOG: Connection closed until 00:00:00 (300 seconds).
...
2018.10.21 23:58:00 3: DbLog DBLOG: Reopen requested.
2018.10.21 23:58:00 3: DbLog DBLOG - Creating Push-Handle to database SQLite:dbname=./conf/fhem.db with user
2018.10.21 23:58:00 3: DbLog DBLOG - Push-Handle to db SQLite:dbname=./conf/fhem.db created
2018.10.22 00:00:00 3: DbLog DBLOG - Creating Push-Handle to database SQLite:dbname=./conf/fhem.db with user
2018.10.22 00:00:00 3: DbLog DBLOG - Push-Handle to db SQLite:dbname=./conf/fhem.db created


[DS_Starter]

Danke für die Info, ich schaue es mir an bzw. überprüfe es.

Grüße,
Heiko

[DS_Starter]

Hallo Virsacer,

du hattest recht bezüglich des Timer löschens.
Habe den Fehler korrigiert und die Version 3.12.6 eingecheckt.

Danke und LG,
Heiko

[Virsacer]

Ja, hab grade gesehen, dass eine neue Version im SVN ist...

Dann sollte jetzt allles funktionieren
Danke