93_DbLog - Überlegungen zur Optimierung (RPI und andere Systeme)

DS_Starter · 11 Februar 2017, 16:53:04

Das sollte uns noch nicht entmutigen. Die Statements funktionieren erstmal.

Habe hier gefunden: http://laurenthinoul.com/how-to-fix-postgres-error-current-transaction-is-aborted-commands-ignored-until-end-of-transaction-block/

Gib mal in deinem SQL-Editor:

Code Auswählen

rollback;

Pyromane · 11 Februar 2017, 16:54:11

Zitat von: DS_Starter am 11 Februar 2017, 16:53:04Gib mal in deinem SQL-Editor:

Code Auswählen Erweitern
rollback;

Code Auswählen

WARNING:  there is no transaction in progress
ROLLBACK

Query returned successfully in 191 msec.

Tante EDIT sagt:
current enthält lediglich einen Eintrag und dieser ist ebenfalls von 14:15, eindeutig zu wenig.

JoeALLb · 11 Februar 2017, 17:01:38

Stellt sich die Frage, ob wir überhaupt mit Transaktionen Daten eintragen müssen...
denn diese machen für eine einzelne Tabelle die nochdazu nur Logs schreibt eibentlich überpowert.
Es müssen ja keine "zusammenhänge" in mehreren Tabellen sicher komplett eingetragen werden.

Eventuell wäre auch

Code Auswählen

SET AUTOCOMMIT { = | TO } { ON | OFF }
(kurzfristig) eine Hilfe?

DS_Starter · 11 Februar 2017, 17:03:12

Schalte mal nur auf history um mit DbLogType = History. Danach nur auf current.
Wie sieht es dann aus ?

@Joe, ja, die Frage ist natürlich berechtigt.

DS_Starter · 11 Februar 2017, 17:15:42

@Joe, auf Transactionen zu verzichten ist IMHO nur im synchronen mode sinnvoll. Im asynch mode brauche ich den rollback um die misslungenen Insert wieder an den Cache zurückzugeben für den nächsten Versuch.
Wir sollten also ergründen warum die Postgre so reagiert hat.

Pyromane · 11 Februar 2017, 17:19:07

Zitat von: DS_Starter am 11 Februar 2017, 17:03:12
Schalte mal nur auf history um mit DbLogType = History. Danach nur auf current.
Wie sieht es dann aus?

Als ich auf history umgestellt habe wurde der gesamte Cache erfolgreich in die DB geschrieben. (geprüft per Admin Tool)

Bei current erhalte ich folgende Fehlermeldung:

Code Auswählen

2017.02.11 17:14:51 5: DbLog myDbLog -> ################################################################
2017.02.11 17:14:51 5: DbLog myDbLog -> ###              New database processing cycle               ###
2017.02.11 17:14:51 5: DbLog myDbLog -> ################################################################
2017.02.11 17:14:51 5: DbLog myDbLog -> MemCache contains 5 entries to process
2017.02.11 17:14:51 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:14:48|mySysMon|SYSMON|ens3_diff: RX: 0.20 MB, TX: 4.60 MB, Total: 4.80 MB|ens3_diff|RX: 0.20 MB, TX: 4.60 MB, Total: 4.80 MB|
2017.02.11 17:14:51 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:14:48|mySysMon|SYSMON|fs_boot: Total: 472 MB, Used: 105 MB, 24 %, Available: 343 MB at /boot|fs_boot|Total: 472 MB, Used: 105 MB, 24 %, Available: 343 MB at /boot|
2017.02.11 17:14:51 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:14:48|mySysMon|SYSMON|ram: Total: 3008.29 MB, Used: -3847.19 MB, -127.89 %, Free: 5509.80 MB|ram|Total: 3008.29 MB, Used: -3847.19 MB, -127.89 %, Free: 5509.80 MB|
2017.02.11 17:14:51 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:14:48|mySysMon|SYSMON|fs_root: Total: 23551 MB, Used: 3131 MB, 15 %, Available: 19201 MB at /|fs_root|Total: 23551 MB, Used: 3131 MB, 15 %, Available: 19201 MB at /|
2017.02.11 17:14:51 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:14:48|mySysMon|SYSMON|loadavg: 0.00 0.01 0.00|loadavg|0.00 0.01 0.00|
2017.02.11 17:14:51 5: DbLog myDbLog -> DbLog_PushAsync called with timeout: 120
2017.02.11 17:14:51 5: DbLog myDbLog -> Start DbLog_PushAsync
2017.02.11 17:14:51 5: DbLog myDbLog -> Primary Key used in fhemdaten.history: timestamp,device,reading
2017.02.11 17:14:51 5: DbLog myDbLog -> Primary Key used in fhemdaten.current: device,reading
2017.02.11 17:14:51 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:14:48, Device: mySysMon, Type: SYSMON, Event: ens3_diff: RX: 0.20 MB, TX: 4.60 MB, Total: 4.80 MB, Reading: ens3_diff, Value: RX: 0.20 MB, TX: 4.60 MB, Total: 4.80 MB, Unit: 
2017.02.11 17:14:51 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:14:48, Device: mySysMon, Type: SYSMON, Event: fs_boot: Total: 472 MB, Used: 105 MB, 24 %, Available: 343 MB at /boot, Reading: fs_boot, Value: Total: 472 MB, Used: 105 MB, 24 %, Available: 343 MB at /boot, Unit: 
2017.02.11 17:14:51 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:14:48, Device: mySysMon, Type: SYSMON, Event: ram: Total: 3008.29 MB, Used: -3847.19 MB, -127.89 %, Free: 5509.80 MB, Reading: ram, Value: Total: 3008.29 MB, Used: -3847.19 MB, -127.89 %, Free: 5509.80 MB, Unit: 
2017.02.11 17:14:51 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:14:48, Device: mySysMon, Type: SYSMON, Event: fs_root: Total: 23551 MB, Used: 3131 MB, 15 %, Available: 19201 MB at /, Reading: fs_root, Value: Total: 23551 MB, Used: 3131 MB, 15 %, Available: 19201 MB at /, Unit: 
2017.02.11 17:14:51 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:14:48, Device: mySysMon, Type: SYSMON, Event: loadavg: 0.00 0.01 0.00, Reading: loadavg, Value: 0.00 0.01 0.00, Unit: 
2017.02.11 17:14:51 2: DbLog myDbLog -> Error: DBD::Pg::st execute_array failed: ERROR:  current transaction is aborted, commands ignored until end of transaction block [err was 7 now 2000000000]
executing 5 generated 4 errors at ./FHEM/93_DbLog.pm line 1481.

2017.02.11 17:14:51 5: DbLog myDbLog -> DbLog_PushAsync finished
2017.02.11 17:14:51 5: DbLog myDbLog -> Start DbLog_PushAsyncDone
2017.02.11 17:14:51 5: DbLog myDbLog -> DbLog_PushAsyncDone finished

DS_Starter · 11 Februar 2017, 17:34:55

Hmm... hat also tatsächlich nur etwas mit der current Tabelle zu tun. Da müssen wir doch nochmal an dem Statement schrauben. Ich weiß bloß noch nicht wo genau es haken könnte.
Um die Sperre zu lösen wird wahrscheinlich ein Restart der Postgre ausreichen. Schau mal ob der Fehler dann auf der current wiederkommt.
Muß erstmal nachdenken was an dem Statement nicht so ganz passt.

Pyromane · 11 Februar 2017, 18:00:30

Ich habe auf current umgestellt, diese per truncate geleert und den ganzen Server neugestartet, danach zeigt das Log folgendes:

Code Auswählen

2017.02.11 17:48:23 5: DbLog myDbLog -> ################################################################
2017.02.11 17:48:23 5: DbLog myDbLog -> ###              New database processing cycle               ###
2017.02.11 17:48:23 5: DbLog myDbLog -> ################################################################
2017.02.11 17:48:23 5: DbLog myDbLog -> MemCache contains 8 entries to process
2017.02.11 17:48:23 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:47:51|ESPEasy_ESP1_FW_RL|ESPEASY|absent|state|absent|
2017.02.11 17:48:23 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:47:51|ESPEasy_ESP1_FW_VL|ESPEASY|absent|state|absent|
2017.02.11 17:48:23 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:47:51|ESPEasy_ESP2_Raum|ESPEASY|absent|state|absent|
2017.02.11 17:48:23 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:47:52|ESPEasy_ESP1_FB_RL|ESPEASY|absent|state|absent|
2017.02.11 17:48:23 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:47:52|ESPEasy_ESP1_WW_WW|ESPEASY|absent|state|absent|
2017.02.11 17:48:23 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:47:54|ESPEasy_ESP1_RA_UM|ESPEASY|absent|state|absent|
2017.02.11 17:48:23 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:47:54|ESPEasy_ESP1_KW_KW|ESPEASY|absent|state|absent|
2017.02.11 17:48:23 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:47:55|ESPEasy_ESP1_FW_UM|ESPEASY|absent|state|absent|
2017.02.11 17:48:23 5: DbLog myDbLog -> DbLog_PushAsync called with timeout: 120
2017.02.11 17:48:23 5: DbLog myDbLog -> Start DbLog_PushAsync
2017.02.11 17:48:23 5: DbLog myDbLog -> Primary Key used in fhemdaten.history: timestamp,device,reading
2017.02.11 17:48:23 5: DbLog myDbLog -> Primary Key used in fhemdaten.current: device,reading
2017.02.11 17:48:23 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:47:51, Device: ESPEasy_ESP1_FW_RL, Type: ESPEASY, Event: absent, Reading: state, Value: absent, Unit: 
2017.02.11 17:48:23 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:47:51, Device: ESPEasy_ESP1_FW_VL, Type: ESPEASY, Event: absent, Reading: state, Value: absent, Unit: 
2017.02.11 17:48:23 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:47:51, Device: ESPEasy_ESP2_Raum, Type: ESPEASY, Event: absent, Reading: state, Value: absent, Unit: 
2017.02.11 17:48:23 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:47:52, Device: ESPEasy_ESP1_FB_RL, Type: ESPEASY, Event: absent, Reading: state, Value: absent, Unit: 
2017.02.11 17:48:23 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:47:52, Device: ESPEasy_ESP1_WW_WW, Type: ESPEASY, Event: absent, Reading: state, Value: absent, Unit: 
2017.02.11 17:48:23 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:47:54, Device: ESPEasy_ESP1_RA_UM, Type: ESPEASY, Event: absent, Reading: state, Value: absent, Unit: 
2017.02.11 17:48:23 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:47:54, Device: ESPEasy_ESP1_KW_KW, Type: ESPEASY, Event: absent, Reading: state, Value: absent, Unit: 
2017.02.11 17:48:23 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:47:55, Device: ESPEasy_ESP1_FW_UM, Type: ESPEASY, Event: absent, Reading: state, Value: absent, Unit: 
2017.02.11 17:48:23 5: DbLog myDbLog -> 8 of 8 events successfully updated in table current using PK on columns device,reading
2017.02.11 17:48:23 5: DbLog myDbLog -> DbLog_PushAsync finished
2017.02.11 17:48:23 5: DbLog myDbLog -> Start DbLog_PushAsyncDone
2017.02.11 17:48:23 5: DbLog myDbLog -> DbLog_PushAsyncDone finished
...
...
...
2017.02.11 17:48:53 5: DbLog myDbLog -> ################################################################
2017.02.11 17:48:53 5: DbLog myDbLog -> ###              New database processing cycle               ###
2017.02.11 17:48:53 5: DbLog myDbLog -> ################################################################
2017.02.11 17:48:53 5: DbLog myDbLog -> MemCache contains 5 entries to process
2017.02.11 17:48:53 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:48:42|mySysMon|SYSMON|loadavg: 0.20 0.09 0.03|loadavg|0.20 0.09 0.03|
2017.02.11 17:48:53 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:48:42|mySysMon|SYSMON|ens3_diff: RX: 0.00 MB, TX: 0.00 MB, Total: 0.00 MB|ens3_diff|RX: 0.00 MB, TX: 0.00 MB, Total: 0.00 MB|
2017.02.11 17:48:53 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:48:42|mySysMon|SYSMON|fs_boot: Total: 472 MB, Used: 105 MB, 24 %, Available: 343 MB at /boot|fs_boot|Total: 472 MB, Used: 105 MB, 24 %, Available: 343 MB at /boot|
2017.02.11 17:48:53 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:48:42|mySysMon|SYSMON|fs_root: Total: 23551 MB, Used: 3132 MB, 15 %, Available: 19201 MB at /|fs_root|Total: 23551 MB, Used: 3132 MB, 15 %, Available: 19201 MB at /|
2017.02.11 17:48:53 5: DbLog myDbLog -> MemCache contains: 2017-02-11 17:48:42|mySysMon|SYSMON|ram: Total: 3008.29 MB, Used: -2813.61 MB, -93.53 %, Free: 5572.53 MB|ram|Total: 3008.29 MB, Used: -2813.61 MB, -93.53 %, Free: 5572.53 MB|
2017.02.11 17:48:53 5: DbLog myDbLog -> DbLog_PushAsync called with timeout: 120
2017.02.11 17:48:53 5: DbLog myDbLog -> Start DbLog_PushAsync
2017.02.11 17:48:53 5: DbLog myDbLog -> Primary Key used in fhemdaten.history: timestamp,device,reading
2017.02.11 17:48:53 5: DbLog myDbLog -> Primary Key used in fhemdaten.current: device,reading
2017.02.11 17:48:53 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:48:42, Device: mySysMon, Type: SYSMON, Event: loadavg: 0.20 0.09 0.03, Reading: loadavg, Value: 0.20 0.09 0.03, Unit: 
2017.02.11 17:48:53 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:48:42, Device: mySysMon, Type: SYSMON, Event: ens3_diff: RX: 0.00 MB, TX: 0.00 MB, Total: 0.00 MB, Reading: ens3_diff, Value: RX: 0.00 MB, TX: 0.00 MB, Total: 0.00 MB, Unit: 
2017.02.11 17:48:53 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:48:42, Device: mySysMon, Type: SYSMON, Event: fs_boot: Total: 472 MB, Used: 105 MB, 24 %, Available: 343 MB at /boot, Reading: fs_boot, Value: Total: 472 MB, Used: 105 MB, 24 %, Available: 343 MB at /boot, Unit: 
2017.02.11 17:48:53 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:48:42, Device: mySysMon, Type: SYSMON, Event: fs_root: Total: 23551 MB, Used: 3132 MB, 15 %, Available: 19201 MB at /, Reading: fs_root, Value: Total: 23551 MB, Used: 3132 MB, 15 %, Available: 19201 MB at /, Unit: 
2017.02.11 17:48:53 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 17:48:42, Device: mySysMon, Type: SYSMON, Event: ram: Total: 3008.29 MB, Used: -2813.61 MB, -93.53 %, Free: 5572.53 MB, Reading: ram, Value: Total: 3008.29 MB, Used: -2813.61 MB, -93.53 %, Free: 5572.53 MB, Unit: 
2017.02.11 17:48:53 2: DbLog myDbLog -> Error: DBD::Pg::st execute_array failed: ERROR:  current transaction is aborted, commands ignored until end of transaction block [err was 7 now 2000000000]
executing 5 generated 3 errors at ./FHEM/93_DbLog.pm line 1481.

2017.02.11 17:48:53 5: DbLog myDbLog -> DbLog_PushAsync finished
2017.02.11 17:48:53 5: DbLog myDbLog -> Start DbLog_PushAsyncDone
2017.02.11 17:48:53 5: DbLog myDbLog -> DbLog_PushAsyncDone finished

Sehr eigenartig finde ich folgendes

Code Auswählen

2017.02.11 17:48:23 5: DbLog myDbLog -> 8 of 8 events successfully updated in table current using PK on columns device,reading

Obwohl die Tabelle leer ist?

Tante EDIT sagt:
ich finde jetzt folgenden Eintrag in der current Tabelle:

Code Auswählen

"timestamp","device","type","event","reading","value","unit"
"2017-02-11 18:02:38","ESPEASY","absent","absent","","ESPEasy_ESP1_FB_RL","state"

Scheint als wäre nur die letzte Zeile übertragen worden.

DS_Starter · 11 Februar 2017, 18:11:32

ZitatObwohl die Tabelle leer ist?

Ja, der Update war für den DB-Treiber erstmal ok, aber der Commit der die Daten in der DB manifestiert klappt offensichtlich nicht. Deswegen sind die Daten letztlich nicht drin und der nachfolgende update geht auf die Bretter weil der davor immer noch auf den commit wartet der nicht funktioniert. Das ist was ich mir bis jetzt erkläre ...

Teste mal die angehängte V2.12.5, die andere nehme ich wieder raus. Habe einen Fehler in der Zuweisung der bind-parameter gefunden. Vllt. ist es das schon gewesen.
Die Postgre mußt du wieder restarten nachdem du das Modul eingespielt hast. sonst löst sich die Sperre nicht.

Pyromane · 11 Februar 2017, 18:35:53

Jetzt hat sich mein EDIT und deine Antwort überschnitten, daher hier zur Sicherheit mein EDIT nochmal

ZitatTante EDIT sagt:
ich finde jetzt folgenden Eintrag in der current Tabelle:
Code Auswählen Erweitern
"timestamp","device","type","event","reading","value","unit" "2017-02-11 18:02:38","ESPEASY","absent","absent","","ESPEasy_ESP1_FB_RL","state"

Scheint als wäre nur die letzte Zeile übertragen worden.

Zitat von: DS_Starter am 11 Februar 2017, 18:11:32Teste mal die angehängte V2.12.5

Eingespielt, current Tabelle geleert und Server neugestartet

DbLogType Current
Current Tabelle erhält Einträge und bestehende werden auch aktualisiert.

DbLogType Current/History
Funktioniert nun ebenfalls, sprich current wird upgedatet und die history erhält Einträge dazu.

DS_Starter · 11 Februar 2017, 18:46:23

Dürfen wir uns jetzt wirklich freuen ?

Mach mal bitte noch ein verbose 5 Log.

Pyromane · 11 Februar 2017, 18:57:10

Zitat von: DS_Starter am 11 Februar 2017, 18:46:23
Dürfen wir uns jetzt wirklich freuen ?

current erhält immer noch laufend Updates
History wird laufend um neue Einträge erweitert

Japp, jetzt scheint der richtige Zeitpunkt gekommen zu sein um sich zu freuen

Und vor allem auch um ein Danke an dich zu richten

Zitat von: DS_Starter am 11 Februar 2017, 18:46:23Mach mal bitte noch ein verbose 5 Log.

Code Auswählen


2017.02.11 18:47:45 5: DbLog myDbLog -> ################################################################
2017.02.11 18:47:45 5: DbLog myDbLog -> ###              New database processing cycle               ###
2017.02.11 18:47:45 5: DbLog myDbLog -> ################################################################
2017.02.11 18:47:45 5: DbLog myDbLog -> MemCache contains 3 entries to process
2017.02.11 18:47:45 5: DbLog myDbLog -> MemCache contains: 2017-02-11 18:47:40|mySysMon|SYSMON|loadavg: 0.00 0.01 0.00|loadavg|0.00 0.01 0.00|
2017.02.11 18:47:45 5: DbLog myDbLog -> MemCache contains: 2017-02-11 18:47:40|mySysMon|SYSMON|ram: Total: 3008.29 MB, Used: -3085.54 MB, -102.57 %, Free: 5547.84 MB|ram|Total: 3008.29 MB, Used: -3085.54 MB, -102.57 %, Free: 5547.84 MB|
2017.02.11 18:47:45 5: DbLog myDbLog -> MemCache contains: 2017-02-11 18:47:40|mySysMon|SYSMON|ens3_diff: RX: 0.03 MB, TX: 0.02 MB, Total: 0.05 MB|ens3_diff|RX: 0.03 MB, TX: 0.02 MB, Total: 0.05 MB|
2017.02.11 18:47:45 5: DbLog myDbLog -> DbLog_PushAsync called with timeout: 120
2017.02.11 18:47:45 5: DbLog myDbLog -> Start DbLog_PushAsync
2017.02.11 18:47:45 5: DbLog myDbLog -> Primary Key used in fhemdaten.history: timestamp,device,reading
2017.02.11 18:47:45 5: DbLog myDbLog -> Primary Key used in fhemdaten.current: device,reading
2017.02.11 18:47:45 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 18:47:40, Device: mySysMon, Type: SYSMON, Event: loadavg: 0.00 0.01 0.00, Reading: loadavg, Value: 0.00 0.01 0.00, Unit: 
2017.02.11 18:47:45 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 18:47:40, Device: mySysMon, Type: SYSMON, Event: ram: Total: 3008.29 MB, Used: -3085.54 MB, -102.57 %, Free: 5547.84 MB, Reading: ram, Value: Total: 3008.29 MB, Used: -3085.54 MB, -102.57 %, Free: 5547.84 MB, Unit: 
2017.02.11 18:47:45 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 18:47:40, Device: mySysMon, Type: SYSMON, Event: ens3_diff: RX: 0.03 MB, TX: 0.02 MB, Total: 0.05 MB, Reading: ens3_diff, Value: RX: 0.03 MB, TX: 0.02 MB, Total: 0.05 MB, Unit: 
2017.02.11 18:47:45 5: DbLog myDbLog -> 3 of 3 events inserted into table history using PK on columns timestamp,device,reading
2017.02.11 18:47:45 5: DbLog myDbLog -> 3 of 3 events updated in table current using PK on columns device,reading
2017.02.11 18:47:45 5: DbLog myDbLog -> DbLog_PushAsync finished
2017.02.11 18:47:45 5: DbLog myDbLog -> Start DbLog_PushAsyncDone
2017.02.11 18:47:45 5: DbLog myDbLog -> DbLog_PushAsyncDone finished
...
...
...
2017.02.11 18:48:45 5: DbLog myDbLog -> ################################################################
2017.02.11 18:48:45 5: DbLog myDbLog -> ###              New database processing cycle               ###
2017.02.11 18:48:45 5: DbLog myDbLog -> ################################################################
2017.02.11 18:48:45 5: DbLog myDbLog -> MemCache contains 3 entries to process
2017.02.11 18:48:45 5: DbLog myDbLog -> MemCache contains: 2017-02-11 18:48:40|mySysMon|SYSMON|loadavg: 0.00 0.00 0.00|loadavg|0.00 0.00 0.00|
2017.02.11 18:48:45 5: DbLog myDbLog -> MemCache contains: 2017-02-11 18:48:40|mySysMon|SYSMON|ens3_diff: RX: 0.03 MB, TX: 0.01 MB, Total: 0.04 MB|ens3_diff|RX: 0.03 MB, TX: 0.01 MB, Total: 0.04 MB|
2017.02.11 18:48:45 5: DbLog myDbLog -> MemCache contains: 2017-02-11 18:48:40|mySysMon|SYSMON|ram: Total: 3008.29 MB, Used: -3085.08 MB, -102.55 %, Free: 5547.36 MB|ram|Total: 3008.29 MB, Used: -3085.08 MB, -102.55 %, Free: 5547.36 MB|
2017.02.11 18:48:45 5: DbLog myDbLog -> DbLog_PushAsync called with timeout: 120
2017.02.11 18:48:45 5: DbLog myDbLog -> Start DbLog_PushAsync
2017.02.11 18:48:45 5: DbLog myDbLog -> Primary Key used in fhemdaten.history: timestamp,device,reading
2017.02.11 18:48:45 5: DbLog myDbLog -> Primary Key used in fhemdaten.current: device,reading
2017.02.11 18:48:45 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 18:48:40, Device: mySysMon, Type: SYSMON, Event: loadavg: 0.00 0.00 0.00, Reading: loadavg, Value: 0.00 0.00 0.00, Unit: 
2017.02.11 18:48:45 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 18:48:40, Device: mySysMon, Type: SYSMON, Event: ens3_diff: RX: 0.03 MB, TX: 0.01 MB, Total: 0.04 MB, Reading: ens3_diff, Value: RX: 0.03 MB, TX: 0.01 MB, Total: 0.04 MB, Unit: 
2017.02.11 18:48:45 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 18:48:40, Device: mySysMon, Type: SYSMON, Event: ram: Total: 3008.29 MB, Used: -3085.08 MB, -102.55 %, Free: 5547.36 MB, Reading: ram, Value: Total: 3008.29 MB, Used: -3085.08 MB, -102.55 %, Free: 5547.36 MB, Unit: 
2017.02.11 18:48:45 5: DbLog myDbLog -> 3 of 3 events inserted into table history using PK on columns timestamp,device,reading
2017.02.11 18:48:45 5: DbLog myDbLog -> 3 of 3 events updated in table current using PK on columns device,reading
2017.02.11 18:48:45 5: DbLog myDbLog -> DbLog_PushAsync finished
...
...
...
2017.02.11 18:54:46 5: DbLog myDbLog -> ################################################################
2017.02.11 18:54:46 5: DbLog myDbLog -> ###              New database processing cycle               ###
2017.02.11 18:54:46 5: DbLog myDbLog -> ################################################################
2017.02.11 18:54:46 5: DbLog myDbLog -> MemCache contains 5 entries to process
2017.02.11 18:54:46 5: DbLog myDbLog -> MemCache contains: 2017-02-11 18:54:26|myDbLog|DBLOG|countHistory: 2567557|countHistory|2567557|
2017.02.11 18:54:46 5: DbLog myDbLog -> MemCache contains: 2017-02-11 18:54:26|myDbLog|DBLOG|countCurrent: 19|countCurrent|19|
2017.02.11 18:54:46 5: DbLog myDbLog -> MemCache contains: 2017-02-11 18:54:40|mySysMon|SYSMON|loadavg: 0.00 0.00 0.00|loadavg|0.00 0.00 0.00|
2017.02.11 18:54:46 5: DbLog myDbLog -> MemCache contains: 2017-02-11 18:54:40|mySysMon|SYSMON|ram: Total: 3008.29 MB, Used: -3085.74 MB, -102.57 %, Free: 5547.39 MB|ram|Total: 3008.29 MB, Used: -3085.74 MB, -102.57 %, Free: 5547.39 MB|
2017.02.11 18:54:46 5: DbLog myDbLog -> MemCache contains: 2017-02-11 18:54:40|mySysMon|SYSMON|ens3_diff: RX: 0.05 MB, TX: 0.07 MB, Total: 0.12 MB|ens3_diff|RX: 0.05 MB, TX: 0.07 MB, Total: 0.12 MB|
2017.02.11 18:54:46 5: DbLog myDbLog -> DbLog_PushAsync called with timeout: 120
2017.02.11 18:54:46 5: DbLog myDbLog -> Start DbLog_PushAsync
2017.02.11 18:54:46 5: DbLog myDbLog -> Primary Key used in fhemdaten.history: timestamp,device,reading
2017.02.11 18:54:46 5: DbLog myDbLog -> Primary Key used in fhemdaten.current: device,reading
2017.02.11 18:54:46 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 18:54:26, Device: myDbLog, Type: DBLOG, Event: countHistory: 2567557, Reading: countHistory, Value: 2567557, Unit: 
2017.02.11 18:54:46 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 18:54:26, Device: myDbLog, Type: DBLOG, Event: countCurrent: 19, Reading: countCurrent, Value: 19, Unit: 
2017.02.11 18:54:46 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 18:54:40, Device: mySysMon, Type: SYSMON, Event: loadavg: 0.00 0.00 0.00, Reading: loadavg, Value: 0.00 0.00 0.00, Unit: 
2017.02.11 18:54:46 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 18:54:40, Device: mySysMon, Type: SYSMON, Event: ram: Total: 3008.29 MB, Used: -3085.74 MB, -102.57 %, Free: 5547.39 MB, Reading: ram, Value: Total: 3008.29 MB, Used: -3085.74 MB, -102.57 %, Free: 5547.39 MB, Unit: 
2017.02.11 18:54:46 5: DbLog myDbLog -> processing event Timestamp: 2017-02-11 18:54:40, Device: mySysMon, Type: SYSMON, Event: ens3_diff: RX: 0.05 MB, TX: 0.07 MB, Total: 0.12 MB, Reading: ens3_diff, Value: RX: 0.05 MB, TX: 0.07 MB, Total: 0.12 MB, Unit: 
2017.02.11 18:54:46 5: DbLog myDbLog -> 5 of 5 events inserted into table history using PK on columns timestamp,device,reading
2017.02.11 18:54:46 5: DbLog myDbLog -> 5 of 5 events updated in table current using PK on columns device,reading
2017.02.11 18:54:46 5: DbLog myDbLog -> DbLog_PushAsync finished
2017.02.11 18:54:46 5: DbLog myDbLog -> Start DbLog_PushAsyncDone
2017.02.11 18:54:46 5: DbLog myDbLog -> DbLog_PushAsyncDone finished

DS_Starter · 11 Februar 2017, 19:04:35

Ich danke dir !

Tests kosten (Frei-)Zeit und Mühe ...
Im Team kommt man eben wirklich weiter und Spaß macht es so auch mehr als nur im eigenen Saft zu schmoren

Schau mal noch ein bisschen rum ... synch mode usw. wie weiter vorn beschrieben ....
Ich teste auch noch etwas mit MySQL und SQLite ...

schönen Abend !

LG
Heiko

DeeSPe · 13 Februar 2017, 16:45:55

Servus Heiko!

Ich denke ich habe reduceLog non-blocking hinbekommen.
Zumindest arbeitet die Funktion und es kommt auch etwas zurück!
die Zeitangabe sieht noch etwas utopisch aus, vielleicht guckst Du Dir das nochmal an.

Per PN habe ich Dir einen Link auf meine Dropbox von der Dev Version geschickt.
Bitte schaue es Dir an und teste!

Danke.

Gruß
Dan

DS_Starter · 15 Februar 2017, 07:44:08

Hallo Dan, @all,

ich habe die Arbeit von Dan bzgl. der non-blocking reduceLog-Funktion in DbLog eingearbeitet und auch auf MySQL getestet.
Läuft bei mir auf MySQL erwartungsgemäß super gut, d.h. FHEM und Logging laufen ohne Beeinträchtigung weiter wenn reducelog gestartet wurde.

Bitte testet es auf euren Systemen, inbesondere wieder SQLite bzw. Postrgre.

Jetzt haben wir in Summe folgende Weiterentwicklungen gegenüber der eingecheckten 2.11.4:

* Support für primary Key auf allen DB's (PostgreSQL ab 9.5) für history und current
* Command clearReadings
* reduceLog non-blocking

Nochmal herzlichen Dank an Dan !!

Nur als Info, das Kommando clearReadings habe ich extra nicht z.B. delReadings genannt um nicht zu suggerieren es würden Readings in der DB gelöscht.

Die neue V2.13.0 ist anbei.

viele Grüße
Heiko