Guten Abend zusammen!
Ich habe aktuell das Problem, dass das UniFi-Modul mir eine Reihe von Freezes beschert (alle unter 2 Sekunden, also kein Weltuntergang, aber störend). Beim Durchsehen der freezelogs fallen eine Reihe von DbLog-Meldungen auf:
2021.11.01 21:55:19.392 4: DbLog DbLog -> ################################################################
2021.11.01 21:55:19.392 4: DbLog DbLog -> ### start of new Logcycle ###
2021.11.01 21:55:19.392 4: DbLog DbLog -> ################################################################
2021.11.01 21:55:19.392 4: DbLog DbLog -> number of events received: 34 of device: SW_Gartenhaus
2021.11.01 21:55:19.392 4: DbLog DbLog -> check Device: SW_Gartenhaus , Event: switch_sys_cpu: 56.1
2021.11.01 21:55:19.399 4: DbLog DbLog -> Device "SW_Gartenhaus" global excluded from logging by attribute "excludeDevs"
[...]
2021.11.01 21:55:19.685 4: DbLog DbLog -> check Device: SW_Gartenhaus , Event: port_08_poe_current: 67.13
2021.11.01 21:55:19.692 4: DbLog DbLog -> Device "SW_Gartenhaus" global excluded from logging by attribute "excludeDevs"
In diesem Logcycle hat DbLog nach meinem Verständnis also 300ms verbraucht - bei einem Gerät, bei dem DbLogInclude ungesetzt ist (DbSelectionMode=Include).
Habe ich irgendeine Möglichkeit, dieses Verhalten wegzuoptimieren? Kann ich trotz SelectionMode=Include in irgendeiner Weise erreichen, dass NOTIFYDEV gesetzt wird?
Mir ist natürlich bewusst, dass 300ms nicht die Welt sind, aber nötig wären sie vermutlich auch nicht.
Patrick
Nabend Patrick,
ZitatKann ich trotz SelectionMode=Include in irgendeiner Weise erreichen, dass NOTIFYDEV gesetzt wird?
Das würde gehen wenn du das Gerät im DEF mit angibst, auch wenn der Regex in DEF bei DbLogInclude bei der Auswertung nicht berücksichtigt wird (NOTIFYDEV wird dennoch gesetzt).
Allerdings bringt das ja nichts, denn die Events willst du ja haben.
Die 300ms kommen m.M. nach nur durch das Schreiben der Logmeldungen mit verbose 4 in das Logfile zustande.
Es werden 34 Events untersucht, das sind ca. 10 ms pro Event incl. Schreiben der Logmeldungen.
Wenn du die Durchlaufzeit der notify-Verarbeitungsschleife messen willst, setzt du dir einfach das Attr. showNotifyTime=1.
Dann wird das Reading notify_processing_time gesetzt. Dort siehst du wieviel Zeit DbLog bei jedem Logcycle verbraucht.
Bei mir bewegt sich diese Zeit zwischen 6 und 35ms pro Logcycle im asynchronen Mode.
Grüße,
Heiko
Hallo Heiko,
danke für die schnelle Antwort.
Zitat von: DS_Starter am 01 November 2021, 22:37:12
Das würde gehen wenn du das Gerät im DEF mit angibst, auch wenn der Regex in DEF bei DbLogInclude bei der Auswertung nicht berücksichtigt wird (NOTIFYDEV wird dennoch gesetzt).
Allerdings bringt das ja nichts, denn die Events willst du ja haben.
Leider nein. Trotz gesetzter Regex wird NOTIFYDEV nicht gesetzt, was ich mir an Hand Deines Quellcodes zugegebenermaßen auch nicht erklären kann. Auch mit einer einfacheren RegEx wird NOTIFYDEV nicht gesetzt.
List:
Internals:
COLUMNS field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
CONFIGURATION ./db.conf
DEF ./db.conf (?!(UniFi|UC_|SW_)).*:.*
FUUID 5c587c89-f33f-5676-a2ac-a89d57699811db41
FVERSION 93_DbLog.pm:v4.12.3-s24440/2021-05-15
MODE asynchronous
MODEL MYSQL
NAME DbLog
NR 17
NTFY_ORDER 50-DbLog
PID 30071
REGEXP (?!(UniFi|UC_|SW_)).*:.*
STATE connected (0 cached)
TYPE DbLog
UTF8 0
dbconn mysql:database=fhem;host=mariadb.prdom;port=3306
dbuser fhem
HELPER:
COLSET 1
DEVICECOL 64
EVENTCOL 512
OLDSTATE connected
PACKAGE main
READINGCOL 64
TC current
TH history
TYPECOL 64
UNITCOL 32
VALUECOL 128
VERSION 4.12.3
OLDREADINGS:
READINGS:
2021-11-01 23:02:43 CacheOverflowLastNum 0
2021-09-09 07:16:03 CacheOverflowLastState normal
2021-11-01 23:02:44 CacheUsage 0
2021-11-01 23:02:43 NextSync 2021-11-01 23:03:13 or if CacheUsage 500 reached
2021-11-01 23:02:44 state connected
helper:
bm:
DbLog_Define:
cnt 3
dmx -1000
dtot 0
dtotcnt 0
mTS 01.11. 22:56:38
max 0.172103881835938
tot 0.478095531463623
mAr:
HASH(0x5575b72708a8)
DbLog DbLog ./db.conf (?!(UniFi|UC_|SW_)).*:.*
DbLog_Get:
cnt 9
dmx -1000
dtot 0
dtotcnt 0
mTS 01.11. 22:56:06
max 0.000191926956176758
tot 0.000710248947143555
mAr:
HASH(0x5575b72708a8)
DbLog
?
DbLog_Log:
cnt 14392
dmx -1000
dtot 0
dtotcnt 0
mTS 01.11. 23:00:07
max 1.43560814857483
tot 338.499107599258
mAr:
HASH(0x5575b72708a8)
HASH(0x5575bf093570)
DbLog_Set:
cnt 28
dmx -1000
dtot 0
dtotcnt 0
mTS 01.11. 22:57:45
max 0.00264692306518555
tot 0.0616014003753662
mAr:
HASH(0x5575b72708a8)
DbLog
?
Attributes:
DbLogSelectionMode Include
DbLogType Current/History
asyncMode 1
cacheEvents 0
cacheLimit 500
event-on-change-reading .*
excludeDevs UniFi,UC_.*,SW_.*
icon icoLog.png
room System->Logging
stateFormat state (CacheUsage cached)
syncInterval 30
verbose 3
Zitat von: DS_Starter am 01 November 2021, 22:37:12
Die 300ms kommen m.M. nach nur durch das Schreiben der Logmeldungen mit verbose 4 in das Logfile zustande.
Es werden 34 Events untersucht, das sind ca. 10 ms pro Event incl. Schreiben der Logmeldungen.
Das müsste ich mir ansehen. Die Logs schreibt freezemon weg. In den "richtigen" Logs landet nur verbose 3. Freezemon sollte aber auch einen gewissen Overhead haben...
Zitat von: DS_Starter am 01 November 2021, 22:37:12
Wenn du die Durchlaufzeit der notify-Verarbeitungsschleife messen willst, setzt du dir einfach das Attr. showNotifyTime=1.
Dann wird das Reading notify_processing_time gesetzt. Dort siehst du wieviel Zeit DbLog bei jedem Logcycle verbraucht.
Bei mir bewegt sich diese Zeit zwischen 6 und 35ms pro Logcycle im asynchronen Mode.
Das schaue ich mir mal an.
Grüße
Patrick
ZitatLeider nein. Trotz gesetzter Regex wird NOTIFYDEV nicht gesetzt, was ich mir an Hand Deines Quellcodes zugegebenermaßen auch nicht erklären kann. Auch mit einer einfacheren RegEx wird NOTIFYDEV nicht gesetzt.
Rudi setzt in der Funktion notifyRegexpChanged das NOTIFYDEV ziemlich streng nach festgelegten Kriterien. Sind diese nicht erfüllt wird NOTIFYDEV nicht gesetzt.
Aber ich würde da jetzt nicht viel Energie drauf verwenden, weil wie gesagt die Events willst du ja haben.
Zitat von: DS_Starter am 01 November 2021, 23:14:02
Rudi setzt in der Funktion notifyRegexpChanged das NOTIFYDEV ziemlich streng nach festgelegten Kriterien. Sind diese nicht erfüllt wird NOTIFYDEV nicht gesetzt.
Aber ich würde da jetzt nicht viel Energie drauf verwenden, weil wie gesagt die Events willst du ja haben.
Ok, schaue ich mir an. Aber die Events will ich (für das DbLog-Device) nicht haben. DbLogInclude ist bei keinem der betroffenen Geräte gesetzt.
Patrick
Hi!
Habe mir mal notify_processing_time angesehen. Du hattest tatsächlich Recht. Die Laufzeiten sind so niedrig, dass es sich garnicht lohnt, noch weiter über die Optimierung von DbLog nachzudenken. Danke für Deine Hilfe!
Patrick