98_FREEZEMON - der bessere PERFMON?

[KernSani]

Das Modul ist ab morgen (06.02.2018) Bestandteil des offiziellen Updates und wird hier https://forum.fhem.de/index.php/topic,83909.0.html weiter diskutiert.

Hallo zusammen,

ich empfinde das aufspüren von "possible freezes" mit Hilfe von PERFMON, ggf. verbose 5 und apptime als extrem umständlich. Daher habe ich auf Basis von PERFMON ein Modul geschnitzt.

FREEZEMON überwacht - ähnlich wie PERFMON mögliche Freezes, allerdings ist FREEZEMON ein echtes Modul und hat daher:

• Readings - die geloggt werden können und damit viel einfacher ausgewertet werden können
• Attribute - mit denen das Verhalten von freezemon beeinflusst werden kann
• zusätzliche Funktionalität - die versucht das den Freeze verursachende Device zu identifizieren

FREEZEMON ist noch in einem sehr frühen Stadium, läuft bei mir aber seit ein paar Tagen stabil, Daher würde ich mich freuen wenn der ein oder andere sich traut zu testen und Feedback gibt.

Ich würde empfehlen, PERFMON zu deaktivieren, wenn FREEZEMON aktiv ist, da beide auf die selbe Art Freezes erkennen und dann nur alles doppelt kommt.

FREEZEMON wird ohne Parameter definiert.

Code Auswählen Erweitern

define myFreezemon freezemon

damit ist der Freezemon aktiv (im Log sollte eine entsprechende Meldung geschrieben werden)

Readings (nach dem ersten erkannten Freeze):
freezeTime: Dauer des Freezes
freezeDevice: Liste von möglicherweise den Freeze auslösenden Funktionen(Devices)
fcDay: kumulierte Anzahl der Freezes pro Tag
ftDay: kumulierte Dauer der Freezes pro Tag
fcDayLast: speichert die kumulierte Anzahl der Freezes des vergangenen Tages (um tageweise plots zu erstellen)
fcDayLast: speichert die kumulierte Dauer der Freezes des vergangenen Tages (um tageweise plots zu erstellen)
state: s:<StartZeit> e:<EndeZeit>f:<Dauer> d:<Devices>

Attribute
fm_freezeTime: Wert in Sekunden (Default: 1) - Nur Freezes länger als fmFreezeTime werden als Freeze betrachtet
fm_forceApptime: Wenn FREEZEMON aktiv ist wird automatisch apptime gestartet (falls nicht aktiv)
fm_log: dynamischer Loglevel, nimmt einen String der Form 10:1 5:2 1:3 entgegen, was bedeutet: Freezes > 10 Sekunden werden mit Loglevel 1 geloggt, >5 Sekunden mit Loglevel 2 usw...
disable: aktivieren/deaktivieren der Freeze-Erkennung

Get
freeze: gibt die letzten 20 freezes zurück (in Kompakter Darstellung, wie im state) - Dies dient einem schnellen Überblick, für detailliertere Auswertungen empfehle ich die Daten zu loggen.

Code Auswählen Erweitern


##############################################################################
#   Changelog:
# 0.0.08: trimming of very long lines in "get freeze"
# start freezemon only after INITIALIZED|REREADCFG (and as late as possible)
# 0.0.07: just for fun - added some color to "get freeze"
# Fixed bug with uninitialized value (Thanks Micheal.Winkler)
# 0.0.06: Code cleanup
# Fixed bug with dayLast readings
# 0.0.05: Experimental coding to improve bad guy detection
# German and English documentation added
# 0.0.04: Added Get function to get last 20 freezes
# 0.0.03: Added dynamic loglevel attribute fm_log
# Added missing "isDisabled" check in define function
# Do some checks not every second
# Fixed PERL WARNING "uninitialized value" if no Device found
# minor adjustments and bugfixes
# 0.0.02: Fixed logical issue with freezetime Attribute
# Renamed Attributes
# added dayLast readings
# fixed delete attribute "disable"
# fixed issue with missing svref_2object
# minor adjustments and bugfixes
#   0.0.01: initial version
##############################################################################

[herrmannj]

der perfmon autor liest mal mit

vg
joerg

[MadMax-FHEM]

Bin grad (länger) unterwegs aber will nichts verpassen und sobald ich zurück bin werd ich mal mein Testsystem damit "füttern"...

Bin gespannt!

Gruß, Joachim

[KölnSolar]

Und schon im Testsystem aktiviert 

Erste kleine Kritik:
Positiv: Ein solches Tool fehlt in FHEM. Prima Idee. Scheint schön einfach in der Handhabung.
Und schon hat FreezeMon den ersten kleinen Übeltäter aufgespürt. Und das in einem fast leeren Testsystem. 
Negativ:
keine einheitliche Namensgebung, was upper/lower case betrifft: freezeTime vs. fmFreezeTime

Und nur so als Gedanke: Bei der Vielzahl der Module verliert man mittlerweile ja den Überblick. Ich könnt mir daher eine Integration in SYSMON vorstellen, was man dann als "Kernmodul" von FHEM installiert, also ein Modul wie FHEMWEB oder allowed, was in keiner Installation fehlen sollte.

Grüße Markus
Edit: FW_closeInactiveClients (0) im FreezeDevice hilft wenig; ließe sich ermitteln, welches Modul verantwortlich ist bzw., sofern/da es aus dem "Kern"(fhem.pl) kommt, wenigstens entsprechend kennzeichnen/beschreiben ?
Edit2: Verursacher ? 

Code Auswählen Erweitern

2018.02.03 08:19:07 1: FreezeMon: freezedetect possible freeze starting at 08:19:04, delay is 3.003 by

Edit3: FreezeTime =1; Alle Meldungen im Log haben FreezTime > 3 u. ganz oft 3.003 

[KernSani]

Danke für's erste testen Schau ich mir heute Abend gleich mal an. Bezüglich dem Verursacher muss ich mal noch genauer verstehen, was ich da eigentlich mache Hab mir da ein bisschen was aus apptime zusammen kopiert...


Kurz, weil mobil...

[KölnSolar]

Nun auch produktiv im Einsatz und ich erhalte die üblichen Verdächtigen. 

Was soll mir diese Zeile

2018.02.03 12:20:22 1: FreezeMon: freezedetect possible freeze starting at 12:20:21, delay is 1.407 by GPIO4_DeviceUpdateLoop (RPi_OW_VL) at_Exec (check_jammer) GPIO4_DeviceUpdateLoop (RPi_OW_WWL)

sagen ? at_Exec (check_jammer) ist eher unverdächtig. Ein simples at, welches lediglich per ReadingsAge das Alter eines timestamps prüft.

Manchmal hab ich ne Menge "Routinen" im Reading stehen. Sind das dann Blocking-Calls ?

Loglevel 1 empfinde ich als zu "hoch". 2 genügt meines Erachtens. Entweder hat man eh das device bewusst kurzzeitig enabled oder man lässt es permanent enabled. Was man im Log oder Reading sehen möchte, lässt sich ja über FreezeTime steuern. Evtl. noch eine Differenzierung zwischen Log(LogFreezeTime) und Reading(FreezeTime). Das Reading gucke ich mir bewusst zu einem bestimmten Zeitpunkt an und beobachte es. Das Log soll mich auf Freezes hinweisen, wenn ich mich gar nicht aktuell mit dem Thema auseinandersetze, also nur im nachhinein über einen Zustand informieren möchte.

[KernSani]

Vielen Dank für's Testen und die Anregungen.

Manchmal hab ich ne Menge "Routinen" im Reading stehen. Sind das dann Blocking-Calls ?

Wahrscheinlich ist einer davon der Schuldige. der Freezemon kann hier nur raten. Es wird ermittelt welche internen Timer zum Zeitpunkt des Freezes ausgeführt werden sollten und die werden alle als verdächtig angesehen. Ich werde das noch irgendwie ausdünnen - ob ich es wirklich auf ein Device einschränken kann, also den Schuldigen eindeutig ermitteln kann, bin ich mir noch nicht so sicher...

Evtl. noch eine Differenzierung zwischen Log(LogFreezeTime) und Reading(FreezeTime). Das Reading gucke ich mir bewusst zu einem bestimmten Zeitpunkt an und beobachte es.

Meine Plan ist eigentlich ein konfigurierbarer Loglevel. sowas in der Art: 10:1 5:2 1:3, bedeutet über 10 Sekunden wird mit Level 1 geloggt, über 5 Sekunden mit Level 2 usw...
Der große Vorteil der Readings ist aus meiner Sicht, dass ich diese in DbLog (oder FileLog) mitloggen kann und dann gezielt auswerten kann (Mir schwebt z.B. vor, die Top10 Verdächtigen - nach Häufigkeit und/oder Dauer anzuzeigen). Bei besonders langen freezes könnte ich mir auch eine Pushmessage schicken lassen o.ä.

[Ma_Bo]

Ich lese mal mit und werde nächste Woche auch mittesten.

Grüße Marcel


Tapatalk iPhone, daher kurz gehalten.

[KölnSolar]

Ja, auch gut

Meine Plan ist eigentlich ein konfigurierbarer Loglevel. sowas in der Art: 10:1 5:2 1:3, bedeutet über 10 Sekunden wird mit Level 1 geloggt, über 5 Sekunden mit Level 2 usw...

[helmut]

FREEZEMON ist noch in einem sehr frühen Stadium, läuft bei mir aber seit ein paar Tagen stabil, Daher würde ich mich freuen wenn der ein oder andere sich traut zu testen und Feedback gibt.

Da ich mit perfmon schon einige Resourcenfresser gefunden habe, finde ich Deinen Ansatz
sehr interessant.

Ich würde empfehlen, PERFMON zu deaktivieren, wenn FREEZEMON aktiv ist, da beide auf die selbe Art Freezes erkennen und dann nur alles doppelt kommt.

Das habe ich getan.

Readings (nach dem ersten erkannten Freeze)

Die habe ich nicht zu sehen bekommen, aber nach wenigen Minuten oder auch nur
Sekunden stuerzt mein fhem reproduzierbar ab mit:
Undefined subroutine &main::svref_2object called at ./FHEM/98_freezemon.pm line 280.

Auch mit "verbose 5" sehe ich nicht mehr; unter "helper" nur die ueblichen Verdaechtigen
wie zum Beispiel:
apptime    DbLog_execmemcache (bath45DbLog) EspLedController_Check (rgbctrl_wz01)
apptime    TSCUL_SendPingHM (CUL1)
apptime    HMUARTLGW_CheckCredits (HMUARTLGW_CheckCredits)
apptime    TSCUL_SendPingHM (CUL1) SYSMON_Update (sysmon)

Mein fhem-System ist aktuell, jedenfalls behauptet das der "update check". perl ist mit
Version v5.20.2 auf einem "Raspbian GNU/Linux 8 (jessie)" installiert.

Gruss Helmut

[KernSani]

Undefined subroutine &main::svref_2object called at ./FHEM/98_freezemon.pm line 280.

Ich habe die Version im ersten Post aktualisiert. Die Funktion wird normalerweise mit apptime mit eingebunden. Jetzt geht's auch wenn apptime nicht läuft (und ein paar weitere Änderungen - siehe changelog im ersten Post).

Grüße,

Oli

[raimundl]

Nur zur Info meine LogDatei:

Code Auswählen Erweitern

2018.02.03 20:14:34 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/98_freezemon.pm line 163.
2018.02.03 20:14:34 1: FreezeMon: FreezeMonitor possible freeze starting at 20:14:29, delay is 5.648 by
2018.02.03 20:14:34 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/98_freezemon.pm line 167.

Danke für das Modul und LG

[helmut]

Jetzt geht's auch wenn apptime nicht läuft

Hallo Oli,

danke, das sieht jetzt gut aus und ich sehe auch das erste "freeze-READINGS".
Die Warnungen die raimundl in der Log-Datei hat, gibt es bei mir nicht.

Gruss Helmut

[KernSani]

Danke für's Feedback.

Code Auswählen Erweitern

2018.02.03 20:14:34 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/98_freezemon.pm line 163.
2018.02.03 20:14:34 1: FreezeMon: FreezeMonitor possible freeze starting at 20:14:29, delay is 5.648 by
2018.02.03 20:14:34 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/98_freezemon.pm line 167.

Hmmm... da konnte Freezetime garkeinen Prozess finden, der den Freeze verursachen könnte...  Zumindest die Warnungen kann ich verhindern. Update im ersten post

@KölnSolar: Loglevel ist jetzt auch einstellbar

[KölnSolar]

wo und wie  hab nur noch fm_freezeThreshold und Plausi: Attribute fm_freezeThreshold has to be a number (seconds)

Du hast oben auch noch den alten Download drin.