reduceLog - Best Practice?

OiledAmoeba · 27 Oktober 2018, 12:54:40

Moin,

derzeit habe ich zwei at's, die nachts die Datenbank aufräumen sollen. Mittlerweile bin ich bei 2,7 GB...
Um 02:02:02 startet reduceLogNbl 7 average
Um 05:05:05 startet reduceLogNbl 30 average=day

Ausgaben von heute Nacht (per Telegram und notify auf reduceLogState):

Code Auswählen

reduceLogState: reduceLogNbl 7 average startet
reduceLogState: reduceLogNbl finished. Rows processed: 10790279, deleted: 8387903, updated: 357786, time: 11772.00sec

Code Auswählen

reduceLogState: reduceLogNbl 30 average=day started
reduceLogState: reduceLogNbl finished. Rows processed: 2324274, deleted: 746155, updated: 41528, time: 2811.00sec

Ist es schlau, erst average und dann average=day zu machen? Oder sollte ich die Reihenfolge umdrehen? (mich nervt vor allem die Runtime.)
Die at laufen täglich, ist meine Annahme dann richtig, das pro Tag 10 Mio Einträge auflaufen, von denen er 8 Mio löscht und 3k zurücklässt? Immerhin müssten die Einträge >7 Tage ja schon gelöscht sein... (Dann wäre die Frage, warum da 10 Mio Einträge am Tag zusammenkommen, aber das hat ja hiermit nix zu tun)

Dann habe ich gesehen, dass die Funktion von DbLog nach DbRep umgestellt wird. Muss ich dann zwei DbRep-Devices anlegen, wenn ich wie oben einmal 7 Tage stündlich und einmal 30 Tage täglich haben will? Oder müssen die at dann die Attribute jedesmal umschreiben?

DS_Starter · 27 Oktober 2018, 14:51:26

Hallo Florian,

deine Reihenfolge halte ich soweit für richtig, wobei die Reihenfolge auf die Laufzeit nicht den massgeblichen Einfluss haben dürfte.

Die Laufzeit dürfte neben den doch erheblichen Datenmengen dadurch zustandekommen, dass du jedesmal die gesamte Datenbank (älter als 7 bzw. 30 Tage) durchackern läst.
In der aktuellen Version von DbLog ist es deshalb auch möglich, den Aufruf z.B. so zu gestalten:

Code Auswählen


reduceLogNbl 7:9 average

Das würde bedeuten, es werden die Datensätze älter als 7 und neuer als 9 Tage berücksichtigt. Wenn du den reduceLog täglich durchführst erwischt du damit jeden Tag mit einer kleinen Überlappung. Für den anderen Aufruf wäre es dann z.B.

Code Auswählen


reduceLogNbl 30:32 average=day

Du hast zwar von 10Mio Einträgen pro Tag gesprochen, es sind m.M. aber "nur" 10Mio./7 -> rund 1,4Mio. Einträge pro Tag, was ich aber trotzdem heftig finde. Du kannst dir im DbLog einen groben Überblick verschaffen wenn du "set ... listCache" aufrufst. Die Ausgabe enthält pro Zeile einen Index, der in Prinzip die Anzahl der gespeicherten Events seit FHEM-Start widerspiegelt:

Zitat
7098 => 2018-10-27 14:31:05|sysmon|SYSMON|ram: Total: 996.07 MB, Used: 361.45 MB, 36.29 %, Free: 116.79 MB|ram|Total: 996.07 MB, Used: 361.45 MB, 36.29 %, Free: 116.79 MB|
7099 => 2018-10-27 14:31:05|sysmon|SYSMON|stat_cpu1_percent: 1.86 0.00 0.48 97.63 0.02 0.00 0.02|stat_cpu1_percent|1.86 0.00 0.48 97.63 0.02 0.00 0.02|

Wenn du also nach einem Tag zur selben Zeit wieder nachschaust, hast du quasi die Anzahl pro Tag, vorausgesetzt FHEM ist durchgelaufen.

Zitat
Dann habe ich gesehen, dass die Funktion von DbLog nach DbRep umgestellt wird. Muss ich dann zwei DbRep-Devices anlegen, wenn ich wie oben einmal 7 Tage stündlich und einmal 30 Tage täglich haben will? Oder müssen die at dann die Attribute jedesmal umschreiben?

Umgestellt ist erstmal nicht ganz richtig. Die Funktion wird es weiterhin im jetzigen DbLog geben. Aber ich habe vor, ein weiterentwickeltes (M)DbLog zu erstellen, welches dann nur noch MariaDB/MySQL unterstützen wird, aber dafür die entsprechenden Datenbankmöglichkeiten besser ausnutzen kann. In diesem neuen (M)DbLog wird es dann solche Funktionen, die mit der Logging-Funktionalität eigentlich nichts zu tun haben, nicht mehr geben.

Deswegen habe diese Funktion schon ins DbRep überführt. Außerdem kann ich dort die Möglichkeiten weiterentwickeln und verbessern.
Für die Ausführung im DbRep erstellst du dir am Besten zwei Devices (kopieren). Ein Umschreiben der Attribute ist zwar möglich, aber eigentlich nicht der Ansatz.

In einem Device setzt du dir:

Code Auswählen


timeOlderThan = d:7
timeDiffToNow = d:9

(Aufruf "set <DbRep> reduceLog average" )

und in dem anderen Device:

Code Auswählen


timeOlderThan = d:30
timeDiffToNow = d:32

(Aufruf "set <DbRep> reduceLog average=day" )

Damit würde bei jedem Lauf automatisch der richtige Zeitabschnitt ermittelt und bearbeitet. Die Attribute gestatten auch andere Zeitangaben -> Commandref.

Schau mal wie nach der Umsetzung deine Laufzeiten aussehen.

Grüße,
Heiko

OiledAmoeba · 28 Oktober 2018, 18:35:01

Hallo Heiko,

danke für die Erklärung und Tipps. Ich habe vorgestern von MySQL auf MariaDB umgestellt (gab schon mal nen ordentlichen Geschwindigkeitsschub).
Jetzt mal sehen, wie sich das "neue" reduceLog so schlägt.
Werde ein paar Nächte testen und mich dann melden.

Noch eine Idee: Die Datenbankanbindung über einen Unix-Socket, spart bei der Menge an Datensätzen sicherlich einiges an Zeit durch den dann fehlenden TCP-Overhead. Sind nur dummerweise zwei Jails, müsste dann über den Host nen Symlink zwischen den Jails setzen. Was wiederum aber auch wieder den Sicherheitsgedanken zunichte macht, warum ich es in zwei Jails gelegt habe...

OiledAmoeba · 04 Dezember 2018, 13:56:46

So, ich hab versprochen, mich zu melden. Da bin ich

Folgende Devices und at's habe ich definiert:

Code Auswählen

defmod Reduce_Daily DbRep logdb
attr Reduce_Daily showproctime 1
attr Reduce_Daily timeDiffToNow d:32
attr Reduce_Daily timeOlderThan d:30

defmod Reduce_Hourly DbRep logdb
attr Reduce_Hourly showproctime 1
attr Reduce_Hourly timeDiffToNow d:9
attr Reduce_Hourly timeOlderThan d:7

defmod at_ReduceLog_long at *04:04:04 {fhem("set Reduce_Daily reduceLog average=day")}

defmod at_ReduceLog_short at *01:01:01 {fhem("set Reduce_Hourly reduceLog average")}

Die Ergebnisse sind so la la...
Der auf die Woche guckt sagt das:

ZitatreduceLogState: reduceLog finished. Rows processed: 239214, deleted: 235319, updated: 3156

Und der auf den Monat guckt das:

ZitatreduceLogState: reduceLog finished. Rows processed: 3144, deleted: 0, updated: 0

So sah es jede Nacht aus, der 7-tägige hat fleißig gelöscht, der monatliche hat immer "deleted: 0" ausgeworfen. Dafür waren die runtimes traumhaft: nur noch wenige Sekunden.

Ich habe jetzt gerade set logdb reduceLogNbl 7 average und set logdb reduceLogNbl 30 average=day ausgeführt, dabei kam raus:

ZitatreduceLogState: reduceLogNbl 7 average started
reduceLogState: reduceLogNbl finished. Rows processed: 1746814, deleted: 220854, updated: 3144, time: 1815.00sec

reduceLogState: reduceLogNbl 30 average=day started
reduceLogState: reduceLogNbl finished. Rows processed: 1453571, deleted: 15580, updated: 771, time: 729.00sec

Irritierend sind die Ergebnisse. Obwohl reduceLog 30 in den letzten Tagen angeblich nix gemacht hat, wurden über die "alte" Funktion nur 771 Werte geändert?
Zu funktionieren scheint es, denn die geplotteten Kurven werden vor 7 Tagen ruhiger und vor 30 Tagen deutlich ruhiger; allerdings hab ich gerade erst nach der manuellen ausführung des alten Befehls draufgeguckt...
Schön wäre es, wenn der "neue" ReduceLog auch die runtime loggen würde. Dazu hab ich nix gefunden...

DS_Starter · 04 Dezember 2018, 14:45:48

Hallo Florian,

erstmal danke für die Aufarbeitung.

Aber ich glaube es liegt noch ein Mißverständnis in der Abgrenzung der Zeiträume vor:

Zitat
attr Reduce_Daily timeDiffToNow d:32
attr Reduce_Daily timeOlderThan d:30

... bedeutet, dass in der DB die Einträge älter als 30 (der Tag inkl.) und neuer als 32 (der Tag inkl.) Tage berücksichtigt werden. In deinem Setup wird dann average=day-> ein Tagesdurchschnitt dieser 3 Tage gebildet.

Zitat
attr Reduce_Hourly timeDiffToNow d:9
attr Reduce_Hourly timeOlderThan d:7

... bedeutet, dass in der DB die Einträge älter als 7 (der Tag inkl.) und neuer als 9 (der Tag inkl.) Tage berücksichtigt werden. In deinem Setup wird dann average -> ein Stundendurchschnitt je Stunde dieser 3 Tage gebildet.

Dagegen bedeuten die Aufrufe :

Zitat
reduceLogNbl 7 average
reduceLogNbl 30 average=day

das jeweils die Daten älter als 7 bzw. älter als 30 Tage bearbeitet werden ohne Begrenzung des unteren Timestamp-Limits. Der Lauf beackert dann (fast) die gesamte DB was unsinnig wäre.

Das heißt der Vergleich beider Laufvarianten ist so nicht korrekt und führt sicherlich zu der Irritation bei der Interpretation der Ergebnisse.

ZitatSchön wäre es, wenn der "neue" ReduceLog auch die runtime loggen würde. Dazu hab ich nix gefunden...

Die benötigte Zeit wird im Reading "background_processing_time" abgebildet.

Hier auch mal ein ebengemachter Lauf von mir zum Vergleich:

Der Aufruf "reducelog average" mit

Code Auswählen


timeDiffToNow d:32
timeOlderThan d:30

Das Log mit verbose 3:

Code Auswählen


2018.12.04 14:41:35.900 3: DbRep Rep.Erzeugung.monatlich - ################################################################
2018.12.04 14:41:35.900 3: DbRep Rep.Erzeugung.monatlich - ###                    new reduceLog run                     ###
2018.12.04 14:41:35.901 3: DbRep Rep.Erzeugung.monatlich - ################################################################
2018.12.04 14:41:36.012 3: DbRep Rep.Erzeugung.monatlich - reduce data older than: 2018-11-04 13:41:34, newer than: 2018-11-02 14:41:34
2018.12.04 14:41:36.013 3: DbRep Rep.Erzeugung.monatlich - reduceLog requested with options: AVERAGE=HOUR INCLUDE -> Devs: % Readings: %
2018.12.04 14:41:36.265 3: DbRep Rep.Erzeugung.monatlich - reduceLog deleting 27990 records of day: 2018-11-02
2018.12.04 14:41:36.314 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 1000
2018.12.04 14:41:36.338 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 2000
2018.12.04 14:41:36.350 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 3000
2018.12.04 14:41:36.363 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 4000
2018.12.04 14:41:36.375 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 5000
2018.12.04 14:41:36.390 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 6000
2018.12.04 14:41:36.403 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 7000
2018.12.04 14:41:36.416 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 8000
2018.12.04 14:41:36.430 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 9000
2018.12.04 14:41:36.443 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 10000
2018.12.04 14:41:36.462 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 11000
2018.12.04 14:41:36.482 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 12000
2018.12.04 14:41:36.497 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 13000
2018.12.04 14:41:36.511 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 14000
2018.12.04 14:41:36.523 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 15000
2018.12.04 14:41:36.537 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 16000
2018.12.04 14:41:36.550 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 17000
2018.12.04 14:41:36.564 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 18000
2018.12.04 14:41:36.577 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 19000
2018.12.04 14:41:36.590 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 20000
2018.12.04 14:41:36.603 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 21000
2018.12.04 14:41:36.616 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 22000
2018.12.04 14:41:36.632 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 23000
2018.12.04 14:41:36.644 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 24000
2018.12.04 14:41:36.659 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 25000
2018.12.04 14:41:36.672 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 26000
2018.12.04 14:41:36.685 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-02 is: 27000
2018.12.04 14:41:36.748 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating 247 records of day: 2018-11-02
2018.12.04 14:41:36.763 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating progress of day: 2018-11-02 is: 100
2018.12.04 14:41:36.770 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating progress of day: 2018-11-02 is: 200
2018.12.04 14:41:37.415 3: DbRep Rep.Erzeugung.monatlich - reduceLog deleting 73546 records of day: 2018-11-03
2018.12.04 14:41:37.540 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-03 is: 10000
2018.12.04 14:41:37.666 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-03 is: 20000
2018.12.04 14:41:37.809 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-03 is: 30000
2018.12.04 14:41:37.938 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-03 is: 40000
2018.12.04 14:41:38.070 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-03 is: 50000
2018.12.04 14:41:38.198 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-03 is: 60000
2018.12.04 14:41:38.334 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-03 is: 70000
2018.12.04 14:41:38.470 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating 618 records of day: 2018-11-03
2018.12.04 14:41:38.491 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating progress of day: 2018-11-03 is: 100
2018.12.04 14:41:38.497 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating progress of day: 2018-11-03 is: 200
2018.12.04 14:41:38.504 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating progress of day: 2018-11-03 is: 300
2018.12.04 14:41:38.511 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating progress of day: 2018-11-03 is: 400
2018.12.04 14:41:38.517 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating progress of day: 2018-11-03 is: 500
2018.12.04 14:41:38.524 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating progress of day: 2018-11-03 is: 600
2018.12.04 14:41:38.889 3: DbRep Rep.Erzeugung.monatlich - reduceLog deleting 39734 records of day: 2018-11-04
2018.12.04 14:41:39.023 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-04 is: 10000
2018.12.04 14:41:39.162 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-04 is: 20000
2018.12.04 14:41:39.303 3: DbRep Rep.Erzeugung.monatlich - reduceLog deletion progress of day: 2018-11-04 is: 30000
2018.12.04 14:41:39.699 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating 334 records of day: 2018-11-04
2018.12.04 14:41:39.721 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating progress of day: 2018-11-04 is: 100
2018.12.04 14:41:39.732 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating progress of day: 2018-11-04 is: 200
2018.12.04 14:41:39.742 3: DbRep Rep.Erzeugung.monatlich - reduceLog (hourly-average) updating progress of day: 2018-11-04 is: 300
2018.12.04 14:41:39.757 3: DbRep Rep.Erzeugung.monatlich - reduceLog finished. Rows processed: 145502, deleted: 141270, updated: 1199

Readings:

background_processing_time 3.00
reduceLogState reduceLog finished. Rows processed: 145502, deleted: 141270, updated: 11992

Grüße
Heiko

OiledAmoeba · 04 Dezember 2018, 15:29:43

Jetzt hab ich das Reading gefunden und auch gleich in die Telegram-Message eingebaut. Echt, Tomaten auf den Augen. Danke!

Die beiden reduceLogNbl habe ich gerade nur als Kontrolle ausgeführt. Wenn der d:7 d:9 korrekt arbeitet (und das auch schon > 14 Tage), müsste reduceLogNbl 7 average doch eigentlich deleted:0 und updated: 0 ergeben. Vor der Nutzung der neuen Funktion hab ich direkt die alte Funktion ausgebaut, also da war schon nix mehr drin, das älter 9 Tage war. Vor allem wollte ich den d:30 d:32 damit prüfen, weil der immer 0 ausgegeben hat.

Was mich gerade stutzig macht ist:

Zitat
reduceLog average (aus dem Device mit d:7 d:9)
reduceLogState: reduceLog finished. Rows processed: 2118, deleted: 0, updated: 0, time: 0.0595sec

reduceLogNbl 7:9 average (aus dem "Mutterdevice" logdb)
reduceLogState: reduceLogNbl finished. Rows processed: 16746, deleted: 0, updated: 0, time: 1.00sec

Erstmal: deleted und updated wie erwartet 0, denn es lief ja vorhin schon mal. Aber da ist eine nicht unerhebliche Diff zwischen den durchgeackerten Datenpunkten. Mal gucken, ob ich mit einer höheren verbosity rausfinde, warum das so ist. Dann könnte ich auch rausfinden, warum logdb fast zweieinhalb mal so lang wie die neue Funktion braucht (wobei, bei der kurzen Zeit kann das auch auf Nbl zurückzuführen sein, dafür forkt er doch, oder? Den fork muss er ja erst mal bilden...)

Edit;
Schade, logdb is auf verbose 5 nicht sonderlich mitteilungsbedürftig. Oder ich habe es überlesen, weil in dem Moment pasenderweise der Cache weggeschrieben wurde...

DS_Starter · 04 Dezember 2018, 15:50:27

Hast du in dem DbRep-Device ein Attribut device oder reading gesetzt ? Das würde sich direkt auf die selected Datensätze auswirken.
Siehst du auch im Log mit verbose 3.

OiledAmoeba · 04 Dezember 2018, 16:06:21

Zitat von: DS_Starter am 04 Dezember 2018, 15:50:27
Hast du in dem DbRep-Device ein Attribut device oder reading gesetzt ? Das würde sich direkt auf die selected Datensätze auswirken.
Siehst du auch im Log mit verbose 3.

Nein. Die einzigen Attibute sind

Code Auswählen

attr Reduce_Daily showproctime 1
attr Reduce_Daily timeDiffToNow d:32
attr Reduce_Daily timeOlderThan d:30
attr Reduce_Daily verbose 5

bzw. analog d:7 d:9

Aber gerade noch ein "Pfui" im Log gesehen:

Zitat2018.12.04 15:34:09.016 5: DbLog logdb -> Primary Key used in fhem.history: none
2018.12.04 15:34:09.016 5: DbLog logdb -> Primary Key used in fhem.current: DEVICE,READING

Hab gerade nur Probleme, den PK reinzufummeln... Vermutlich wäre das einfachste, FHEM runterzufahren, um neue Dubletten zu vermeiden...

DS_Starter · 04 Dezember 2018, 16:14:08

Zitat
Hab gerade nur Probleme, den PK reinzufummeln... Vermutlich wäre das einfachste, FHEM runterzufahren, um neue Dubletten zu vermeiden...

Nimm die neue Funktion "delDoublets" vor dem anlegen des Keys.

Das könnte lange laufen. Deswegen würde ich DbLog vorher für ein paar Stunden für das Logging schließen:

Code Auswählen


attr DbRep executeBeforeProc set LogDB reopen 86000

Wenn der Lauf durch ist kannst du den PK einbauen.
Danach die DB wieder öffnen:

Code Auswählen


set LogDB reopen

OiledAmoeba · 04 Dezember 2018, 17:25:51

Wenn es so einfach wäre...

Code Auswählen

chef@gehirn [fhem]> SQL ALTER TABLE fhem.history ADD PRIMARY KEY(TIMESTAMP, DEVICE, READING);
ERROR 1062 (23000): Duplicate entry '2018-12-04 15:55:25-bz_Heizung-hmstate' for key 'PRIMARY'
chef@gehirn [fhem]>

chef@gehirn [fhem]> SELECT * FROM fhem.history WHERE TIMESTAMP='2018-12-04 15:55:25' AND DEVICE='bz_Heizung' AND READING='hmstate';
TIMESTAMP 		DEVICE 		TYPE 		EVENT 		READING 	VALUE 	UNIT
2018-12-04 15:55:25 	bz_Heizung 	HMCCUDEV 	hmstate: 17.0 	hmstate 	17.0
chef@gehirn [fhem]>

Genau ein Vorkommen, aber soll eine Dublette sein? WTF?

Vielleicht schon ein PK vorhanden und die Fehlermeldung ist falsch?

Code Auswählen

chef@gehirn [fhem]> SELECT * FROM INFORMATION_SCHEMA.TABLE_CONSTRAINTS WHERE TABLE_SCHEMA = 'fhem';
CONSTRAINT_CATALOG 	CONSTRAINT_SCHEMA 	CONSTRAINT_NAME 	TABLE_SCHEMA 	TABLE_NAME 	CONSTRAINT_TYPE
def 			fhem 			PRIMARY 		fhem 		current 	PRIMARY KEY
def 			fhem 			PRIMARY 		fhem 		frontend 	PRIMARY KEY
chef@gehirn [fhem]>

Nö, auch nicht.
Muss jetzt erst mal weg, probiere es heute Abend noch mal.

DS_Starter · 04 Dezember 2018, 18:38:55

ZitatGenau ein Vorkommen, aber soll eine Dublette sein? WTF?

Verstehe ich auch nicht. Wenn der Datensatz nicht total wichtig ist würde ich den löschen ...
und schauen ob es dann möglich ist den PK anzulegen.

OiledAmoeba · 11 Dezember 2018, 20:59:00

Ich werd noch verrückt...
Lösche ich den Datensatz, tauch ein neuer auf, der doppelt sein soll.
Habe jetzt nochmal den delDoublets drüberlaufen lassen.

Code Auswählen

select timestamp,device,reading,count(*) no_of_records from history group by timestamp,device,reading having count(*) > 1;

gibt unter anderem:

Code Auswählen

| 2018-12-11 16:48:47 | ku_Heizung      | state                   |             3 |
| 2018-12-11 16:48:49 | d_rpcHmIP_RF    | state                   |             2 |
| 2018-12-11 17:06:27 | d_rpcBidCos_RF  | state                   |             2 |
| 2018-12-11 17:06:27 | d_rpcCUxD       | rpcstate                |             2 |
| 2018-12-11 17:06:27 | d_rpcCUxD       | state                   |             2 |
| 2018-12-11 17:06:27 | d_rpcHmIP_RF    | state                   |             2 |
| 2018-12-11 17:06:29 | d_rpcCUxD       | state                   |             2 |
| 2018-12-11 17:06:30 | d_rpcHmIP_RF    | rpcstate                |             2 |
| 2018-12-11 17:06:31 | d_rpcBidCos_RF  | rpcstate                |             2 |
| 2018-12-11 17:06:31 | d_rpcBidCos_RF  | state                   |             2 |
| 2018-12-11 17:06:33 | ku_Heizung      | state                   |             3 |
| 2018-12-11 17:06:34 | d_rpcHmIP_RF    | state                   |             2 |
+---------------------+-----------------+-------------------------+---------------+
1147 rows in set (3 min 57.66 sec)

1147 Einträge sollen noch doppelt sein. Und jetzt das irre:

Code Auswählen

ALTER TABLE history ADD PRIMARY KEY(TIMESTAMP, DEVICE, READING);
ERROR 1062 (23000): Duplicate entry '2018-12-11 17:20:46-logdb-CacheUsage' for key 'PRIMARY'

Aber die Liste endet um 17:06:34...
Solange ich nicht weiß, was das Problem ist, kriege ich da keinen PK rein...
Nächster Versuch, aber wohl nicht mehr heute: Dump ohne Struktur, Testdatenbank anlegen, Struktur per Hand anlegen, PK setzen, Dump einspielen.

EDIT:
Guck ich nur auf den Timestamp:

Code Auswählen

select * FROM history WHERE TIMESTAMP="2018-12-11 17:20:38";
+---------------------+---------------+----------+---------------------+---------------+-------+------+
| TIMESTAMP           | DEVICE        | TYPE     | EVENT               | READING       | VALUE | UNIT |
+---------------------+---------------+----------+---------------------+---------------+-------+------+
| 2018-12-11 17:20:38 | HM_fht.Kueche | HMCCUDEV | 1.TEMPERATURE: 19.9 | 1.TEMPERATURE | 19.9  |      |
| 2018-12-11 17:20:38 | HM_fht.Kueche | HMCCUDEV | temperature: 19.9   | temperature   | 19.9  | Â°C   |
+---------------------+---------------+----------+---------------------+---------------+-------+------+
2 rows in set (3.09 sec)

Immer noch keine Dublette...

DS_Starter · 11 Dezember 2018, 21:20:38

Sieht mir aus wie Hexerei

Im ernst, kann mir nicht vorstellen was hier das Problem sein soll. Irgendwie passen die verscheidenen Ergebnisse nicht zusammen.

OiledAmoeba · 11 Dezember 2018, 22:52:33

Zitat von: DS_Starter am 11 Dezember 2018, 21:20:38
Sieht mir aus wie Hexerei
Im ernst, kann mir nicht vorstellen was hier das Problem sein soll. Irgendwie passen die verscheidenen Ergebnisse nicht zusammen.

Das kann ich ganz einfach erklären. Ich hatte einen anderen problematischen Eintrag im letzten Beispiel nehmen müssen, da ich 2018-12-11 17:20:46-logdb-CacheUsage bereits gelöscht hatte

Code Auswählen

chef@gehirn [(none)]> CREATE DATABASE new_fhem;
Query OK, 1 row affected (1.61 sec)

chef@gehirn [(none)]> USE new_fhem;
Database changed
chef@gehirn [new_fhem]> CREATE TABLE `history` (
    ->   `TIMESTAMP` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
    ->   `DEVICE` varchar(64) COLLATE utf8_bin NOT NULL,
    ->   `TYPE` varchar(64) COLLATE utf8_bin DEFAULT NULL,
    ->   `EVENT` varchar(191) COLLATE utf8_bin DEFAULT NULL,
    ->   `READING` varchar(64) COLLATE utf8_bin NOT NULL,
    ->   `VALUE` varchar(128) COLLATE utf8_bin DEFAULT NULL,
    ->   `UNIT` varchar(32) COLLATE utf8_bin DEFAULT NULL
    -> ) ENGINE=Aria DEFAULT CHARSET=utf8 COLLATE=utf8_bin PAGE_CHECKSUM=1 TRANSACTIONAL=1;
Query OK, 0 rows affected (0.41 sec)

chef@gehirn [new_fhem]> ALTER TABLE history ADD PRIMARY KEY(TIMESTAMP, DEVICE, READING);
Query OK, 0 rows affected (0.33 sec)
Records: 0  Duplicates: 0  Warnings: 0

So, geht doch.
Nun noch mal fhem-Datenbank schließen, dumpen und in new_fhem einspielen.

OiledAmoeba · 12 Dezember 2018, 13:21:23

So, jetzt hat es geklappt. mysql-cli hat keine doppelten Zeilen angezeigt, im Dump waren aber tatsächlich welche, teilweise mehr als 10 Dubletten... aber dank mysql --force kein Problem

Egal, Hauptsache, der PK ist nun endlich drauf.

Habe jetzt noch mal DbRep und DbLog auf die Datenbank losgelassen. Die kommen zu unterschiedlichen Ergebnissen:

DbRep, nur auf "Älter 30 Tage" eingegrenzt:

Code Auswählen

defmod Reduce_Daily DbRep logdb
attr Reduce_Daily DbLogExclude .*
attr Reduce_Daily fastStart 1
attr Reduce_Daily group Datenbank
attr Reduce_Daily room System
attr Reduce_Daily showproctime 1
attr Reduce_Daily timeOlderThan d:30
attr Reduce_Daily verbose 5

set Reduce_Daily reduceLog average=day

2018.12.12 11:34:36.132 3: DbRep Reduce_Daily - ################################################################
2018.12.12 11:34:36.132 3: DbRep Reduce_Daily - ###                    new reduceLog run                     ###
2018.12.12 11:34:36.146 3: DbRep Reduce_Daily - ################################################################
2018.12.12 11:34:36.282 4: DbRep Reduce_Daily - -------- New selection --------- 
2018.12.12 11:34:36.286 4: DbRep Reduce_Daily - Command: reduceLog 
2018.12.12 11:34:36.438 4: DbRep Reduce_Daily - timeOlderThan - year: , day: 30, hour: , min: , sec:  
2018.12.12 11:34:36.468 4: DbRep Reduce_Daily - Year 2016 is leap year
2018.12.12 11:34:36.469 5: DbRep Reduce_Daily - Timestamp begin epocheseconds: 1358593200
2018.12.12 11:34:36.470 4: DbRep Reduce_Daily - Timestamp begin human readable: 2013-01-19 12:00:00
2018.12.12 11:34:36.470 4: DbRep Reduce_Daily - Time difference to current time for calculating Timestamp end: 2678401 sec
2018.12.12 11:34:36.471 5: DbRep Reduce_Daily - Timestamp end epocheseconds: 1541932475.47081
2018.12.12 11:34:36.471 4: DbRep Reduce_Daily - Timestamp end human readable: 2018-11-11 11:34:35
2018.12.12 11:34:36.834 5: DbRep Reduce_Daily -> Start DbLog_reduceLog
2018.12.12 11:34:36.888 5: DbRep Reduce_Daily - Devices for operation - included: % , excluded: 
2018.12.12 11:34:36.889 5: DbRep Reduce_Daily - Readings for operation - included: %, excluded:  
2018.12.12 11:34:36.890 5: DbRep Reduce_Daily - IsTimeSet: 1, IsAggrSet: 0
2018.12.12 11:34:36.904 5: DbRep Reduce_Daily - Devices for operation - included: % , excluded: 
2018.12.12 11:34:36.904 5: DbRep Reduce_Daily - Readings for operation - included: %, excluded:  
2018.12.12 11:34:36.925 4: DbRep Reduce_Daily - SQL execute: SELECT TIMESTAMP,DEVICE,'',READING,VALUE FROM history where TIMESTAMP >= '2013-01-19 12:00:00' AND TIMESTAMP <= '2018-11-11 11:34:35' ORDER BY TIMESTAMP ASC;
2018.12.12 11:34:36.926 3: DbRep Reduce_Daily - reduce data older than: 2018-11-11 11:34:35, newer than: 2013-01-19 12:00:00
2018.12.12 11:34:36.926 3: DbRep Reduce_Daily - reduceLog requested with options: AVERAGE=DAY INCLUDE -> Devs: % Readings: %
2018.12.12 11:43:29.642 3: DbRep Reduce_Daily - reduceLog finished. Rows processed: 1450305, deleted: 0, updated: 0
2018.12.12 11:43:29.937 5: DbRep Reduce_Daily -> DbRep_reduceLogNbl finished

Und DbLog, ebenfalls älter 30 Tage:

Code Auswählen

defmod logdb DbLog ./db.conf .*:.*
attr logdb DbLogInclude CacheUsage
attr logdb DbLogSelectionMode Exclude/Include
attr logdb DbLogType SampleFill/History
attr logdb asyncMode 1
attr logdb cacheEvents 2
attr logdb cacheLimit 500
attr logdb colEvent 191
attr logdb excludeDevs logdb^(?!.*(CacheUsage)|(state)).*$,CUL,global
attr logdb group Datenbank
attr logdb room System
attr logdb showNotifyTime 0
attr logdb showproctime 1
attr logdb shutdownWait 5
attr logdb stateFormat State: state<br />Cache: CacheUsage
attr logdb suppressAddLogV3 1
attr logdb suppressUndef 1
attr logdb syncEvents 1
attr logdb syncInterval 30
attr logdb timeout 86400
attr logdb useCharfilter 1
attr logdb verbose 3

set logdb reduceLogNbl 30 average=day

2018.12.12 11:51:01.294 3: DbLog logdb: reduceLogNbl requested with DAYS=30, AVERAGE=DAY
2018.12.12 11:52:02.251 1: PERL WARNING: Use of uninitialized value $text in concatenation (.) or string at configDB.pm line 1028.
2018.12.12 12:06:49.938 3: DbLog logdb: reduceLogNbl (daily-average) updating 129, deleting 2633 records of day: 2018-11-03
2018.12.12 12:08:19.832 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-03 is: 1000
2018.12.12 12:08:47.049 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-03 is: 2000
2018.12.12 12:08:48.721 1: PERL WARNING: Use of uninitialized value $ku in multiplication (*) at ./FHEM/93_DbLog.pm line 4476.
2018.12.12 12:08:48.749 3: DbLog logdb: reduceLogNbl (daily-average) updating progress of day: 2018-11-03 is: 0
2018.12.12 12:09:29.229 3: DbLog logdb: reduceLogNbl (daily-average) updating 129, deleting 2620 records of day: 2018-11-04
2018.12.12 12:09:59.895 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-04 is: 1000
2018.12.12 12:12:24.533 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-04 is: 2000
2018.12.12 12:12:27.529 3: DbLog logdb: reduceLogNbl (daily-average) updating progress of day: 2018-11-04 is: 0
2018.12.12 12:12:46.188 3: DbLog logdb: reduceLogNbl (daily-average) updating 129, deleting 900 records of day: 2018-11-05
2018.12.12 12:12:51.465 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-05 is: 100
2018.12.12 12:12:54.506 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-05 is: 200
2018.12.12 12:12:57.824 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-05 is: 300
2018.12.12 12:13:01.597 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-05 is: 400
2018.12.12 12:13:04.579 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-05 is: 500
2018.12.12 12:13:07.139 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-05 is: 600
2018.12.12 12:13:09.983 3: DbLog logdb: reduceLogNbl (daily-average) updating progress of day: 2018-11-05 is: 0
2018.12.12 12:13:10.312 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-05 is: 700
2018.12.12 12:13:26.989 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-05 is: 800
2018.12.12 12:13:46.349 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-05 is: 900
2018.12.12 12:13:46.384 3: DbLog logdb: reduceLogNbl (daily-average) updating 9, deleting 9 records of day: 2018-11-08
2018.12.12 12:13:46.914 3: DbLog logdb: reduceLogNbl (daily-average) updating 130, deleting 2561 records of day: 2018-11-09
2018.12.12 12:14:15.395 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-09 is: 1000
2018.12.12 12:14:38.154 3: DbLog logdb: reduceLogNbl (daily-average) updating progress of day: 2018-11-09 is: 0
2018.12.12 12:14:39.117 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-09 is: 2000
2018.12.12 12:14:49.595 3: DbLog logdb: reduceLogNbl (daily-average) updating 136, deleting 2530 records of day: 2018-11-10
2018.12.12 12:14:55.838 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-10 is: 1000
2018.12.12 12:14:57.469 3: DbLog logdb: reduceLogNbl (daily-average) updating progress of day: 2018-11-10 is: 0
2018.12.12 12:14:57.708 3: DbLog logdb: reduceLogNbl (daily-average) deleting progress of day: 2018-11-10 is: 2000
2018.12.12 12:14:59.059 3: DbLog logdb: reduceLogNbl finished. Rows processed: 1451874, deleted: 11253, updated: 662, time: 1438.00sec

Unterschied:

ZitatDbRep: Rows processed: 1450305, deleted: 0, updated: 0
DbLog: Rows processed: 1451874, deleted: 11253, updated: 662

Dazu kommt noch, das DbRep und DbLog "30 Tage" anders interpretieren. DbRep sagt "jetzt minus 30 Tage" -> 2018-11-11 11:34:35 und scheinbar sagt DbLog "0:00 minus 30 Tage" -> 2018-11-10
Anders kann ich mir zumindest nicht erklären, warum DbLog den 11.11. mit der obigen Auswahl nicht bearbeitet, ist aber Nebensache.

Da DbRep vor DbLog lief, hätte es vom 03.11. - 10.11. (und sicher auch am 11.11.) zu bearbeitende Daten finden müssen.