93_DbLog - Umstellung Log-Funktion auf non-blocking

Tobias · 06 Januar 2017, 14:32:38

ok, das ist ev. auch wichtig, meinte ich aber nicht. Ich meinte da NonBlocking Data-Get von DBLog. Holt man zb. ein JahresPlot raus, kann FHEM schonmal für mehrere Sekunden hängen bleiben... Und mit Plot meine ich ein Plot in TabletUI, nicht zwingend ein BuildIn SVG in FHEM pgm2

DS_Starter · 06 Januar 2017, 14:36:56

ah ... ok. Das ist genau die Vorgehensweise mit der ich im DbRep die Analysen der DB-Inhalte fahre. Das läuft dort genauso wie von dir gemeint.

EDIT: vielleicht kann man in der Get-Funktion eine Fallentscheidung einbauen um dieses Problem zu lösen ? Ich habe mich wie gesagt mit der Get-Funktion noch garnicht im Detail beschäftigt. Wenn du/ihr eine Idee habt ....

rudolfkoenig · 06 Januar 2017, 14:55:53

ZitatAlso zb. wenn TabletUI Daten für den eigenen Chart abzieht?

Das kenne ich nicht. Kannst du mich bitte aufklaeren, oder zeigen, wo ich was nachlesen kann?

JoeALLb · 06 Januar 2017, 15:03:03

Anbei einj Auszug aus meinem Verbose5 Log.
Diese Fehlermeldung verstehe ich, stimmt die Annahme dass dieser eine Eintrag dann schlicht NICHT in der DB eingefügt wurde, die anderen aus dem Cache jedoch schon?
So wäüre es ja korrekt! (Oder scheitert dann der komplette insert aller gecachten Daten?)

Code Auswählen

DbLog myDbLogSQL DBD::mysql::st execute_array failed: Duplicate entry 'myDbLogSQL-CacheUsage-2017-01-06 14:57:41' for key 'PRIMARY' [err was 1062 now 2000000000]

Aber häufig kommt eben auch diese Fehlermeldung, die ich nicht wirklich verstehe:

Code Auswählen

DbLog myDbLogSQL DBD::mysql::st execute_array failed: executing 7 generated 1 errors at ./FHEM/93_DbLog.pm line 1183.

@Heiko: Hast Du eine Idee, wie ich das genauer untersuchen kann?

Danke für die tolle Erweiterung!!!

Code Auswählen

DbLog myDbLogSQL NextSync: 2017-01-06 14:57:18
DbLog myDbLogSQL connected
DbLog myDbLogSQL CacheUsage: 2
DbLog myDbLogSQL connected
DbLog myDbLogSQL CacheUsage: 2
DbLog myDbLogSQL CacheUsage: 4
DbLog myDbLogSQL CacheUsage: 5
DbLog myDbLogSQL CacheUsage: 5
DbLog myDbLogSQL CacheUsage: 6
DbLog myDbLogSQL CacheUsage: 6
DbLog myDbLogSQL CacheUsage: 7
DbLog myDbLogSQL CacheUsage: 0
DbLog myDbLogSQL NextSync: 2017-01-06 14:57:28
DbLog myDbLogSQL connected
DbLog myDbLogSQL CacheUsage: 2
DbLog myDbLogSQL DBD::mysql::st execute_array failed: executing 7 generated 1 errors at ./FHEM/93_DbLog.pm line 1183.

DbLog myDbLogSQL CacheUsage: 3
DbLog myDbLogSQL CacheUsage: 4
DbLog myDbLogSQL CacheUsage: 5
DbLog myDbLogSQL CacheUsage: 6
DbLog myDbLogSQL CacheUsage: 7
DbLog myDbLogSQL CacheUsage: 9
DbLog myDbLogSQL CacheUsage: 10
DbLog myDbLogSQL CacheUsage: 13
DbLog myDbLogSQL CacheUsage: 14
DbLog myDbLogSQL CacheUsage: 15
DbLog myDbLogSQL CacheUsage: 16
DbLog myDbLogSQL CacheUsage: 19
DbLog myDbLogSQL CacheUsage: 20
DbLog myDbLogSQL CacheUsage: 21
DbLog myDbLogSQL CacheUsage: 22
DbLog myDbLogSQL CacheUsage: 23
DbLog myDbLogSQL CacheUsage: 24
DbLog myDbLogSQL CacheUsage: 25
DbLog myDbLogSQL CacheUsage: 26
DbLog myDbLogSQL CacheUsage: 27
DbLog myDbLogSQL CacheUsage: 28
DbLog myDbLogSQL CacheUsage: 29
DbLog myDbLogSQL CacheUsage: 30
DbLog myDbLogSQL CacheUsage: 31
DbLog myDbLogSQL CacheUsage: 32
DbLog myDbLogSQL CacheUsage: 32
DbLog myDbLogSQL CacheUsage: 33
DbLog myDbLogSQL CacheUsage: 35
DbLog myDbLogSQL CacheUsage: 36
DbLog myDbLogSQL CacheUsage: 0
DbLog myDbLogSQL NextSync: 2017-01-06 14:57:38
DbLog myDbLogSQL connected
DbLog myDbLogSQL CacheUsage: 2
DbLog myDbLogSQL DBD::mysql::st execute_array failed: executing 36 generated 11 errors at ./FHEM/93_DbLog.pm line 1183.

DbLog myDbLogSQL CacheUsage: 3
DbLog myDbLogSQL CacheUsage: 3
DbLog myDbLogSQL CacheUsage: 4
DbLog myDbLogSQL CacheUsage: 9
DbLog myDbLogSQL CacheUsage: 10
DbLog myDbLogSQL CacheUsage: 12
DbLog myDbLogSQL CacheUsage: 13
DbLog myDbLogSQL CacheUsage: 15
DbLog myDbLogSQL CacheUsage: 16
DbLog myDbLogSQL CacheUsage: 0
DbLog myDbLogSQL NextSync: 2017-01-06 14:57:51
DbLog myDbLogSQL connected
DbLog myDbLogSQL CacheUsage: 2
DbLog myDbLogSQL DBD::mysql::st execute_array failed: Duplicate entry 'myDbLogSQL-CacheUsage-2017-01-06 14:57:41' for key 'PRIMARY' [err was 1062 now 2000000000]
executing 16 generated 1 errors at ./FHEM/93_DbLog.pm line 1183.

DbLog myDbLogSQL CacheUsage: 2
DbLog myDbLogSQL CacheUsage: 2

Nachtrag: Ich habe bewußt einen PK in die Datenbank eingefügt, um doppelte Datensätze
zu vermeiden und Module, die diese erzeugen besser aufspüren zu können

Code Auswählen

PRIMARY KEY (`DEVICE`, `READING`, `TIMESTAMP`),

Tobias · 06 Januar 2017, 15:05:10

@rudi: https://github.com/knowthelist/fhem-tablet-ui

@DS_Starter, hab ich jetzt nicht verstanden, in DBRep machst du ein Non-Blocking? Rufst du da Funktionen von DBLog auf? Wenn ja, dann bleibt FHEM nicht hängen?
sorry für die Fragen, blick das nicht ganz...

DS_Starter · 06 Januar 2017, 15:15:32

Zitatin DBRep machst du ein Non-Blocking? Rufst du da Funktionen von DBLog auf?

Ich rufe die DB-Inhalte non-Blocking aus der DB ab. Aber ich verwende dafür eigene Funktionen im DbRep und greife dazu nicht ins DbLog.
Aber es ist die Technologie die du meintest.

DS_Starter · 06 Januar 2017, 15:22:33

Hallo Joe,

ZitatDbLog myDbLogSQL DBD::mysql::st execute_array failed: executing 7 generated 1 errors at ./FHEM/93_DbLog.pm line 1183.

Die Meldung wird direkt von dem DBI-interface bei dir generiert.

Mit verbose 5 müßtest du im Erfolgsfall im Log so etwas finden:

Code Auswählen

DbLog $name -> $rows of $ceti events successfully inserted into table history

oder aber

Code Auswählen

"DbLog $name -> Failed to insert into history: ......

Findest du dies ?

Grüße
Heiko

JoeALLb · 06 Januar 2017, 15:36:37

Hallo Heiko:

ich bekomme folgendes: daraus geht für mich nicht ganz hervor, ob nun alle datensätze aus dem cache eingefügt wurden und was nicht.
Aber folgender Vorschlag: Könnten wir "insert into" ändern in "insert ignore into"?
Dann würden die anderen (nicht doppelten) Datensätze immer eingefügt werden...

Code Auswählen

2017.01.06 14:57:28 5: DbLog myDbLogSQL -> DbLog_PushAsync finished
2017.01.06 14:57:28 5: DbLog myDbLogSQL -> Start DbLog_PushAsyncDone
2017.01.06 14:57:28 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:28 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:57:28 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:28 4: DbLog myDbLogSQL -> amount of events received: 1 for device: myDbLogSQL
2017.01.06 14:57:28 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: DBD::mysql::st execute_array failed: executing 36 generated 11 errors at ./FHEM/93_DbLog.pm line 1183.

2017.01.06 14:57:28 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:28, Device: myDbLogSQL, Type: DBLOG, Event: DBD::mysql::st execute_array failed: executing 36 generated 11 errors at ./FHEM/93_DbLog.pm line 1183.
, Reading: DBD::mysql::st execute_array failed, Value: executing 36 generated 11 errors at ./FHEM/93_DbLog.pm line 1183.
, Unit:
2017.01.06 14:57:28 5: DbLog myDbLogSQL -> DbLog_PushAsyncDone finished
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> amount of events received: 1 for device: HMLAN1
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> check Device: HMLAN1 , Event: loadLvl: low
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> amount of events received: 1 for device: myDbLogSQL
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: CacheUsage: 3
2017.01.06 14:57:33 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:33, Device: myDbLogSQL, Type: DBLOG, Event: CacheUsage: 3, Reading: CacheUsage, Value: 3, Unit:
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> amount of events received: 5 for device: CO20
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> check Device: CO20 , Event: voc: 1028
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:35, Device: CO20, Type: CO20, Event: voc: 1028, Reading: voc, Value: 1028, Unit:
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> check Device: CO20 , Event: debug: 776
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:35, Device: CO20, Type: CO20, Event: debug: 776, Reading: debug, Value: 776, Unit:
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> check Device: CO20 , Event: pwm: 386
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:35, Device: CO20, Type: CO20, Event: pwm: 386, Reading: pwm, Value: 386, Unit:
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> check Device: CO20 , Event: r_h: 153.29
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:35, Device: CO20, Type: CO20, Event: r_h: 153.29, Reading: r_h, Value: 153.29, Unit:
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> check Device: CO20 , Event: r_s: 192516
2017.01.06 14:57:35 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:57:35, Device: CO20, Type: CO20, Event: r_s: 192516, Reading: r_s, Value: 192516, Unit:

Noch ein Gedanke:
Sollte nicht beim löschen des attributs "assync" ebenfalls der cach in die db geschrieben werden?
bei mir blieben dabei Datensätze zurück im Memcache.

sG Joe

DS_Starter · 06 Januar 2017, 17:09:21

Hallo Joe,

Zitatdaraus geht für mich nicht ganz hervor, ob nun alle datensätze aus dem cache eingefügt wurden und was nicht.

Für mich auch nicht.

Der Logauszug ist auch nicht der richtige bzw. ausschlaggbebende. Schau mal bitte in deinem Logfile nach der verbose 5 Passage die so aussieht:

Code Auswählen


2017.01.06 16:54:39.560 5: DbLog LogDB -> ################################################################
2017.01.06 16:54:39.561 5: DbLog LogDB -> ###              New database processing cycle               ###
2017.01.06 16:54:39.561 5: DbLog LogDB -> ################################################################
2017.01.06 16:54:39.561 5: DbLog LogDB -> MemCache contains 22 entries to process
2017.01.06 16:54:39.561 5: DbLog LogDB -> MemCache contains: 2017-01-06 16:53:32|sysmon|SYSMON|loadavg: 0.07 0.05 0.05|loadavg|0.07 0.05 0.05|
2017.01.06 16:54:39.561 5: DbLog LogDB -> MemCache contains: 2017-01-06 16:53:32|sysmon|SYSMON|eth0_diff: RX: 0.34 MB, TX: 0.07 MB, Total: 0.41 MB|eth0_diff|RX: 0.34 MB, TX: 0.07 MB, Total: 0.41 MB|
2017.01.06 16:54:39.561 5: DbLog LogDB -> MemCache contains: 2017-01-06 16:53:32|sysmon|SYSMON|stat_cpu_percent: 1.51 0.00 0.61 97.11 0.57 0.00 0.20|stat_cpu_percent|1.51 0.00 0.61 97.11 0.57 0.00 0.20|
.........
.........
2017.01.06 16:54:39.574 5: DbLog LogDB -> DbLog_PushAsync called with timeout: 60
2017.01.06 16:54:39.579 5: DbLog LogDB -> Start DbLog_PushAsync
2017.01.06 16:54:39.586 5: DbLog LogDB -> processing event Timestamp: 2017-01-06 16:53:32, Device: sysmon, Type: SYSMON, Event: loadavg: 0.07 0.05 0.05, Reading: loadavg, Value: 0.07 0.05 0.05, Unit: 
2017.01.06 16:54:39.586 5: DbLog LogDB -> processing event Timestamp: 2017-01-06 16:53:32, Device: sysmon, Type: SYSMON, Event: eth0_diff: RX: 0.34 MB, TX: 0.07 MB, Total: 0.41 MB, Reading: eth0_diff, Value: RX: 0.34 MB, TX: 0.07 MB, Total: 0.41 MB, Unit: 
2017.01.06 16:54:39.586 5: DbLog LogDB -> processing event Timestamp: 2017-01-06 16:53:32, Device: sysmon, Type: SYSMON, Event: stat_cpu_percent: 1.51 0.00 0.61 97.11 0.57 0.00 0.20, Reading: stat_cpu_percent, Value: 1.51 0.00 0.61 97.11 0.57 0.00 0.20, Unit: 
2017.01.06 16:54:39.586 5: DbLog LogDB -> processing event Timestamp: 2017-01-06 16:53:32, Device: sysmon, Type: SYSMON, Event: ram: Total: 876.27 MB, Used: 591.86 MB, 67.54 %, Free: 284.40 MB, Reading: ram, Value: Total: 876.27 MB, Used: 591.86 MB, 67.54 %, Free: 284.40 MB, Unit: 
2017.01.06 16:54:39.586 5: DbLog LogDB -> processing event Timestamp: 2017-01-06 16:53:32, Device: sysmon, Type: SYSMON, Event: swap: Total: 1293.00 MB, Used: 46.71 MB,  3.61 %, Free: 1246.28 MB, Reading: swap, Value: Total: 1293.00 MB, Used: 46.71 MB,  3.61 %, Free: 1246.28 MB,

Also der Beginn des asynchronen DB-Inserts wird mit dem Header "New database processing cycle" im Log gekennzeichnet. Deine "start of new Logcycle" - Einträge rühren von der Notify-Funktion her, sind auch verbose 4. Die relevanten Einträge müßten also weiter unten kommen. Wenn dir die Ausgabe durch die Logcycle-Einträge mit verbose 4 dein Log zu unübersichtlich macht, kannst du mit dem attr "verbose4Devs" nur auf ein Device beschränken. Dann funken dir die "start of new Logcycle" - Einträge nicht mehr dazwischen.

ZitatKönnten wir "insert into" ändern in "insert ignore into"?

Probieren wir im nächsten Entwicklungsschritt mit aus.

ZitatSollte nicht beim löschen des attributs "assync" ebenfalls der cach in die db geschrieben werden?

Ja, klappt bei mir auch einwandfrei. Das schauen wir uns noch genauer an wenn dein anderes Problem genügend analysiert ist.

Grüße
Heiko

JoeALLb · 06 Januar 2017, 17:21:31

Hallo Heiko,

sorry, ich denke, das ist jetzt das korrekte Log:

Code Auswählen

2017.01.06 14:56:50 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> amount of events received: 9 for device: temp.wz.innen
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: battery: low
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: humidity: 34
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: T: 22.4 H: 34
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: temperature: 22.4
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: batteryCopy: ok
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: dew: 5.78
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: dd: 921.0
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: af: 6.8
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: temp.wz.innen , Event: empfehlung: LÃ¼ften nicht notwendig
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> amount of events received: 1 for device: myDbLogSQL
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: CacheUsage: 3
2017.01.06 14:56:50 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:56:50, Device: myDbLogSQL, Type: DBLOG, Event: CacheUsage: 3, Reading: CacheUsage, Value: 3, Unit:
2017.01.06 14:56:50 3:  Batteriewarnung %
2017.01.06 14:56:50 3:  Batteriewarnung %
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> ###              New database processing cycle               ###
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains 4 entries to process
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:48|myDbLogSQL|DBLOG|CacheUsage: 0|CacheUsage|0|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:48|myDbLogSQL|DBLOG|NextSync: 2017-01-06 14:56:58|NextSync|2017-01-06 14:56:58|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:48|myDbLogSQL|DBLOG|DBD::mysql::st execute_array failed: executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
|DBD::mysql::st execute_array failed|executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:50|myDbLogSQL|DBLOG|CacheUsage: 3|CacheUsage|3|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> DbLog_PushAsync called with timeout: 60
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> Start DbLog_PushAsync
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-06 14:56:48, Device: myDbLogSQL, Type: DBLOG, Event: CacheUsage: 0, Reading: CacheUsage, Value: 0, Unit:
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-06 14:56:48, Device: myDbLogSQL, Type: DBLOG, Event: NextSync: 2017-01-06 14:56:58, Reading: NextSync, Value: 2017-01-06 14:56:58, Unit:
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-06 14:56:48, Device: myDbLogSQL, Type: DBLOG, Event: DBD::mysql::st execute_array failed: executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
, Reading: DBD::mysql::st execute_array failed, Value: executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
, Unit:
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> processing event Timestamp: 2017-01-06 14:56:50, Device: myDbLogSQL, Type: DBLOG, Event: CacheUsage: 3, Reading: CacheUsage, Value: 3, Unit:
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> amount of events received: 3 for device: myDbLogSQL
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: CacheUsage: 0
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:56:58, Device: myDbLogSQL, Type: DBLOG, Event: CacheUsage: 0, Reading: CacheUsage, Value: 0, Unit:
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: NextSync: 2017-01-06 14:57:08
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> added event to memcache - Timestamp: 2017-01-06 14:56:58, Device: myDbLogSQL, Type: DBLOG, Event: NextSync: 2017-01-06 14:57:08, Reading: NextSync, Value: 2017-01-06 14:57:08, Unit:
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: connected
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> 4 of 4 events successfully inserted into table history
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> DbLog_PushAsync finished
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> Start DbLog_PushAsyncDone
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> ###              start of new Logcycle                       ###
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> amount of events received: 1 for device: myDbLogSQL
2017.01.06 14:56:58 4: DbLog myDbLogSQL -> check Device: myDbLogSQL , Event: connected
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> DbLog_PushAsyncDone finished

DS_Starter · 06 Januar 2017, 17:44:38

Hi Joe,

genau das ist es. Hier siehst du auch genau die Ergebnisse.
Der Hintergrundprozess startet mit

Code Auswählen


2017.01.06 14:56:58 5: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> ###              New database processing cycle               ###
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> ################################################################
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains 4 entries to process

Es sind 4 Einträge in die DB zu bringen. Danach wird aufgezählt welche das sind:

Code Auswählen


2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:48|myDbLogSQL|DBLOG|CacheUsage: 0|CacheUsage|0|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:48|myDbLogSQL|DBLOG|NextSync: 2017-01-06 14:56:58|NextSync|2017-01-06 14:56:58|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:48|myDbLogSQL|DBLOG|
DBD::mysql::st execute_array failed: executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
|DBD::mysql::st execute_array failed|executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
|
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> MemCache contains: 2017-01-06 14:56:50|myDbLogSQL|DBLOG|CacheUsage: 3|CacheUsage|3|

In dem Fall ist der Eintrag "2017-01-06 14:56:48|myDbLogSQL|DBLOG|DBD::mysql::st execute_array failed: executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
|DBD::mysql::st execute_array failed|executing 9 generated 2 errors at ./FHEM/93_DbLog.pm line 1183.
|" allerdings ein Event der in die DB geschrieben werden soll !! und kein Fehler an sich.

Wahrscheinlich loggst du bei dir jedes Device mit der Konfiguration ".*:.*". Wenn das so ist/sein soll würde ich aber an deiner Stelle das Device "myDbLogSQL" über das Attribut "excludeDevs" ausschließen.

Weiter unten siehst du dass alle 4 Events in die DB geschrieben wurden.

Code Auswählen


2017.01.06 14:56:58 5: DbLog myDbLogSQL -> 4 of 4 events successfully inserted into table history
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> DbLog_PushAsync finished
2017.01.06 14:56:58 5: DbLog myDbLogSQL -> Start DbLog_PushAsyncDone

Wenn ein Insert nicht gemacht werden konnte würde ich im Log ausschreiben "DbLog $name ->Failed to insert into history: <Device>, <Event>".
Also in dem Beispiel ist alles gut.

Wenn du tatsächlich mal auf den Fehler "DBD::mysql::st execute_array failed:" läufst müßte man das genauso analysieren ob nur der eine Event nicht in die DB kommt oder der Block. Vielleicht kannst du es provozieren. Ganz gemein wäre natürlich wenn dein DBI-Modul an der Stelle einfach die Arbeit einstellt. Dann gäbe es nichts auszuwerten. Aber das muß man sehen.

Kommst du damit klar ?

Grüße
Heiko

JoeALLb · 06 Januar 2017, 18:12:02

Hallo Heiko,

vielen Dank, das hätte ich da nicht alles rauslesen können....

Wenn ich mit myDbLogSQL mit "excludeDevs" ausnehme, bekomme ich die Fehlermeldung nicht.
Dennoch wunderts mich... woher diese Fehlermeldung kommt. Bisher hatte ich beim Device myDbLogSQL einfach mit "DbLogExclude" einzelne Readings ausgenommen.
manchmal steht da

Code Auswählen

executing 9 generated 2 errors
ein anderes mal

Code Auswählen

executing 21 generated 3 errors

Also scheint die Meldung zumindest nicht statisch zu sein...

Ich lasse es nun weiter mit async laufen und werde morgen sehen, was alles in die Logdatei geschrieben wurde.

Noch eine Rückfrage: Ist es ganz korrekt, dass hier die Meldung "myDbLogSQL excluded from database ..." 2x kommt? Wird hier der Ausschluss 2x berechnet?

Code Auswählen

2017.01.06 18:03:30 4: DbLog myDbLogSQL -> Device: myDbLogSQL excluded from database logging due to attribute "excludeDevs" restrictions
2017.01.06 18:03:30 5: DbLog myDbLogSQL -> Start DbLog_PushAsyncDone
2017.01.06 18:03:30 4: DbLog myDbLogSQL -> Device: myDbLogSQL excluded from database logging due to attribute "excludeDevs" restrictions
2017.01.06 18:03:30 5: DbLog myDbLogSQL -> DbLog_PushAsyncDone finished

DS_Starter · 06 Januar 2017, 18:33:35

Hi Joe,

ZitatDennoch wunderts mich... woher diese Fehlermeldung kommt.

Mit den Ausschriften "executing 9 generated 2 errors" oder "executing 21 generated 3 errors" kann ich ehrlich gesagt auch nichts anfangen. Sie sind mir auch bis jetzt nicht begegnet. Vielleicht mal die Suchfunktion im Browser bemühen. Möglicherweise sind diese Meldungen von der DB-Version abhängig.
Aber mit ziemlicher Sicherheit ist es eine Meldung deines Perl DBI-Interface weil ich in Zeile 1183 den execute_array-Aufruf starte. Die Auswertungen und Ausschriften die ich über das Modul ausgebe, kommen aber erst später.

ZitatNoch eine Rückfrage: Ist es ganz korrekt, dass hier die Meldung "myDbLogSQL excluded from database ..." 2x kommt? Wird hier der Ausschluss 2x berechnet?

Die Meldung ist soweit ok. Aber sie bezieht sich auf zwei unterschiedliche Events die über die Notify-Funktion hereinkommen und bewertet werden, ist also nicht doppelt berechnet/ausgegeben. Die Meldung soll den Nutzer lediglich daran erinnern dass er dieses Device vom Logging ausgeschlossen hat wenn er Analysen mit verbose4/5 tätigt.

Schauen wir morgen mal weiter ...

Schönen Abend !

Grüße,
Heiko

Pyromane · 06 Januar 2017, 21:38:27

Guten Abend!

Möchte ich ein SVG von einem Device erstellen, das nachdem ich die DbLog eingespielt habe erstellt wurde, so finde ich es nicht in der Auswahlliste/Dropdown.
Schreibe ich die Devices händisch in die *.plot Datei werden die SVG Plots erstellt.

Ich verwende die Version 2.8.2 unter PostgreSQL.

Tante EDIT sagt:
Ich kann keinen Eintrag für die neuen Devices in der current Tabelle entdecken können.

DS_Starter · 06 Januar 2017, 22:43:48

Hallo Pyromane,

Du mußt das Attribut DbLogType explizit auf "Current" bzw. "History/Current" setzen um die Current-Tabelle zu benutzen.

VG