DbLog: Optimierung

Begonnen von PatrickR, 01 November 2021, 22:11:09

Vorheriges Thema - Nächstes Thema

PatrickR

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
lepresenced - Tracking von Bluetooth-LE-Tags (Gigaset G-Tag) mittels PRESENCE

"Programming today is a race between software engineers striving to build bigger and better idiot-proof programs, and the universe trying to produce bigger and better idiots. So far, the universe is winning." - Rich Cook

DS_Starter

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
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

PatrickR

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
lepresenced - Tracking von Bluetooth-LE-Tags (Gigaset G-Tag) mittels PRESENCE

"Programming today is a race between software engineers striving to build bigger and better idiot-proof programs, and the universe trying to produce bigger and better idiots. So far, the universe is winning." - Rich Cook

DS_Starter

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.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

PatrickR

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
lepresenced - Tracking von Bluetooth-LE-Tags (Gigaset G-Tag) mittels PRESENCE

"Programming today is a race between software engineers striving to build bigger and better idiot-proof programs, and the universe trying to produce bigger and better idiots. So far, the universe is winning." - Rich Cook

PatrickR

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
lepresenced - Tracking von Bluetooth-LE-Tags (Gigaset G-Tag) mittels PRESENCE

"Programming today is a race between software engineers striving to build bigger and better idiot-proof programs, and the universe trying to produce bigger and better idiots. So far, the universe is winning." - Rich Cook