DbLog - Umstellung Betrieb auf SubProcess -> Tester gesucht

Begonnen von DS_Starter, 29 November 2022, 12:54:25

Vorheriges Thema - Nächstes Thema

erwin

... läuft unauffällig,

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
15083 fhem      20   0   53348  35096   5128 S   8.9  3.7   7:46.51 perl # "vorgeschummelte" instanz
15088 fhem      20   0   92544  58624   5216 S   8.9  6.2   7:44.97 perl # instanz NR=92
15082 fhem      20   0  121136  93440  12268 S   3.3  9.9   7:58.75 perl # main

ich denke, damit sind die Möglichkeiten einer "abwärtskompatiblen" Lösung ausgereizt.... ;D
in apptime sehe ich noch relativ lange Zeiten (im main thread) für:  tmr-DbLog_execmemcache, ich denke speziell das eval (in DbLog_Log) schlägt hier zu....
das zu transformieren ohne die Kompatibilität zu verlieren kann ich mir nicht wirklich vorstellen!
Danke nochmals für deine Energie!
l.g. erwin   
FHEM aktuell auf RaspberryPI Mdl 1-4
Maintainer: 00_KNXIO.pm 10_KNX.pm
User: CUNO2 (868 SLOWRF) - HMS100xx, FS20, FHT, 1-Wire  - 2401(iButton), 18x20, 2406, 2413 (AVR), 2450,..,MQTT2, KNX, SONOFF, mySENSORS,....
Hardware:  Busware ROT, Weinzierl IP731, 1-Wire GW,...

DS_Starter

#31
Moin erwin,

Zitat
Danke nochmals für deine Energie!
Gerne  :)

Wenn tmr-DbLog_execmemcache rel. hohe Zeiten in apptime anzeigt liegt es meiner Meinung nach vermutlich an einer entsprechend hohen Anzahl von zu verarbeitenden Datensätzen im Memory Cache. In der Funktion, die unabhängig von der (Notify) Log-Funktion arbeitet, werden die gecachten Daten seriell verpackt und  an den Child Prozess gesendet.

Die Zeit, die in der Notify-Funktion (DbLog_Log) für einen Zyklus verbraucht wird,  kann man sich mit dem Attr showNotifyTime = 1 reporten lassen -> Reading notify_processing_time.

Inzwischen bin ich soweit auch den synchronen Log-Vorgang non-blocking über den SubProcess abwickeln zu können.
Ich teste diese Weiterentwicklung noch. Wenn ich soweit bin stelle ich euch die Version wieder im contrib zur Verfügung und beschreibe in der Hilfe auch genauer die jeweiligen Vorteile/Nachteile der jweilige asyncMode-Einstellungen.
Vermutlich sollte ich das Attr  asyncMode nun besser in operationMode umbenennen. Das kann ich ja für den User unschädlich im Code vornehmen.


Zum Thema {NR} Sortierung ...
Möglicherweise hat Rudi Lust und auch eine Idee die Nutzung von SubProcess global in der fhem.pl mit einer entsprechenden Sortierung zu unterstützen.  ;)
Beta-User hatte weiter vorn eine Art "high prio"-Flag ins Spiel gebracht.
Die Idee gefällt mir gut, weil es ja auch weitere Module gibt die SubProcess nutzen und im Prinzip vor der gleichen Problematik stehen sofern sie den SP nicht ständig starten und beenden.
Dadurch geht zwar ein bisschen die "Exklusivität" für DbLog verloren, aber das wäre vermutlich die sauberste weil zentrale Lösung für diese Sache.

LG,
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

rudolfkoenig

ZitatMöglicherweise hat Rudi Lust und auch eine Idee die Nutzung von SubProcess global in der fhem.pl mit einer entsprechenden Sortierung zu unterstützen.  ;)
Ich habe schon zwei Versuche hinter mir, beide waren problematisch.
Haken an dem high Prio Flag ist, dass configDB auch angepasst werden muss.
Haken an der Umnummerierung ist, dass NR von einigen Modulen verwendet wird, d.h. das ist nur mit anschliessenden save+restart machbar.

DS_Starter

Danke Rudi schonmal für das Aufgreifen eines solchen Ansatzes !  8)

Ich weiß nicht wie groß eine etwaige Anpassung in configDB wäre und wie betateilchen dazu steht.
Aber ich könnte mir vorstellen dass ein genereller Support für SubProcess unter den behandelten Gesichtspunkten
sinnvoll ist.
Es geht ja nicht nur um den jetzigen Einsatzfall.
Es gibt ja weitere Module, die SubProcess einsetzen und vllt. werden es ja noch mehr.



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

erwin

Idee zum Thema HiPrio-Flag...

Nachdem ja "Lücken" in den NR's grundsätzlich erlaubt sind..., folgende idee:
Während CommandDefine einen niederen Bereich NR's für "spezielle" - explizit definerte Module freilassen - und alle übrigen Module z.B. ab 30 numerieren.
Das würde für bestehende defs beim nächsten start schlagend werden, für neue defs zur runtime!
Es braucht dann kein neues Flag, und alle bisherigen Module bleiben unberührt....
l.g. erwin
FHEM aktuell auf RaspberryPI Mdl 1-4
Maintainer: 00_KNXIO.pm 10_KNX.pm
User: CUNO2 (868 SLOWRF) - HMS100xx, FS20, FHT, 1-Wire  - 2401(iButton), 18x20, 2406, 2413 (AVR), 2450,..,MQTT2, KNX, SONOFF, mySENSORS,....
Hardware:  Busware ROT, Weinzierl IP731, 1-Wire GW,...

Beta-User

Na ja, wahrscheinlich bräuchte man gar nicht so viele Nummern, wenn man das beschränkt auf die Zeit nach $init_done (für bestehende Installationen dann: defmod, und die Instanz wandert nach vorne?).
Den Prio-Flag könnte man  direkt in "Initialize" setzen => nicht für den User sichtbar, aber zur define-Time schon bekannt?.

Beim Speichern/Neustart wird dann die nach vorne geholte Instanz "NR 31", und es wäre wieder Platz "vorne".
Server: HP-elitedesk@Debian 12, aktuelles FHEM@ConfigDB | CUL_HM (VCCU) | MQTT2: MiLight@ESP-GW, BT@OpenMQTTGw | MySensors: seriell, v.a. 2.3.1@RS485 | ZWave | ZigBee@deCONZ | SIGNALduino | MapleCUN | RHASSPY
svn: u.a MySensors, Weekday-&RandomTimer, Twilight,  div. attrTemplate-files

DS_Starter

#36
In meinem contrib liegt die V 5.1.0.
Nun ist das Logging im synchronen Mode ebenfalls non-blocking über den SubProcess realisiert.

Ich habe die Hilfe zum Attr asyncMode ausgebaut. Der User sollte damit nun genau einschätzen können welcher Modus für seinen Einsatzzweck der richtige ist. Hier ein Auszug. Wenn ihr noch Ergänzung haben solltet nehme ich sie gerne entgegen.

asyncMode

    attr <device> asyncMode [0|1]

    Dieses Attribut stellt den Verarbeitungsprozess ein nach dessen Verfahren das DbLog Device die Daten in die Datenbank schreibt.
    DbLog verwendet zum Schreiben der Log-Daten in die Datenbank einen SubProzess.
    Dadurch erfolgt der Schreibprozess in die Datenbank generell nicht blockierend und FHEM wird im dem Fall,
    dass die Datenbank nicht performant arbeitet oder nicht verfügbar ist (Wartung, Fehlerzustand), nicht beeinträchtigt.
    (default: 0)

        0 -    Synchroner Log-Modus. Die zu loggenden Daten werden sofort nach dem Empfang in die Datenbank geschrieben.
           Vorteile:
           Die Daten stehen im Prinzip sofort in der Datenbank zur Verfügung.
           Bei einem Absturz von FHEM gehen sehr wenige bis keine Daten verloren.
           Nachteile:
           Die Daten werden nicht zwischengespeichert und gehen verloren wenn die Datenbank nicht verfügbar ist
           oder fehlerhaft arbeitet. Eine alternative Speicherung im Filesystem wird nicht unterstützt.
           
           
        1 -    Asynchroner Log-Modus. Die zu loggenden Daten werden zunächst in einem Memory Cache zwischengespeichert
           und abhängig von einem Zeitintervall bzw. Füllgrad des Caches in die Datenbank geschrieben.
           Vorteile:
           Die Daten werden zwischengespeichert und gehen nicht verloren wenn die Datenbank nicht verfügbar ist
           oder fehlerhaft arbeitet. Die alternative Speicherung im Filesystem wird unterstützt.
           Nachteile:
           Die Daten stehen zeitlich verzögert in der Datenbank zur Verfügung.
           Bei einem Absturz von FHEM gehen alle im Memory zwischengespeicherten Daten verloren.


LG
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

rudolfkoenig

ZitatWährend CommandDefine einen niederen Bereich NR's für "spezielle" - explizit definerte Module freilassen - und alle übrigen Module z.B. ab 30 numerieren.

Das habe ich jetzt implementiert und eingecheckt.
D.h. global kriegt weiterhin NR=1, alle anderen ab 30, es sei denn, InitilizeFn setzt im Modul-Hash prioSave=1.
Diese Definitionen kriegen die Nummer 2 bis 29.

DS_Starter

Danke Rudi.

Bin grad unterwegs. Wenn ich wieder zu Hause bin, werde ich das Feature ins Modul einbauen und testen.
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

erwin

@Rudi:
Danke, das funktioniert bestens!
@Heiko:
das reading CacheUsage benimmt sich komisch:- eventmonitor:

2022-12-04 13:26:16.132 DbLog myDbLog CacheUsage: 60
2022-12-04 13:26:16.132 DbLog myDbLog CacheUsage: 0
2022-12-04 13:26:16.162 DbLog myDbLog CacheOverflowLastNum: 0
2022-12-04 13:26:16.162 DbLog myDbLog CacheUsage: 0
2022-12-04 13:26:16.302 DbLog myDbLog background_processing_time: 0.1021
2022-12-04 13:26:16.302 DbLog myDbLog sql_processing_time: 0.0814
2022-12-04 13:26:16.302 DbLog myDbLog CacheUsage: 0

Damit sieht das für den User so aus, als ob nichts geloggt wird...

.. ich hab Rudi's Implementation probehalber im DbLog_Init eingebaut... nach einem save - shutdown - restart sind bede DbLog Instanzen ganz vorne!

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
6719 fhem      20   0   46912  29052   5152 S   9.2  3.1   1:54.50 perl
6720 fhem      20   0   46912  29004   5152 S   9.2  3.1   1:54.07 perl
6718 fhem      20   0  118844  91328  12484 S   6.9  9.6   4:14.75 perl
FHEM aktuell auf RaspberryPI Mdl 1-4
Maintainer: 00_KNXIO.pm 10_KNX.pm
User: CUNO2 (868 SLOWRF) - HMS100xx, FS20, FHT, 1-Wire  - 2401(iButton), 18x20, 2406, 2413 (AVR), 2450,..,MQTT2, KNX, SONOFF, mySENSORS,....
Hardware:  Busware ROT, Weinzierl IP731, 1-Wire GW,...

DS_Starter

Hallo zusammen,

habe das Prio Flag jetzt in DbLog eingebaut und getestet ... funktioniert auch bei mir bestens.

Neben dieser Änderung sind noch einige mehr Code-Änderungen eingeflossen  und ich habe auch begonnen Teile der CommandRef
auf die neue Architektur anzupassen.

Ich habe auch begonnen die SetFn umzubauen und muss nun noch schauen wie kompatibel die übrigen Kommandos (importCachefile,
reduceLog, etc.) sind bzw. sie kompatibel machen.

Neue Version liegt im contrib.

LG
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

erwin

Hallo Heiko,

ein kleines Problem ist aufgetaucht:
PERL WARNING: Use of uninitialized value $memcount in numeric ge (>=) at ./FHEM/93_DbLog.pm line 1632.
kommt ständig, offensichtlich dann, wenn es nichts zu loggen gibt. (war auch in der gestrigen version so, hab das gestern schon gepatcht gleichzeitig mit prioflag - und dann vergessen zu erwähnen...)
fix: im attachment.
Das prio-Flag funkt bestens, das hab ich gestern schon geschrieben.
Das Problem mit cacheUsage ist noch da!
ich verwende attr cacheEvents 2
l.g.erwin
FHEM aktuell auf RaspberryPI Mdl 1-4
Maintainer: 00_KNXIO.pm 10_KNX.pm
User: CUNO2 (868 SLOWRF) - HMS100xx, FS20, FHT, 1-Wire  - 2401(iButton), 18x20, 2406, 2413 (AVR), 2450,..,MQTT2, KNX, SONOFF, mySENSORS,....
Hardware:  Busware ROT, Weinzierl IP731, 1-Wire GW,...

DS_Starter

Moin erwin,

$memcount hatte ich auch gesehen und die Warnung kommt bei mir aktuell nicht mehr.

Bzgl. cacheUsage  schaue ich nochmal.

Weil ich inzwischen noch etwas weitergemacht hatte ... kannst du bitte nochmal aus dem contrib laden ?
Sonst komme ich mit den Zeilennummern im Patch nicht mehr klar...
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

Frank_Huber

kurze Rückmeldung. 5.2 läuft jetzt auch bei mir auf Zwei Instanzen. Nach dem ersten Reboot alles weiterhin Problemlos.
Hab das define noch dazu ganz nach vorne geholt in der cfg.


SusisStrolch

Welches sind denn die Rahmenbedingungen für die 5.x Version?
Umgebung:
  FHEM Update am 5.12.2022 durchgeführt
  fhem.pl:26635/2022-11-01

Mein logdb Device:
Internals:
   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
   CONFIGURATION ./contrib/dblog/MariaDB10.conf
   DEF        ./contrib/dblog/MariaDB10.conf .*:.*
   FUUID      5e0e63f1-f33f-6054-f97a-82f8e05ae3c5c61b
   FVERSION   93_DbLog.pm:v4.13.3-s26750/2022-11-26
   MODE       asynchronous
   MODEL      MYSQL
   NAME       logdb
   NR         6
   NTFY_ORDER 50-logdb
   PID        18098
   REGEXP     .*:.*
   STATE      connected
   TYPE       DbLog
   UTF8       1
   dbconn     mysql:database=fhem;host=192.168.254.20;port=3307
   dbuser     fhem
   eventCount 26
   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.13.3
   READINGS:
     2022-12-05 11:55:16   CacheOverflowLastNum 0
     2022-12-03 15:42:58   CacheOverflowLastState normal
     2022-12-05 11:55:23   CacheUsage      7
     2022-12-05 11:55:16   NextSync        2022-12-05 11:55:46 or if CacheUsage 500 reached
     2022-12-05 11:55:17   background_processing_time 0.5536
     2022-12-04 15:59:56   lastCachefile   ./log/cache_logdb_2022-12-02_07-20-22 import successful
     2022-12-05 11:55:23   notify_processing_time 0.0022
     2022-12-05 11:55:17   sql_processing_time 0.4971
     2022-12-05 11:55:17   state           connected
Attributes:
   DbLogExclude .*
   DbLogSelectionMode Exclude/Include
   DbLogType  Current/History
   asyncMode  1
   bulkInsert 0
   cacheEvents 2
   cacheOverflowThreshold 750
   colEvent   512
   colReading 64
   colValue   128
   disable    0
   event-on-change-reading CacheUsage,background_processing_time
   icon       security
   room       DbLog
   showNotifyTime 1
   showproctime 1
   timeout    86400
   verbose    3



  • FHEM via "systemctl stop fhem.service" gestoppt
  • FHEM/93_DbLog.pm gesicher
  • FHEM/93_DbLog.pm durch den Download ersetzt
  • FHEM via "systemctl start fhem.service" gestartet

Im FHEM-Log finde ich dann folgende Fehlermeldungen:
2022.12.05 11:32:50.070 1: PERL WARNING: Use of uninitialized value $memcount in numeric ge (>=) at ./FHEM/93_DbLog.pm line 1653.
2022.12.05 11:32:50.070 1: stacktrace:
2022.12.05 11:32:50.071 1:     main::__ANON__                      called by ./FHEM/93_DbLog.pm (1653)
2022.12.05 11:32:50.071 1:     main::DbLog_Log                     called by fhem.pl (3972)
2022.12.05 11:32:50.071 1:     main::CallFn                        called by fhem.pl (3884)
2022.12.05 11:32:50.071 1:     main::DoTrigger                     called by fhem.pl (4269)
2022.12.05 11:32:50.072 1:     main::Dispatch                      called by ./FHEM/00_MQTT2_SERVER.pm (580)
2022.12.05 11:32:50.072 1:     main::MQTT2_SERVER_doPublish        called by ./FHEM/00_MQTT2_SERVER.pm (460)
2022.12.05 11:32:50.072 1:     main::MQTT2_SERVER_Read             called by fhem.pl (3972)
2022.12.05 11:32:50.072 1:     main::CallFn                        called by fhem.pl (782)


Any ideas?
Synology DS1515+, 16GB RAM, 4x 6TB WD-Red
- Docker (FHEM), MariaDB, MariaDB10, Surveillance Station
Gateways: LCG miniCUL433, LCG miniCUL868, AVR-X4000, VU-Solo SE, Kodi
ESP8266: ESPEasy (S0-Counter, Temp/Hum), Sonoff TH, Sonoff 4ch