Modul 93_DbRep - Reporting und Management von Datenbankinhalten (DbLog)

[frober]

Hallo Heiko,

seit Beginn habe ich die Grünlandtemperatur wie im Wiki beschrieben angelegt.
Nun ist mir zufällig (zigbee2mqtt geht auf offline), dank perfmon aufgefallen das es ca. 22s blockiert.

Start ist 00:20, die db benötigt ca. 90s, danach wird die myUtils gestartet. Diese ist blockierend.

Code Auswählen Erweitern

2024.10.13 00:21:53 1: Perfmon: possible freeze starting at 00:21:33, delay is 20.75
2024.10.13 00:22:13 1: 127.0.0.1:1883 disconnected, waiting to reappear (MQTT2_Client)
2024.10.13 00:22:13 1: 192.168.10.15:81 reappeared (LaCrosseGateway)
2024.10.13 00:22:15 1: Perfmon: possible freeze starting at 00:21:54, delay is 21.792
2024.10.13 00:22:16 1: 127.0.0.1:1883 reappeared (MQTT2_Client)
Ist es möglich userExitFn auch nonblocking auszuführen oder muss ich das in die myUtils integrieren. Bzw. (ich habe mit nonblocking noch keine Erfahrung) funktioniert das überhaupt, 2 nonblocking Prozesse db + myUtil die miteinander kommunizieren sollen?

Nachtrag:
Ich konnte beide Freezes durch manuellen Start reproduzieren.
Wieso sind es 2 und werden hier jeden Tag alles GTS neu gespeichert?

Die GTS das ganze Jahr durch laufen zu lassen macht eigentlich keinen Sinn. Ich werde das at entsprechend anpassen.
Meine Fragen hätte ich trotzdem gerne beantwortet.

LG
Bernd

[JWRu]

Ich habe ein Problem mit DbRep seit dem letzten FHEM-Update:
Bei mir läuft seit langer Zeit ohne Probleme jede Nacht um 2:00 Uhr ein DbRep, das meine DbLog-Datenbank ausdünnt und bis auf wenige Ausnahmen alle Einträge entfernt, die älter sind als 10 Tage.
Am 17.10. habe ich ein Update von FHEM gemacht. Bei der ersten Ausführung nach dem Update gab es folgende Fehlermeldung:

Code Auswählen Erweitern

2024.10.18 02:00:00 3: DbRep myDbRep - get initial structure information of database "fhem", remaining attempts: 3
2024.10.18 02:00:00 3: DbRep myDbRep - Connectiontest to database mysql:database=fhem;host=localhost;port=3306 with user fhemuser
2024.10.18 02:00:00 3: DbRep myDbRep - Index Report_Idx exists. Check ok
2024.10.18 02:00:00 3: DbRep myDbRep - Initial data information retrieved - total time used: 0.0145 seconds
2024.10.18 02:00:00 3: DbRep myDbRep - Connectiontest to db mysql:database=fhem;host=localhost;port=3306 successful
2024.10.18 02:05:47 2: myDbLog - Error table history - DBD::mysql::st execute_array failed: executing 600 generated 7 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.

2024.10.18 02:05:49 2: DbRep myDbRep - ERROR - DBD::mysql::st execute failed: The total number of locks exceeds the lock table size at ./FHEM/93_DbRep.pm line 11891.

Seither erhalte ich bei jeder Ausführung:

Code Auswählen Erweitern

2024.10.20 02:06:35 2: myDbLog - Error table history - DBD::mysql::st execute_array failed: executing 600 generated 6 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3215.

2024.10.20 02:06:59 2: DbRep myDbRep - ERROR - DBD::mysql::st execute failed: The total number of locks exceeds the lock table size at ./FHEM/93_DbRep.pm line 11891.

[JWRu]

Ich habe jetzt das Problem gelöst, indem ich die Datenbank stark ausgedünnt habe.
Dabei ist mir aber etwas anderes aufgefallen:

Jeden Tag um 2 Uhr lasse ich jetzt zuerst eine DbRep-Instanz laufen die alle Einträge älter als 4 Wochen bis auf wenige Ausnahmen löscht (delEntries).
Anschließend läuft eine zweite DbRep-Instanz, die die verbleibenden Einträge ausdünnt (reduceLog average).
Das hat heute Morgen prima geklappt, beide Aufrufe waren in weniger als einer Minute beendet - es gab keine Fehlermeldungen im Log.
Allerdings steigt zeitgleich mit der Ausführung die CPU Last deutlich an und bleibt anschließend dauerhaft hoch.
Die Last wird eindeutig von FHEM verursacht und nicht von der Datenbank (in meinem Fall MariaDB). Ein "sudo systemctl restart mariadb" ändert nichts an der Last.
Erst ein "shutdown restart" von FHEM (gegen 9:00 Uhr) bringt die Last wieder auf ein normales Niveau - siehe Screenshot im Anhang.


Du darfst diesen Dateianhang nicht ansehen.

[DS_Starter]

Diese Meldung

Code Auswählen Erweitern

....The total number of locks exceeds the lock table size...

wird durch das DBMS erstellt. Dafür gibt es eine Einstellung: https://stackoverflow.com/questions/6901108/the-total-number-of-locks-exceeds-the-lock-table-size

Die andere Meldung

myDbLog - Error table history - DBD::mysql::st execute_array failed: executing 600 generated 7 errors

bedeutet dass vonn 600 zu loggenden Events 7 nicht in der DB gespeichert werden können. Der Grund ist im Nachhinein nicht ermittelbar. Aber da DbLog solche Daten nicht einfach entsorgt, laufen sie mit und erzeugen immer wiedder diese Meldung damit man der Sache auch auf den Grund gehen kann wenn gewünscht.

Zur der CPU-Last kann ich nur Vermutungen anstellen. Ich könnte mir vorstellen, dass dein System evtl. durch einen Speicherengpass bedingt in den Swap-Status geht und ständig ein und auslagern muß.

LG

[JWRu]

Zur der CPU-Last kann ich nur Vermutungen anstellen. Ich könnte mir vorstellen, dass dein System evtl. durch einen Speicherengpass bedingt in den Swap-Status geht und ständig ein und auslagern muß.

Heute zeitgleich mit dem Start von DbRep wieder der gleiche Effekt. Ich habe seit gestern Abend mal die Swap Usage (aus SYSMON) mitgeloggt - da ist nichts zu sehen.
Hier ist der Ausschnitt aus dem Log:

Code Auswählen Erweitern

2024.10.23 02:00:00 3: DbRep myDbRep_delEntries - get initial structure information of database "fhem", remaining attempts: 3
2024.10.23 02:00:00 3: DbRep myDbRep_delEntries - Connectiontest to database mysql:database=fhem;host=localhost;port=3306 with user fhemuser
2024.10.23 02:00:00 3: DbRep myDbRep_delEntries - Index Report_Idx exists. Check ok
2024.10.23 02:00:00 3: DbRep myDbRep_delEntries - Initial data information retrieved - total time used: 0.0100 seconds
2024.10.23 02:00:00 3: DbRep myDbRep_delEntries - Connectiontest to db mysql:database=fhem;host=localhost;port=3306 successful
2024.10.23 02:00:00 3: DbRep myDbRep_delEntries - Entries of fhem.history deleted: EXCLUDE/Luftdruckmesser/Regenmesser/Klima_aussen/Klima_Wohnzimmer/MQTT2_ESP8266_Sensor_03/MQTT2_ESP8266_Sensor_04/MQTT2_ESP8266_Sensor_05/MQTT2_Ahoy_DTU_971008--EXCLUDE/pressure/rain_total/humidity/temperature/SoilTemp/VolumeWaterContent/Level/WindSpeedAverage/P_AC/YieldDay--0
2024.10.23 02:10:00 3: DbRep myDbRep_reduceLog - ################################################################
2024.10.23 02:10:00 3: DbRep myDbRep_reduceLog - ###                    new reduceLog run                     ###
2024.10.23 02:10:00 3: DbRep myDbRep_reduceLog - ################################################################
2024.10.23 02:10:00 3: DbRep myDbRep_reduceLog - get initial structure information of database "fhem", remaining attempts: 3
2024.10.23 02:10:00 3: DbRep myDbRep_reduceLog - Connectiontest to database mysql:database=fhem;host=localhost;port=3306 with user fhemuser
2024.10.23 02:10:00 3: DbRep myDbRep_reduceLog - Index Report_Idx exists. Check ok
2024.10.23 02:10:00 3: DbRep myDbRep_reduceLog - Initial data information retrieved - total time used: 0.0106 seconds
2024.10.23 02:10:00 3: DbRep myDbRep_reduceLog - Connectiontest to db mysql:database=fhem;host=localhost;port=3306 successful
2024.10.23 02:10:00 3: DbRep myDbRep_reduceLog - reduce data older than: 2024-09-25 02:09:59, newer than: 2023-12-25 00:30:00
2024.10.23 02:10:00 3: DbRep myDbRep_reduceLog - reduceLog requested with options:
average
INCLUDE -> Devs: 'Luftdruckmesser','Regenmesser','Klima_aussen','Klima_Wohnzimmer','MQTT2_ESP8266_Sensor_03','MQTT2_ESP8266_Sensor_04','MQTT2_ESP8266_Sensor_05','MQTT2_Ahoy_DTU_971008' Readings: 'pressure','rain_total','humidity','temperature','SoilTemp','VolumeWaterContent','Level','WindSpeedAverage','P_AC','YieldDay'
2024.10.23 02:10:02 3: DbRep myDbRep_reduceLog - reduceLog finished. Rows processed: 59675, deleted: 0, updated: 0Ich lasse jetzt mal freezemon mitlaufen, vielleicht gibt's damit ein paar hilfreiche Informationen.

Edit: Das ist die Speichernutzung gegen 8:30 Uhr von FHEM (ps aux). Man sieht, dass zwei FHEM-Prozesse laufen - davon einer mit erheblicher CPU-Nutzung:

Code Auswählen Erweitern

USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
fhem      113724 26.0  3.3 274024 265224 ?       R    Okt22 364:16 /usr/bin/perl fhem.pl configDB
fhem      113725  0.0  0.8  84640 71416 ?        S    Okt22   1:16 /usr/bin/perl fhem.pl configDB
fhem      113767  0.6  0.9 911228 73660 ?        Sl   Okt22   9:08 node /usr/local/bin/alexa-fhem -c ./alexa-fhem.cfg -s
fhem      113823  0.0  0.0  12100  6392 ?        S    Okt22   0:00 /usr/bin/ssh -R 1234:127.0.0.1:45057 -oServerAliveInterval=90

Du darfst diesen Dateianhang nicht ansehen.

[DS_Starter]

DbRep führt die Datenbank-Aktion nicht blockierend in einem temporären Nebenprozess (BlockingCall) aus.
Mit verbose 5 im Device sieht man die erzeugte Prozess-ID:

2024.10.23 19:17:03.438 4: DbRep Rep.update - -------- New selection ---------
2024.10.23 19:17:03.441 4: DbRep Rep.update - Command: reduceLog 74:80
2024.10.23 19:17:03.443 4: DbRep Rep.update - timeDiffToNow - year: , day: 80, hour: , min: , sec:
2024.10.23 19:17:03.445 4: DbRep Rep.update - Year 2024 is leap year
2024.10.23 19:17:03.447 4: DbRep Rep.update - startMonth: 7 endMonth: 9 lastleapyear:  baseYear: 2024 diffdaylight:1 isdaylight:1
2024.10.23 19:17:03.449 4: DbRep Rep.update - timeOlderThan - year: 0, day: 74, hour: 0, min: 0, sec: 0
2024.10.23 19:17:03.451 4: DbRep Rep.update - Year 2024 is leap year
2024.10.23 19:17:03.452 4: DbRep Rep.update - startMonth: 8 endMonth: 7 lastleapyear:  baseYear: 2024 diffdaylight:1 isdaylight:1
2024.10.23 19:17:03.454 4: DbRep Rep.update - FullDay option: 1
2024.10.23 19:17:03.455 4: DbRep Rep.update - Time difference to current time for calculating Timestamp begin: 6912001 sec
2024.10.23 19:17:03.457 5: DbRep Rep.update - Timestamp begin epocheseconds: 1722722400
2024.10.23 19:17:03.458 4: DbRep Rep.update - Timestamp begin human readable: 2024-08-04 00:00:00
2024.10.23 19:17:03.460 5: DbRep Rep.update - Timestamp end epocheseconds: 1723327199
2024.10.23 19:17:03.462 4: DbRep Rep.update - Timestamp end human readable: 2024-08-10 23:59:59
2024.10.23 19:17:03.464 5: DbRep Rep.update - weekday start for selection: So  ->  wdadd: 86400
2024.10.23 19:17:03.487 5: DbRep Rep.update - BlockingCall with PID "1825857" started
2024.10.23 19:17:03.503 4: DbRep Rep.update - Database Model: MYSQL
2024.10.23 19:17:03.506 4: DbRep Rep.update - Database connect - user: fhemtest, UTF-8 option set: yes
2024.10.23 19:17:03.513 4: DbRep Rep.update - Communication between Client and Server will be compressed
2024.10.23 19:17:03.516 4: DbRep Rep.update - SQL execute: SHOW VARIABLES LIKE 'collation_database'
2024.10.23 19:17:03.518 4: DbRep Rep.update - Database Character set is >utf8mb4_bin<
2024.10.23 19:17:03.520 4: DbRep Rep.update - simple do statement: set names "utf8mb4" collate "utf8mb4_bin"
2024.10.23 19:17:03.530 5: DbRep Rep.update - Devices for operation -
.....

Diese PID sieht man natürlich auch auf BS-Ebene:

fhem     1818099       1  5 12:34 ?        00:23:12 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818100 1818099  0 12:34 ?        00:00:08 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818101 1818099  0 12:34 ?        00:00:49 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818102 1818099  0 12:34 ?        00:00:09 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818103 1818099  0 12:34 ?        00:00:07 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818104 1818099  0 12:34 ?        00:00:13 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818105 1818099  0 12:34 ?        00:00:07 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818106 1818099  0 12:34 ?        00:00:07 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818107 1818099  0 12:34 ?        00:00:07 /usr/bin/perl fhem.pl fhem.cfg
fhem     1825857 1818099 39 19:17 ?        00:05:04 /usr/bin/perl fhem.pl fhem.cfg

Nach dem Ende der Aktion muß diese PID wieder verschwunden sein, da der Nebenprozess ebenfalls endet.

Code Auswählen Erweitern

fhem     1818099       1  5 12:34 ?        00:27:26 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818100 1818099  0 12:34 ?        00:00:10 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818101 1818099  0 12:34 ?        00:00:57 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818102 1818099  0 12:34 ?        00:00:10 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818103 1818099  0 12:34 ?        00:00:08 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818104 1818099  0 12:34 ?        00:00:15 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818105 1818099  0 12:34 ?        00:00:08 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818106 1818099  0 12:34 ?        00:00:08 /usr/bin/perl fhem.pl fhem.cfg
fhem     1818107 1818099  0 12:34 ?        00:00:08 /usr/bin/perl fhem.pl fhem.cfg

Vielleicht hilft dir dieser Zusammenhang bei der Suche.
Achtung: verbose 5 erzeugt sehr sehr viele Einträge im Log!

[JWRu]

Ich mein "at" um 2:00 Uhr gestern mal deaktiviert und heute Nachmittag etwas experimentiert:
Ich habe die erste Stufe (Aufruf von DbRep mit delEntries) mit Verbose 5 um Punkt 17:00 Uhr händisch ausgelöst - siehe Log:

Code Auswählen Erweitern

2024.10.24 17:00:00 3: DbRep myDbRep_delEntries - get initial structure information of database "fhem", remaining attempts: 3
2024.10.24 17:00:00 3: DbRep myDbRep_delEntries - Connectiontest to database mysql:database=fhem;host=localhost;port=3306 with user fhemuser
2024.10.24 17:00:00 5: DbRep myDbRep_delEntries - start BlockingCall with PID "76782"
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Database Model: MYSQL
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Database connect - user: fhemuser, UTF-8 option set: yes
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - SQL execute: SHOW VARIABLES LIKE 'collation_database'
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Database Character set is >utf8mb4_bin<
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - simple do statement: set names "utf8mb4" collate "utf8mb4_bin"
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Oldest timestamp determined: 2023-12-25 00:30:00
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Encoding of database determined: utf8mb4
2024.10.24 17:00:00 3: DbRep myDbRep_delEntries - Index Report_Idx exists. Check ok
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Grants determined: SELECT,DELETE,USAGE,INSERT,UPDATE
2024.10.24 17:00:00 5: DbRep myDbRep_delEntries - getInitData finished PID "76782"
2024.10.24 17:00:00 3: DbRep myDbRep_delEntries - Initial data information retrieved - total time used: 0.0126 seconds
2024.10.24 17:00:00 3: DbRep myDbRep_delEntries - Connectiontest to db mysql:database=fhem;host=localhost;port=3306 successful
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - -------- New selection ---------
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Command: delEntries
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - timeOlderThan - year: , day: 28, hour: , min: , sec:
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Year 2024 is leap year
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - startMonth: 11 endMonth: 8 lastleapyear:  baseYear: 2024 diffdaylight:1 isdaylight:1
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - FullDay option: 0
2024.10.24 17:00:00 5: DbRep myDbRep_delEntries - Timestamp begin epocheseconds: 1703460600
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Timestamp begin human readable: 2023-12-25 00:30:00
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Time difference to current time for calculating Timestamp end: 2419201 sec
2024.10.24 17:00:00 5: DbRep myDbRep_delEntries - Timestamp end epocheseconds: 1727362799.64942
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Timestamp end human readable: 2024-09-26 16:59:59
2024.10.24 17:00:00 5: DbRep myDbRep_delEntries - weekday start for selection: Mo  ->  wdadd: 604800
--> 2024.10.24 17:00:00 5: DbRep myDbRep_delEntries - BlockingCall with PID "76783" started
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Database Model: MYSQL
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Database connect - user: fhemuser, UTF-8 option set: yes
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - SQL execute: SHOW VARIABLES LIKE 'collation_database'
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - Database Character set is >utf8mb4_bin<
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - simple do statement: set names "utf8mb4" collate "utf8mb4_bin"
2024.10.24 17:00:00 5: DbRep myDbRep_delEntries - IsTimeSet: 1, IsAggrSet: 0
2024.10.24 17:00:00 5: DbRep myDbRep_delEntries - Devices for operation -
included (1): %
included with wildcard: 
excluded (8): Luftdruckmesser,Regenmesser,Klima_aussen,Klima_Wohnzimmer,MQTT2_ESP8266_Sensor_03,MQTT2_ESP8266_Sensor_04,MQTT2_ESP8266_Sensor_05,MQTT2_Ahoy_DTU_971008
excluded with wildcard:
2024.10.24 17:00:00 5: DbRep myDbRep_delEntries - Readings for operation -
included (1): %
included with wildcard: 
excluded (10): 'pressure','rain_total','humidity','temperature','SoilTemp','VolumeWaterContent','Level','WindSpeedAverage','P_AC','YieldDay'
excluded with wildcard:
2024.10.24 17:00:00 4: DbRep myDbRep_delEntries - SQL execute: delete FROM history where DEVICE NOT IN ('Luftdruckmesser','Regenmesser','Klima_aussen','Klima_Wohnzimmer','MQTT2_ESP8266_Sensor_03','MQTT2_ESP8266_Sensor_04','MQTT2_ESP8266_Sensor_05','MQTT2_Ahoy_DTU_971008') AND READING NOT IN ('pressure','rain_total','humidity','temperature','SoilTemp','VolumeWaterContent','Level','WindSpeedAverage','P_AC','YieldDay') AND TIMESTAMP >= '2023-12-25 00:30:00' AND TIMESTAMP <= '2024-09-26 16:59:59' ;
2024.10.24 17:00:01 5: DbRep myDbRep_delEntries - Number of deleted rows: 0
--> 2024.10.24 17:00:01 5: DbRep myDbRep_delEntries - BlockingCall PID "76783" finished
2024.10.24 17:00:01 3: DbRep myDbRep_delEntries - Entries of fhem.history deleted: EXCLUDE/Luftdruckmesser/Regenmesser/Klima_aussen/Klima_Wohnzimmer/MQTT2_ESP8266_Sensor_03/MQTT2_ESP8266_Sensor_04/MQTT2_ESP8266_Sensor_05/MQTT2_Ahoy_DTU_971008--EXCLUDE/pressure/rain_total/humidity/temperature/SoilTemp/VolumeWaterContent/Level/WindSpeedAverage/P_AC/YieldDay--0Der BlockingCall (PID 76783 - markiert mit -->) startet und wird kurz danach wieder beendet.
Danach steigt aber die CPU-Nutzung des FHEM-Hauptprozesses (PID 886) an und bleibt auch nach jetzt 4 Stunden immer noch auf erhöhtem Niveau.
Das ist sowohl im SYSMON-Plot als auch mit "ps" deutlich zu sehen.

Code Auswählen Erweitern

16:59 Uhr
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
fhem         886 10.0  3.4 284856 275096 ?       S    Okt23 156:23 /usr/bin/perl fhem.pl configDB
fhem         897  0.1  0.8  84652 71292 ?        S    Okt23   1:41 /usr/bin/perl fhem.pl configDB
fhem       76728  0.0  3.3 284856 266936 ?       S    16:58   0:00 /usr/bin/perl fhem.pl configDB


21:00 Uhr
fhem         886 18.2  3.5 288740 279936 ?       S    Okt23 328:17 /usr/bin/perl fhem.pl configDB
fhem         897  0.1  0.8  84652 71292 ?        S    Okt23   1:52 /usr/bin/perl fhem.pl configDB
fhem       89527  0.6  3.4 288740 271776 ?       S    20:58   0:00 /usr/bin/perl fhem.pl configDB
Du darfst diesen Dateianhang nicht ansehen.

[DS_Starter]

Dazu kann ich nichts weiter beitragen. Habe bei meinem Produktivsystem ohnehin eine stets wechselnde Last zwischen 2,6% bis 33%.

[JWRu]

Ich schließe auch mal ab - die Sache ist ja auch etwas off-topic.
Ich habe in den nächsten Wochen eh keine Zeit, weiter zu experimentieren.

[tobi01001]

Hallo Heiko,

Mir sind im Log-File immer folgende Fehler aufgetreten:

Code Auswählen Erweitern

readdir() attempted on invalid dirhandle DIR at /opt/fhem/FHEM/93_DbRep.pm line 562.
closedir() attempted on invalid dirhandle DIR at /opt/fhem/FHEM/93_DbRep.pm line 567.

Die Ursache habe ich nach langen Suchen (durch Codeänderung mit zusätzliche Logeinträgen) gefunden... Ich habe mein NAS (uralt Synology) abgeschalten, weil das Ding unverhältnismäßig viel Strom brauchte.
Ausgerechnet in einem DB-Rep Device hatte ich aber ein Attribut "dumpDirLocal" auf einen NFS-Mount gesetzt, der jetzt nicht mehr vorhanden ist.

Wie dem auch sei, vielleicht könntest du für solche Fälle (oder auch wenn in global das Verzeichnis nicht erreich- oder lesbar ist) soetwas wie das einbauen:

Code Auswählen Erweitern

opendir(DIR,$dir) or Log3 ($name, 1, "DbRep $name Kann nicht in Backup-Verzeichnis $dir schreiben.");

Das hätte mir die Suche vereinfacht. Ich bin zuerst davon ausgegangen, dass das log-Verzeichnis von DB-Rep nicht les-/ schreibbar wäre, konnte aber nix finden...

Nachdem im Code daraus offenbar "nur" die Liste der wiederherstellbaren Backups im Verzeichnis erstellt wird, könnte man für den Fall wo das Verzeichnis nicht existent oder lesbar ist den Teil auch überspringen (und dennoch eine Log-Meldung ausgeben)...

Danke und Gruß,
Tobias

[JWRu]

Dazu kann ich nichts weiter beitragen. Habe bei meinem Produktivsystem ohnehin eine stets wechselnde Last zwischen 2,6% bis 33%.

Ich melde ich mich doch noch mal.
Ich habe vermutlich den Grund für die erhöhte Systemlast gefunden. Die DbRep-Instanz, die alte Einträge aus der DbLog-Datenbank löscht, aktualisiert anschließend noch andauernd das erste der beiden Readings, obwohl sie längst beendet ist (Ausschnitt aus dem List unten).

Code Auswählen Erweitern

READINGS:
     2024-10-27 09:38:30   EXCLUDE/Luftdruckmesser/Regenmesser/Klima_aussen/Klima_Wohnzimmer/MQTT2_ESP8266_Sensor_03/MQTT2_ESP8266_Sensor_04/MQTT2_ESP8266_Sensor_05/MQTT2_Ahoy_DTU_971008--EXCLUDE/pressure/rain_total/humidity/temperature/SoilTemp/VolumeWaterContent/Level/WindSpeedAverage/P_AC/YieldDay--DELETED_ROWS_HISTORY 0
     2024-10-27 01:00:00   state           doneIch habe daraufhin event-on-change-reading auf .* gesetzt und die Systemlast ging sofort anschließend dauerhaft nach unten.

[DS_Starter]

Hallo zusammen,

@Tobias, danke für die Info, werde ich gerne berücksichtigen.

@JWRu, auch eigenartig. Ich habe ca. 160 DbReps laufen und keins dieser Devices generiert fortwährend Events nachdem es fertig ist. Gerade auch nochmal mit einem "delete" ausprobiert um deinen Case nachzustellen.

Kannst du eigentlich nur mal schauen ob du dir eine Logik eingebaut hast, vllt. ein sich wiederholendes at oder ein notify, welches das DbRep Device ständig antriggert. Man kann sich natürlich auch mit dem Attribut "executeAfterProc" selbst ein Schleife einbauen.

LG,
Heiko

(komisches Forum ... seit einiger Zeit kommen keine oder nur sporadisch Infomails zu aktualisierten Beiträgen)

[DS_Starter]

Hallo Bernd,

sorry, deinen Beitrag hatte ich ganz übersehen.    Bitte sieh es mir nach.

Ist es möglich userExitFn auch nonblocking auszuführen oder muss ich das in die myUtils integrieren. Bzw. (ich habe mit nonblocking noch keine Erfahrung) funktioniert das überhaupt, 2 nonblocking Prozesse db + myUtil die miteinander kommunizieren sollen?

Möglich ist vieles, aber die userExitFn würde ich dafür keinesfalls verwenden.
Die Funktion in userExitFn wird nach jedem generierten Reading des DbRep Devices aufgerufen damit man mit diesem Reading/Wert etwas machen kann.

Besser ist es dafür das Attr executeAfterProc zu verwenden. Die angegebene Routine wird nachdem DbRep mit seinen Aufgaben fertig ist ausgeführt.

Nachtrag:
Ich konnte beide Freezes durch manuellen Start reproduzieren.
Wieso sind es 2 und werden hier jeden Tag alles GTS neu gespeichert?

Weil wie oben geschrieben die Routine für jedes erstellten Reading durchlaufen wird.

Die GTS das ganze Jahr durch laufen zu lassen macht eigentlich keinen Sinn. Ich werde das at entsprechend anpassen.
Meine Fragen hätte ich trotzdem gerne beantwortet.

Ich hoffe es ist damit passiert. 

LG,
Heiko

[frober]

Hallo Heiko,
danke für deine Antwort. Damit sollten meine Fragen beantwortet sein.
Mein at für die GTS läuft nur noch von Jan bis März. Das sollte reichen.

Ich dachte schon du kannst mich nicht mehr leiden 😢 

Auch ich bekomme von machen Threads keine Benachrichtigung mehr. Das ist ein Problem der Forumssoftware, sollte ich der neueren Version evtl. behoben sein. Nur das Upgrade ist anscheinend zu aufwendig. Siehe https://forum.fhem.de/index.php?topic=133184.0

Grüße und einen schönen Feiertag
Bernd

[DS_Starter]

Danke Bernd und dir auch sowie ein schönes WE! 

LG