[erledigt] DbLog - disable, trotzdem Meldungen im Freezemon

[ch.eick]

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.

Code Auswählen Erweitern

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)


Code Auswählen Erweitern

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

[betateilchen]

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.

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.

[DS_Starter]

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.

[ch.eick]

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.

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.

[ch.eick]

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

[CQuadrat]

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

[DS_Starter]

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

[erwin]

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"    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

[DS_Starter]

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

[erwin]

Also 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....

Code Auswählen Erweitern

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

[DS_Starter]

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

[erwin]

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:

Code Auswählen Erweitern

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:

Code Auswählen Erweitern

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

[CQuadrat]

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:

Code Auswählen Erweitern

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?

[DS_Starter]

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.

[CQuadrat]

notify_processing_time ist in der kleiner als 0.07

sql_processing_time ist kleiner als 0.04