93_DbLog - Umstellung Log-Funktion auf non-blocking

stromer-12 · 22 Januar 2017, 21:15:09

Habe bei mir das IGNORE aber eingesetzt.

DS_Starter · 22 Januar 2017, 21:26:27

ZitatHabe bei mir das IGNORE aber eingesetzt.

Joe und du macht da ein paar Versuche mit IGNORE ...
Das wollte ich später auch mal probieren um bei der Current das Update/Insert zusammenfassen zu können .
Aber das versuche ich mit Joe erst später. Ich muß auch mal eine Pause machen ...

JoeALLb · 22 Januar 2017, 21:37:52

Zitat von: DS_Starter am 22 Januar 2017, 21:10:57
Mach dir doch mal verbose 5 an. Es sollte dann ersichtlich sein wieviele Datansätze (Ist/Soll) in die DB eingefügt wurden.

Werd ich morgen mal machen, heute ists schon zu spät dafür!

@Stromer: Ernn ich ignore einfüge, kommt der oben von mir genannte fehler gar nicht mehr... das mit verbose5 rauskommt weiß ich gerade nicht.
Jedenfalls ist für mich "insert ignore" ohne negative Nebenwirkung, also sehr positiv.

Im Moment benutze ich jedoch bewußt die Originalversion ohne ignor, um die Devices ausfindug machen zu können, die eben falsche/doppelte Stati loggen. Mit ignore sehe ich dazu im Moment keine
Möglichkeit...

Guten Nacht euch allen, und Danke an Heiko!!!

DS_Starter · 22 Januar 2017, 21:44:38

Ja ist schon spät. Habe die 2.10.4 noch eingecheckt.

Gute Nacht @all, gute Nacht Joe.

Heiko

stromer-12 · 22 Januar 2017, 22:01:32

Ich habe jetzt mal mit der 2.10.4 und den timeout rumgespielt, ich habe den Timeout hochgeschraubt auf über eine Stunde und es hat geklappt.
Ich hatte die Datenbank ümorganisiert. Der erste Commit blieb im Hintergrund bestehen und der nächste schob sich immer weiter bis der Hintergrundtask beendet(abgeschlossen) wurde.

ioT4db · 23 Januar 2017, 08:57:57

Hallo Heiko,

die Attribute für die Feldlängen funktionieren! Hab die 2.10.4 am WE getestet und soweit läuft alles stabil!

Das einzige was mir aufgefallen ist, dass z.B. bei einem FHEM-Update mit verbundenem Restart anfänglich noch Werte mit den "kurzen" Feldlängen in die DB geschrieben werden. Das sind bei mir pro Update 1-2 Datensätze, die "abgehackt" werden. Scheinbar wirken die Attribute nicht schnell genug. Vlt. könnte man da noch etwas nachjustieren...

Nun an dieser Stelle auch nochmal von mir ein dickes Dankeschön für die Zeit und Energie, die Du und nicht zu vergessen alle anderen Beteiligten, die sich hier engagieren, investieren!

VG
Daniel...

JoeALLb · 23 Januar 2017, 10:43:56

Zitat von: DS_Starter am 22 Januar 2017, 21:10:57
Mach dir doch mal verbose 5 an. Es sollte dann ersichtlich sein wieviele Datansätze (Ist/Soll) in die DB eingefügt wurden.

Anbei ein Eintrag mit Verbose 5 mit 2.10.4 von gestern aus dem Forum: Besonders viel kann ich daran nicht erkennen

Code Auswählen

2017.01.23 10:36:06 4: DbLog myDbLogSQL -> ################################################################
2017.01.23 10:36:06 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.23 10:36:06 4: DbLog myDbLogSQL -> ################################################################
2017.01.23 10:36:06 4: DbLog myDbLogSQL -> amount of events received: 1 for device: PCA301_01
2017.01.23 10:36:06 4: DbLog myDbLogSQL -> check Device: PCA301_01 , Event: power: 2
2017.01.23 10:36:11 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 20634 generated 20619 errors at ./FHEM/93_DbLog.pm line 1326.

2017.01.23 10:36:11 5: DbLog myDbLogSQL -> DbLog_PushAsync finished

Ein bisschen früher imLog steht dies:
Wenn ich das richtig verstehe, versucht er um 10:35 noch immer einen Eintrag in die DB zu schreiben, der eigentlich von "04:44:09" stammt, und eben nicht geschrieben werden kann
weil er doppelt ist...

Code Auswählen

2017.01.23 10:35:43 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-23 04:46:07, Device: CO20, Type: CO20, Event: voc: 1940, Reading: voc, Value: 1940, Unit:
2017.01.23 10:35:43 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-23 04:46:07, Device: CO20, Type: CO20, Event: debug: 778, Reading: debug, Value: 778, Unit:
2017.01.23 10:35:43 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-23 04:46:07, Device: CO20, Type: CO20, Event: r_h: 152.21, Reading: r_h, Value: 152.21, Unit:
2017.01.23 10:35:43 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-23 04:46:07, Device: CO20, Type: CO20, Event: r_s: 172478, Reading: r_s, Value: 172478, Unit:
2017.01.23 10:35:43 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-23 04:44:05, Device: myDbLogSQL, Type: DBLOG, Event: sql_processing_time: 18.0341, Reading: sql_processing_time, Value: 18.0341, Unit:
2017.01.23 10:35:43 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-23 04:44:05, Device: myDbLogSQL, Type: DBLOG, Event: DBD::mysql::st execute_array failed: executing 13784 generated 13760 errors at ./FHEM/93_DbLog.pm line 1326.
, Reading: DBD::mysql::st execute_array failed, Value: executing 13784 generated 13760 errors at ./FHEM/93_DbLog.pm line 1326.
, Unit:
2017.01.23 10:35:43 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-23 04:44:05, Device: ug.Stauraum, Type: LACROSSE, Event: humidity: 50.7, Reading: humidity, Value: 50.7, Unit: %
2017.01.23 10:35:43 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-23 04:44:09, Device: ug.Stauraum, Type: LACROSSE, Event: humidity: 50.55, Reading: humidity, Value: 50.55, Unit: %
2017.01.23 10:35:43 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-23 04:44:09, Device: ug.Stauraum, Type: LACROSSE, Event: dd: 654.8, Reading: dd, Value: 654.8, Unit:

Soll ich aktuell einfach wieder auf insert ignore umstellen, damit sich mein Cache wieder leert?

DS_Starter · 23 Januar 2017, 11:14:05

Hi Joe,

Bin unterwegs und kann schlecht schreiben.
Deine Annahme sehe ich auch so. Aber ich vermisse im Logfile Einträge wie "... Events successfuly Inserts ..." Oder eben "Failed toll insert Info history ... " Eins von beiden muss da kommen.
Guckst nochmal. Damit sich DbLog nicht selbst loggt kannst du excludedevs setzen.

VG
Heikk

JoeALLb · 23 Januar 2017, 16:11:44

Hallo Heiko,

davon sehe ich leider seit dem Update nichts mehr im Log mein letzter Eintrag davon war vom 16.1.

Anbei noch ein Screenshot von einem anderen System, das das Update von heute zeigt. (Zuvor war DbLog 2.9.2 installiert)
Ich kann mir im Moment nicht erklären, warum die Zeiten nach dem Update heute so massiv angestiegen sind,
einzig was ich sehe ist eine enorme CPU-Auslastung durch fhem selbst.
Aufgefallen ist mir nur, dass kurz nach dem Absetzen con "shutdown restart" die CacheUsage mit 16710 angezeigt wurde.
Woher dieser riesige Wert plötzlich kommt, kann ich mir nicht erklären. In die DB wurde jedenfalls nie solch eine hohe Anzahl in 60
Sekunden geschrieben...

Edit1: Umstellung auf async=0 hat die CPU-Last wieder auf einen Normalwert gesenkt.

Im Log (es war nicht auf verbose5!) war nur folgendes seit dem Restart zu finden:
keine einzige Zeile bezüglich: "... Events successfuly Inserts ..." Oder eben "Failed toll insert Info history ... "

Code Auswählen

2017.01.23 16:03:45 2: DbLog myDbLogSQL waiting for shutdown
2017.01.23 16:07:30 3: DbRep myDbLogSQLrep - connected
2017.01.23 16:10:33 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 399 generated 6 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:11:33 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 501 generated 399 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:11:42 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: Duplicate entry 'eq3-state-2017-01-23 16:07:35-0' for key 'PRIMARY' [err was 1062 now 2000000000]
2017.01.23 16:11:53 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 534 generated 529 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:12:15 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 539 generated 534 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:12:25 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 545 generated 539 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:12:30 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 556 generated 545 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:12:35 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 569 generated 556 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:12:39 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 573 generated 569 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:12:44 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 574 generated 573 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:12:48 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 575 generated 574 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:12:54 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 576 generated 575 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:12:58 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 584 generated 576 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:13:02 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 585 generated 584 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:13:07 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 586 generated 585 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:13:11 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 587 generated 586 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:13:16 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 588 generated 587 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:13:21 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: Duplicate entry 'myDbLogSQL-sql_processing_time-2017-01-23 16:12:32-0' for key 'PRIMARY' [err was 1062 now 2000000000]
2017.01.23 16:13:25 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 599 generated 594 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:13:31 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 600 generated 599 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:13:36 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 613 generated 600 errors at ./FHEM/93_DbLog.pm line 1324.
2017.01.23 16:13:42 2: DbLog myDbLogSQL -> Error: DBD::mysql::st execute_array failed: executing 614 generated 613 errors at ./FHEM/93_DbLog.pm line 1324.

Edit2: VErsion von DbLog(alt) im Text ergänzt).

JoeALLb · 23 Januar 2017, 16:32:29

Mein zweites System zeigt diesen Effekt übrigens ebenfalls

Tedious · 23 Januar 2017, 17:44:41

Hallo zusammen,

ich hab seit 2 oder 3 Tagen reproduzierbar Fehler im Modul:

Code Auswählen

DBD::mysql::db commit failed: Turning on AutoCommit failed at ./FHEM/93_DbLog.pm line 1107.
DBD::mysql::db rollback failed: Turning on AutoCommit failed at ./FHEM/93_DbLog.pm line 1101.
DBD::mysql::db rollback failed: Turning on AutoCommit failed at ./FHEM/93_DbLog.pm line 1101.
DBD::mysql::db commit failed: Turning on AutoCommit failed at ./FHEM/93_DbLog.pm line 1107.
DBD::mysql::db rollback failed: Turning on AutoCommit failed at ./FHEM/93_DbLog.pm line 1101.
DBD::mysql::db commit failed: Turning on AutoCommit failed at ./FHEM/93_DbLog.pm line 1107.

Hatte noch nichts unternommen, aber auch die Updates ändern nix am Status?!

DS_Starter · 23 Januar 2017, 18:21:42

Hallo Joe,

ich vermute es hängt mit deiner speziellen DB-Konfiguration zusammen. Es werden ja bei dir viele Fehler produziert die wiederum, so wie ich gesehen habe, in der DB geloggt werden sollen. Ich denke du löst das Problem wenn du wieder auf dein IGNORE umstellst.

Hier mal ein Beispiel für ein verbose 5 log eines DB-Insert Zyklus. Du siehst am Ende auch den Eintrag wieviele insert in die einzelnen Tabellen vorgenommen wurden.

Code Auswählen


2017.01.23 16:28:47.583 5: DbLog LogDB -> ################################################################
2017.01.23 16:28:47.583 5: DbLog LogDB -> ###              New database processing cycle               ###
2017.01.23 16:28:47.583 5: DbLog LogDB -> ################################################################
2017.01.23 16:28:47.583 5: DbLog LogDB -> MemCache contains 22 entries to process
2017.01.23 16:28:47.583 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|SMA_Energymeter|SMAEM|Bezug_WirkP_Zaehler_Diff: 0.0099|Bezug_WirkP_Zaehler_Diff|0.0099|
2017.01.23 16:28:47.583 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|SMA_Energymeter|SMAEM|Bezug_WirkP_Kosten_Diff: 0.0021|Bezug_WirkP_Kosten_Diff|0.0021|
2017.01.23 16:28:47.584 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|SMA_Energymeter|SMAEM|Einspeisung_WirkP_Zaehler_Diff: 0|Einspeisung_WirkP_Zaehler_Diff|0|
2017.01.23 16:28:47.584 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|SMA_Energymeter|SMAEM|Einspeisung_WirkP_Verguet_Diff: 0.0000|Einspeisung_WirkP_Verguet_Diff|0.0000|
2017.01.23 16:28:47.584 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|SMA_Energymeter|SMAEM|-553.0|state|-553.0|
2017.01.23 16:28:47.584 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|SMA_Energymeter|SMAEM|Saldo_Wirkleistung: -553.0|Saldo_Wirkleistung|-553.0|
2017.01.23 16:28:47.584 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|SMA_Energymeter|SMAEM|Bezug_Wirkleistung: 553.0|Bezug_Wirkleistung|553.0|
2017.01.23 16:28:47.584 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|SMA_Energymeter|SMAEM|Bezug_Wirkleistung_Zaehler: 1521.5514|Bezug_Wirkleistung_Zaehler|1521.5514|
2017.01.23 16:28:47.584 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|SMA_Energymeter|SMAEM|Einspeisung_Wirkleistung: 0.0|Einspeisung_Wirkleistung|0.0|
2017.01.23 16:28:47.584 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|SMA_Energymeter|SMAEM|Einspeisung_Wirkleistung_Zaehler: 1632.1170|Einspeisung_Wirkleistung_Zaehler|1632.1170|
2017.01.23 16:28:47.584 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|MySTP_5000|SMAINVERTER|etotal: 12870.662|etotal|12870.662|
2017.01.23 16:28:47.584 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|MySTP_5000|SMAINVERTER|0.000|state|0.000|
2017.01.23 16:28:47.584 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:02|Dum.Energy|DUMMY|TotalConsumption: 553.0|TotalConsumption|553.0|
2017.01.23 16:28:47.585 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:16|MyWetter|WEATHER|wind: 7|wind|7|km/h
2017.01.23 16:28:47.585 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:16|MyWetter|WEATHER|humidity: 93|humidity|93|%
2017.01.23 16:28:47.585 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:16|MyWetter|WEATHER|pressure: 1011|pressure|1011|hPa
2017.01.23 16:28:47.585 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:16|MyWetter|WEATHER|temperature: -5|temperature|-5|°C
2017.01.23 16:28:47.585 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:37|sysmon|SYSMON|ram: Total: 876.27 MB, Used: 231.00 MB, 26.36 %, Free: 645.27 MB|ram|Total: 876.27 MB, Used: 231.00 MB, 26.36 %, Free: 645.27 MB|
2017.01.23 16:28:47.585 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:37|sysmon|SYSMON|loadavg: 0.10 0.04 0.05|loadavg|0.10 0.04 0.05|
2017.01.23 16:28:47.585 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:37|sysmon|SYSMON|swap: Total: 1293.00 MB, Used: 0.05 MB,  0.00 %, Free: 1292.95 MB|swap|Total: 1293.00 MB, Used: 0.05 MB,  0.00 %, Free: 1292.95 MB|
2017.01.23 16:28:47.585 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:37|sysmon|SYSMON|stat_cpu_percent: 0.97 0.00 0.38 98.46 0.09 0.00 0.11|stat_cpu_percent|0.97 0.00 0.38 98.46 0.09 0.00 0.11|
2017.01.23 16:28:47.585 5: DbLog LogDB -> MemCache contains: 2017-01-23 16:28:37|sysmon|SYSMON|eth0_diff: RX: 0.14 MB, TX: 0.10 MB, Total: 0.24 MB|eth0_diff|RX: 0.14 MB, TX: 0.10 MB, Total: 0.24 MB|
2017.01.23 16:28:47.592 5: DbLog LogDB -> DbLog_PushAsync called with timeout: 60
2017.01.23 16:28:47.597 4: DbLog LogDB -> Device: LogDB excluded from database logging due to attribute "excludeDevs" restrictions
2017.01.23 16:28:47.597 5: DbLog LogDB -> Start DbLog_PushAsync
2017.01.23 16:28:47.601 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: SMA_Energymeter, Type: SMAEM, Event: Bezug_WirkP_Zaehler_Diff: 0.0099, Reading: Bezug_WirkP_Zaehler_Diff, Value: 0.0099, Unit: 
2017.01.23 16:28:47.601 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: SMA_Energymeter, Type: SMAEM, Event: Bezug_WirkP_Kosten_Diff: 0.0021, Reading: Bezug_WirkP_Kosten_Diff, Value: 0.0021, Unit: 
2017.01.23 16:28:47.601 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: SMA_Energymeter, Type: SMAEM, Event: Einspeisung_WirkP_Zaehler_Diff: 0, Reading: Einspeisung_WirkP_Zaehler_Diff, Value: 0, Unit: 
2017.01.23 16:28:47.602 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: SMA_Energymeter, Type: SMAEM, Event: Einspeisung_WirkP_Verguet_Diff: 0.0000, Reading: Einspeisung_WirkP_Verguet_Diff, Value: 0.0000, Unit: 
2017.01.23 16:28:47.602 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: SMA_Energymeter, Type: SMAEM, Event: -553.0, Reading: state, Value: -553.0, Unit: 
2017.01.23 16:28:47.602 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: SMA_Energymeter, Type: SMAEM, Event: Saldo_Wirkleistung: -553.0, Reading: Saldo_Wirkleistung, Value: -553.0, Unit: 
2017.01.23 16:28:47.602 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: SMA_Energymeter, Type: SMAEM, Event: Bezug_Wirkleistung: 553.0, Reading: Bezug_Wirkleistung, Value: 553.0, Unit: 
2017.01.23 16:28:47.602 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: SMA_Energymeter, Type: SMAEM, Event: Bezug_Wirkleistung_Zaehler: 1521.5514, Reading: Bezug_Wirkleistung_Zaehler, Value: 1521.5514, Unit: 
2017.01.23 16:28:47.603 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: SMA_Energymeter, Type: SMAEM, Event: Einspeisung_Wirkleistung: 0.0, Reading: Einspeisung_Wirkleistung, Value: 0.0, Unit: 
2017.01.23 16:28:47.603 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: SMA_Energymeter, Type: SMAEM, Event: Einspeisung_Wirkleistung_Zaehler: 1632.1170, Reading: Einspeisung_Wirkleistung_Zaehler, Value: 1632.1170, Unit: 
2017.01.23 16:28:47.603 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: MySTP_5000, Type: SMAINVERTER, Event: etotal: 12870.662, Reading: etotal, Value: 12870.662, Unit: 
2017.01.23 16:28:47.603 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: MySTP_5000, Type: SMAINVERTER, Event: 0.000, Reading: state, Value: 0.000, Unit: 
2017.01.23 16:28:47.604 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:02, Device: Dum.Energy, Type: DUMMY, Event: TotalConsumption: 553.0, Reading: TotalConsumption, Value: 553.0, Unit: 
2017.01.23 16:28:47.604 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:16, Device: MyWetter, Type: WEATHER, Event: wind: 7, Reading: wind, Value: 7, Unit: km/h
2017.01.23 16:28:47.604 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:16, Device: MyWetter, Type: WEATHER, Event: humidity: 93, Reading: humidity, Value: 93, Unit: %
2017.01.23 16:28:47.604 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:16, Device: MyWetter, Type: WEATHER, Event: pressure: 1011, Reading: pressure, Value: 1011, Unit: hPa
2017.01.23 16:28:47.604 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:16, Device: MyWetter, Type: WEATHER, Event: temperature: -5, Reading: temperature, Value: -5, Unit: °C
2017.01.23 16:28:47.604 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:37, Device: sysmon, Type: SYSMON, Event: ram: Total: 876.27 MB, Used: 231.00 MB, 26.36 %, Free: 645.27 MB, Reading: ram, Value: Total: 876.27 MB, Used: 231.00 MB, 26.36 %, Free: 645.27 MB, Unit: 
2017.01.23 16:28:47.605 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:37, Device: sysmon, Type: SYSMON, Event: loadavg: 0.10 0.04 0.05, Reading: loadavg, Value: 0.10 0.04 0.05, Unit: 
2017.01.23 16:28:47.605 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:37, Device: sysmon, Type: SYSMON, Event: swap: Total: 1293.00 MB, Used: 0.05 MB,  0.00 %, Free: 1292.95 MB, Reading: swap, Value: Total: 1293.00 MB, Used: 0.05 MB,  0.00 %, Free: 1292.95 MB, Unit: 
2017.01.23 16:28:47.605 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:37, Device: sysmon, Type: SYSMON, Event: stat_cpu_percent: 0.97 0.00 0.38 98.46 0.09 0.00 0.11, Reading: stat_cpu_percent, Value: 0.97 0.00 0.38 98.46 0.09 0.00 0.11, Unit: 
2017.01.23 16:28:47.605 5: DbLog LogDB -> processing event Timestamp: 2017-01-23 16:28:37, Device: sysmon, Type: SYSMON, Event: eth0_diff: RX: 0.14 MB, TX: 0.10 MB, Total: 0.24 MB, Reading: eth0_diff, Value: RX: 0.14 MB, TX: 0.10 MB, Total: 0.24 MB, Unit: 
2017.01.23 16:28:47.628 5: DbLog LogDB -> 22 of 22 events successfully inserted into table history
2017.01.23 16:28:47.652 5: DbLog LogDB -> 22 of 22 events successfully updated in table current
2017.01.23 16:28:47.729 5: DbLog LogDB -> DbLog_PushAsync finished

Hallo Tedious,

die Meldung wird von deiner MySQL-DB (bzw. Treiber) übermittelt. Normalerweise läuft eine MySQL mit Autocommit on, also eingeschaltet. Wenn die Daten in die DB geschrieben werden sollen wird eine Transaktion gestart und dafür das Autocommit ausgeschaltet um nach (erfolgreichem) Abschluß des Inserts die Transaktion zu beenden. Dann wird Autocommit automatisch wieder eingeschaltet.
Die Meldung liest sich für mich so als dass deine DB es nicht zulässt das Autocommit wieder einzuschalten. Läuft die DB evtl. nicht mit dem Default Autocommit on ? Nur eine Vermutung ...
Vielleicht hilft ein Restart deines DB-Servers.

Grüße
Heiko

JoeALLb · 23 Januar 2017, 18:43:51

Zitat von: DS_Starter am 23 Januar 2017, 18:21:42
Hallo Joe,

ich vermute es hängt mit deiner speziellen DB-Konfiguration zusammen. Es werden ja bei dir viele Fehler produziert die wiederum, so wie ich gesehen habe, in der DB geloggt werden sollen. Ich denke du löst das Problem wenn du wieder auf dein IGNORE umstellst.

Hallo Heiko,
also verbose5 ist gar nicht so einfahc, hat jetzt in einer Stunde 1.5GB nur DbLog-Einträge geloggt....
da ich das System brauchte, hab ich dann kurz auf 2.9.2 zurückgestellt und da funktionierte es wieder zügig und schnell.. auch ohne ignore!
Werde aber nachher nochmal in die aktuelle das ignore mit einbauen und testen! Vielen Dank fürs mitdenken!!!

DS_Starter · 23 Januar 2017, 18:50:12

Hallo Joe,

das Logging der V2.10.4 entspricht übrigens der 2.10.5 die du in #413 schon erfolgreich getestet hast. Kann IMHO nur an der schon vermuteten Sache liegen. Aber excludeDevs auf dein DbLog-Device setzen ist auch keine schlechte Idee.

DS_Starter · 23 Januar 2017, 18:52:51

Hallo stromer-12,

ZitatIch habe jetzt mal mit der 2.10.4 und den timeout rumgespielt, ich habe den Timeout hochgeschraubt auf über eine Stunde und es hat geklappt.
Ich hatte die Datenbank ümorganisiert. Der erste Commit blieb im Hintergrund bestehen und der nächste schob sich immer weiter bis der Hintergrundtask beendet(abgeschlossen) wurde.

Das klingt gut. Dann hat es sich ja gelohnt den Timeout flexibel zu gestalten.

VG
Heiko