Hallo zusammen,
ich suche bereits geraume Zeit nach Modulen, die zu einer Verzögerung im FHEM beitragen.
Hierbei ist mir aufgefallen, dass tmr-DbLog_execMemCacheAsync(LogDB_2) immer wieder aufgerufen wird, obwohl das Modul auf disabled steht.
Momentan ist dort keine zusätzliche Datenbank vorhanden.
2023.08.07 02:04:24.402 1: [Freezemon] myFreezemon: possible freeze starting at 02:04:22, delay is 2.402 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-HttpUtils_TimeoutErr(N/A) tmr-HttpUtils_TimeoutErr(N/A) tmr-HttpUtils_TimeoutErr(N/A)
2023.08.07 02:06:05.392 1: [Freezemon] myFreezemon: possible freeze starting at 02:06:03, delay is 2.391 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-HttpUtils_TimeoutErr(N/A) tmr-CODE(0x55a42bda08)(ResponseTimeout)
2023.08.07 03:24:05.005 1: [Freezemon] myFreezemon: possible freeze starting at 03:24:03, delay is 2.005 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-HttpUtils_TimeoutErr(N/A)
2023.08.07 03:36:04.959 1: [Freezemon] myFreezemon: possible freeze starting at 03:36:03, delay is 1.958 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-HttpUtils_TimeoutErr(N/A)
2023.08.07 04:06:03.944 1: [Freezemon] myFreezemon: possible freeze starting at 04:06:02, delay is 1.944 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-HttpUtils_TimeoutErr(N/A)
2023.08.07 04:48:04.949 1: [Freezemon] myFreezemon: possible freeze starting at 04:48:03, delay is 1.948 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-FHEM::Astro::Update(Astro) tmr-CODE(0x55a420bea0)(ProcessRequestQueue)
2023.08.07 04:54:04.859 1: [Freezemon] myFreezemon: possible freeze starting at 04:54:03, delay is 1.858 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-HttpUtils_TimeoutErr(N/A) tmr-CODE(0x55a42bda08)(ResponseTimeout)
2023.08.07 05:18:04.779 1: [Freezemon] myFreezemon: possible freeze starting at 05:18:02, delay is 2.778 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-CODE(0x55a19a2d28)(HandleSendQueue) tmr-DbLog_execMemCacheAsync(LogDB_2)
2023.08.07 06:03:05.615 1: [Freezemon] myFreezemon: possible freeze starting at 06:03:01, delay is 4.614 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-CODE(0x559aaa3058)(dnsQuery) tmr-CODE(0x559aaa3058)(dnsQuery) tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-CODE(0x55a19a2d28)(HandleSendQueue)
2023.08.07 07:03:02.111 1: [Freezemon] myFreezemon: possible freeze starting at 07:03:01, delay is 1.111 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-CODE(0x559aaa3058)(dnsQuery) tmr-CODE(0x559aaa3058)(dnsQuery) tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-CODE(0x55a19a2d28)(HandleSendQueue)
2023.08.07 07:06:04.953 1: [Freezemon] myFreezemon: possible freeze starting at 07:06:03, delay is 1.952 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-HttpUtils_TimeoutErr(N/A)
2023.08.07 08:06:04.918 1: [Freezemon] myFreezemon: possible freeze starting at 08:06:03, delay is 1.917 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-HttpUtils_TimeoutErr(N/A) tmr-CODE(0x55a42bda08)(ResponseTimeout)
2023.08.07 09:12:04.852 1: [Freezemon] myFreezemon: possible freeze starting at 09:12:03, delay is 1.851 possibly caused by: tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-CODE(0x55a420bea0)(ProcessRequestQueue)
2023.08.07 09:18:04.878 1: [Freezemon] myFreezemon: possible freeze starting at 09:18:03, delay is 1.878 possibly caused by: tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-CODE(0x55a420bea0)(ProcessRequestQueue) tmr-DbLog_execMemCacheAsync(LogDB_2) tmr-HttpUtils_TimeoutErr(N/A)
Internals:
COLUMNS field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
CONFIGURATION ./db_2.conf
DEF ./db_2.conf .*:.*
FD 7
FUUID 5faa6fca-f33f-61a8-350c-a03dfb161f54a948
FVERSION 93_DbLog.pm:v5.9.0-s27617/2023-05-25
MODE asynchronous
MODEL MYSQL
NAME LogDB_2
NR 3
NTFY_ORDER 50-LogDB_2
PID 11397
REGEXP .*:.*
SBP_PID 11433
SBP_STATE running
STATE disabled
TYPE DbLog
UTF8 1
dbconn mysql:database=fhem;host=192.168.178.40;port=3307
dbuser fhemuser
eventCount 2
HELPER:
COLSET 1
DEVICECOL 64
EVENTCOL 512
OLDSTATE disabled
PACKAGE main
READINGCOL 64
TC current
TH history
TYPECOL 64
UNITCOL 32
VALUECOL 128
VERSION 5.9.0
OLDREADINGS:
READINGS:
2023-02-13 13:50:01 CacheOverflowLastNum 0
2021-03-12 16:12:40 CacheOverflowLastState normal
2020-11-23 16:35:30 NextSync 2020-11-23 16:36:00 or if CacheUsage 500 reached
2020-11-11 12:57:00 background_processing_time 0.1265
2020-11-11 12:57:00 sql_processing_time 0.0113
2023-07-29 20:06:09 state disabled
Attributes:
DbLogExclude .*
DbLogSelectionMode Exclude/Include
DbLogType History
asyncMode 1
disable 1
insertMode 1
room System
showproctime 1
verbose 0
Hinweise wären gerne willkommen.
VG Christian
Zitat von: ch.eick am 07 August 2023, 09:40:33Hallo zusammen,
ich suche bereits geraume Zeit nach Modulen, die zu einer Verzögerung im FHEM beitragen.
Hierbei ist mir aufgefallen, dass tmr-DbLog_execMemCacheAsync(LogDB_2) immer wieder aufgerufen wird, obwohl das Modul auf disabled steht.
Ein Modul kannst Du nicht disablen, das geht maximal auf device-Ebene.
Das disable im DbLog device bezieht sich mit hoher Wahrscheinlichkeit nur auf die Logik des DbLog (also das eigentliche Erfassen der Werte), aber nicht auf die Datenbankanbindung selbst.
Der Timer startet regelmäßig um evtl. im Cache vorhandene Daten in die DB zu schreiben.
Ist das Device disabled, wird die aufgerufene Routine DbLog_execMemCacheAsync sofort wieder verlassen, sie macht de facto nichts.
Trotzdem sieht man den Aufruf.
@Christian, bzgl. Performance kannst du die Routine ignorieren wenn das Device auf disabled steht.
Wäre es nicht disabled, würde diese Routine die Daten aus dem Cache serialisieren und an den Subprozess übergeben.
Eventuelle Verzögerungen durch die DB hätte keine Auswirkungen auf den Hauptprozess. Das Datenbankhandling übernimmt generell der Subprozess.
Möglicherweise kann ich das Handling der Routine bzgl. disable besser machen.
Wenn DbLog bei mir mal wieder in den Focus rückt, schaue ich mir das mit an.
Zitat von: betateilchen am 07 August 2023, 15:34:38Zitat von: ch.eick am 07 August 2023, 09:40:33Hallo zusammen,
ich suche bereits geraume Zeit nach Modulen, die zu einer Verzögerung im FHEM beitragen.
Hierbei ist mir aufgefallen, dass tmr-DbLog_execMemCacheAsync(LogDB_2) immer wieder aufgerufen wird, obwohl das Modul auf disabled steht.
Ein Modul kannst Du nicht disablen, das geht maximal auf device-Ebene.
Das disable im DbLog device bezieht sich mit hoher Wahrscheinlichkeit nur auf die Logik des DbLog (also das eigentliche Erfassen der Werte), aber nicht auf die Datenbankanbindung selbst.
Okay, dank.
Schade, und ich dachte ich hätte eine Erklärung für meine kurzen Hänger im FHEM.
Vielen Dank für's Mitdenken
Christian
Ich krame diesen Thread mal hervor, da meine Beobachtung vielleicht irgendwie hier rein passt.
Ich nutze Perfom, um Freezes aufzuspüren. Dabei beobachte ich, dass ich in der Regel zwei- bis dreimal pro Minute einen Freeze (meistens kürzer als 2s) im Log beobachten kann. In meiner eigentlichen Fhem-Installation kann ich allerdings solche massiven Verzögerungen nicht beobachten. Trotzdem hat es mir keine Ruhe gelassen, und ich habe nach der Ursache geforscht. Nach langem Suchen habe ich herausgefunden, dass nach einem Disable meines DbLog-Devices sofort die Freezes im Log aufhören.
Wenn ich die obigen Kommentare richtig deute, können meine die "Freezes" durch DbLog verursacht werden; sie haben aber keine Auswirkungen auf die eigentliche Fhem-Installation. Ist das korrekt? Wenn ja, lassen sich die DbLog-"Freezes" irgendwie aus dem Perfom-Modul aussteuern? So ist es irgendwie schwierig, echte Freezes zu analysieren.
Viele Grüße
Christoph
Es ist sehr unwahrscheinlich dass DbLog selbst Systemblockierungen verursacht, da das Logging der Daten in einem Subprozess erledigt wird.
Mit dem Attr showNotifyTime, showproctime kannst du dir die Verarbeitungszeiten anschauen.
Aber die SVG-Generierung kann, wenn ungüstig eingestellt, Blockierungen verursachen. Ein "get <name> configCheck" kann dir Hinweise auf evtl. Engpässe geben.
LG
Interessante Geschichte....habe ähnliches festgestellt:
2 dblog-devices - auf 2 verschiedene sql-server...
das aktive hat ca. 0.1 sec processing time, ca. 100 records /120 sec.
das disabled knapp über 1 Sekunde - obwohl nichts zu tun ist.
.. environment - beide loggen via VPN.... alle Attribute "fast" ;D gleich....
Ursache bei mir (danke an den Hinweis mit config-check): Attr insertMode !!!
kaum stellt man auf 0 - hat auch der disabled server 0.1 sec!!! (array/sequential-insert)
l.g. erwin
Das ist jetzt ein Mysterium. ;)
Weil ...
1. wenn disabled aktiv ist, wird die Notify Funktion (DbLog_Log) nicht mehr durchlaufen -> Ausstieg gleich zu Beginn
2. sich der insertMode ohnehin nur im Nebenprozess auswirkt weil NUR dort die Verbindung zur DB zum Schreiben von Daten aufgebaut wird (Ausnahme ist das Lesen von Daten durch SVG)
Also da braucht es einen Erklärungsansatz den ich nicht sehe.
LG,
Heiko
ZitatAlso da braucht es einen Erklärungsansatz den ich nicht sehe.
Vermutlich hast du recht, ich kann das auch nicht mehr nachstellen, durch zurückstellen von Attr insertMode....
bleibt in beiden Fällen bei ca. 0.1 sec...
Ich vermute fast
false positive, im Zusammenhang mit anderen Ereignissen, es ist immer tmr-DbLog_execMemCacheAsync(myDbLogStby) mit über 1 sec, nie die notify-funct, ist ja auch klar, die wird nicht aufgerufen (bzw. unmittelbar beendet) wenn es nix zu loggen gibt.
Auffällig ist nur, dass tmr-DbLog_execMemCacheAsync sehr viel öfter aufgerufen wird wenn das dblog-dev disabled ist. - ca. Factor 12
Wie freezmon misst ? keine Ahnung - relativ oft gibts eine korrelation mit Solarforcast, aber nicht immer....
2024.03.08 17:00:58.850 2: mySolarForecast - Consumer 'myEBUS' was external switched off
2024.03.08 17:00:59.224 1: [Freezemon] myfreezemon: possible freeze starting at 17:00:58, delay is 1.223 possibly caused by: tmr-DbLog_execMemCacheAsync(myDbLogStby)
.. aber das kann auch Zufall sein.... - myDbLogStby ist die disabled instanz.
Sorry für die Verwirrung
l.g. erwin
Kein Problem erwin. :)
Ich bin sowieso gerade wieder etwas in DbLog eingetaucht weil ich den MariaDB Treiber Support einbauen will.
Vllt. kann ich bei der Gelegenheit noch den Timer für die DbLog_execMemCacheAsync etwas umgestalten damit der bei einem disable nicht mehr läuft und erst wieder angestartet wird wenn er gebraucht wird.
Die aktuelle Implementierung ist diesbezüglich nicht ganz optimal.
LG
Zur Vollständigkeit:
die Freezes , die auf DBLog_execMemCacheAsync hinzeigen ...
DbLog als Ursache ist definitiv falsch - die freezes sind vermutlich echt.
1.Test: Ich hab den Timer in DBLog_execMemCacheAsync so modifiziert, dass, wenn disabled, das Interval $nextsync gesetzt wird (bei mir 120 sec)
dann kommt regelmässig: delay is 1.287 possibly caused by: no bad guy found :-(
2.Test: ein AT definiert, das alle 2 sekunden einen Timer startet und sonst nix macht.
resultat:
delay is 1.142 possibly caused by: tmr-sleep_WakeUpFn(N/A) tmr-at_Exec(testAT2)
bzw. auch andere tmr-xxx die zum FreezeZeitpunkt gerade laufen....
Es liegt also offensichtlich an der "Messmethode"....von freezemon. Ich vermute alles was mit tmr- beginnt in freezmon ist nicht die wahrscheinliche Ursache.
l.g.erwin
Sorry für die späte Reaktion, aber ich war beruflich und privat etwas gefordert.
insertMode ist bei mir auf 0; das reduziert die geloggten Freezes nicht.
Ansonsten habe ich mithilfe von configCheck die Datenbank etwas optimiert; da ist jetzt alles grün.
Das alles ändert aber nichts. Ich habe im Log unzählige Freezes:
2024.03.11 13:43:29.194 1: Perfmon: possible freeze starting at 13:43:26, delay is 3.194
2024.03.11 13:43:49.304 1: Perfmon: possible freeze starting at 13:43:46, delay is 3.304
2024.03.11 13:44:10.877 1: Perfmon: possible freeze starting at 13:44:07, delay is 3.877
2024.03.11 13:44:30.067 1: Perfmon: possible freeze starting at 13:44:26, delay is 4.067
2024.03.11 13:44:50.216 1: Perfmon: possible freeze starting at 13:44:45, delay is 5.216
2024.03.11 13:45:01.565 1: Perfmon: possible freeze starting at 13:44:59, delay is 2.565
2024.03.11 13:45:09.822 1: Perfmon: possible freeze starting at 13:45:06, delay is 3.822
2024.03.11 13:45:29.422 1: Perfmon: possible freeze starting at 13:45:26, delay is 3.422
2024.03.11 13:45:31.589 1: Perfmon: possible freeze starting at 13:45:30, delay is 1.589
2024.03.11 13:45:50.156 1: Perfmon: possible freeze starting at 13:45:46, delay is 4.156
2024.03.11 13:46:09.694 1: Perfmon: possible freeze starting at 13:46:06, delay is 3.694
2024.03.11 13:46:29.494 1: Perfmon: possible freeze starting at 13:46:26, delay is 3.494
2024.03.11 13:46:51.882 1: Perfmon: possible freeze starting at 13:46:46, delay is 5.881
2024.03.11 13:47:09.319 1: Perfmon: possible freeze starting at 13:47:06, delay is 3.319
Allerdings kann ich die in meiner Installation so nicht beobachten. Da läuft alles geschmeidig durch.
Sobald ist mein DbLog-Device auf disable=1 setze, verschwinden die geloggten Freezes.
Nachtrag: Kann es vielleicht sein, dass irgendwie Regex in einem DbLogInclude Ressourcen schluckt?
Die Event Verarbeitungszeit innerhalb DbLog siehst du mit dem Attr showNotifyTime wie oben geschrieben. Was zeigt denn das resultierende Reading?
Ungünstige Regex, vor allem wenn sie massiv ausgewertet werden müssen, verbrauchen natürlich Zeit. Aber das sieht man mit dem gesetzten Attr.
notify_processing_time ist in der kleiner als 0.07
sql_processing_time ist kleiner als 0.04
Die notify_processing_time ist mit ca. 70 ms zwar relativ hoch (bei mir zum Vergleich 0.0006) aber weit entfernt von den beschriebenen Messwerten von Freezemon.
Es hat mir keine Ruhe gelassen und daher habe ich nochmal etwas rumexperimentiert.
Die Ursache (zumindest für einen großen Teil der geloggten Freezes) war das Attribut excludeDevs. Damit hatte ich einige Devices vom Logging ausgeschlossen. Nachdem ich das Attribut gelöscht habe, sind die Freezes fast alle verschwunden. Auch sank notify_processing_time deutlich um mindestens eine Größenordnung.
Test doch mal die neue Version: https://forum.fhem.de/index.php?topic=137480.0
wenn du magst. Ich habe an verschiedenen Stellen nachgebessert.
LG