Neues Modul: 98_FREEZEMON Freezes monitoren und Verursacher identifizieren

Amenophis86 · 14 März 2018, 18:15:11

Habe heute auch mal dein Modul in meinem aktiven System eingesetzt und bekomme regelmäßig folgende Meldung:

2018-03-14: s:18:12:40 e:18:12:43 f:3.1 d:RESIDENTStk_DurationTimer(rr_Anja_DurationTimer) RESIDENTStk_DurationTimer(rr_Etienne_DurationTimer) RESIDENTStk_DurationTimer(rgr_Zuhause_DurationTimer) MQTT((Timer(Mosquitto) RESIDENTStk_DurationT...

Das heißt wenn ich nun rr_Etienne,rr_Anja,rgr_Zuhause,Mosquitto auf die ignore-liste setze, dann bekomme ich diese Meldung nicht mehr? Und denkst du ich sollte den Modulmaintainer informieren, dass seine Funktion DurationTimer regelmäßig länger als 2 Sekunden (thereshold steht bei mir auf 2sek) brauchen?

KernSani · 14 März 2018, 19:59:20

Hi Etienne,

Die Residents sind nicht die Ursache... Die kommen bei mir auch laufend. Vielleicht mal im Log schauen, ob da nicht noch was anderes läuft. Freezemon versucht nur aufgrund der internen Timer zu erraten, was einen Freeze verursachen könnte, aber es ist eben nicht alles Timer-gesteuert...
Wenn du das Device auf die ignoreDevs setzt, wird der Freeze nicht mehr geloggt. Wenn du die Sub auf die Whitelist setzt, werden die Freezes noch geloggt, aber die Residents als Verursacher ausgeschlossen.
Grüße,
Oli

Kurz, weil mobil...

Amenophis86 · 14 März 2018, 20:05:20

Na dann werde ich das mal so machen und schauen. Ansonsten cooles Modul. Dank dir dafür Oli.

vbs · 17 März 2018, 15:33:42

Danke für das Modul, gefällt mir bisher sehr gut!

Eine kleine Warning beim Start von FHEM bekomme ich aber:

Code Auswählen

2018.03.17 15:31:54.836 3: freezemon defined sys_freezemon freezemon
2018.03.17 15:31:54.837 0: [Freezemon] sys_freezemon: Wrapping Log3
2018.03.17 15:31:54.837 1: PERL WARNING: Subroutine main::Log3 redefined at ./FHEM/98_freezemon.pm line 823, <$fh> line 2973.

KernSani · 17 März 2018, 16:32:56

Um die verbose 5 Meldungen abzufangen überschreibt Freezemon die Log3 Funktion, das erzeugt eine Warnung... (Ähnliches Prinzip wie bei apptime, da gibt's auch Warnungen). Och schau mal, ob ich das irgendwie unterdrücken kann.

Kurz, weil mobil...

vbs · 17 März 2018, 16:40:12

Schon so ein bisschen geahnt, dass das prinzipbedingt sein könnte. Im Zweifel könnte man ja evtl. davor noch eine Logzeile machen so in der Art "nicht wundern: gleich kommt ne Warning" ^^

KernSani · 19 März 2018, 23:14:04

Neue Version zum Testen im Anhang. Feedback wie immer willkommen.

Die Warnungen beim überschreiben von FHEM-Funktionenetc... werden nun unterdrückt
Neues Attribut: fm_catchCallFn: wenn aktiviert, werden zusätzlich FHEM-interne Funktionsaufrufe überwacht, in einigen Fällen kann das zusätzliche Hinweise auf den Freeze-Verursacher geben
Neues Attribut: fm_catchCmds: wenn aktiviert, werden zusätzlich FHEM-Kommandos überwacht, in einigen Fällen kann das zusätzliche Hinweise auf den Freeze-Verursacher geben

sledge · 21 März 2018, 11:10:31

Hi,

nach dem ersten Setup meines FHEM-Systems vor gut 2 Jahren habe ich mal mit perfmon aufgeräumt. In letzter Zeit waren mir dann wieder "freezes" aufgefallen - die konnte ich auf Yeelight zurückführen und dank der Version von "vbs" beseitigen.

Allerdings habe ich immer noch einen Freeze von 2-3sec, der ziemlich genau alle 63 Sekunden auftritt. Danke freezemon komme ich jetzt zu folgender Auswertung:

Code Auswählen


1 - 2018-03-21 [Log]: s:10:56:52 e:10:56:55 f:3.086 d:TSCUL_XmitAwaitTo(N/A) TSCUL_SendPingHM(N/A) TSCUL_Timed_Clear_SlowRF_Stat(N/A) HttpUtils_E...
1 - 2018-03-21 [Log]: s:10:57:55 e:10:57:58 f:3.009 d:no bad guy found :-(
1 - 2018-03-21 [Log]: s:10:58:59 e:10:59:01 f:2.103 d:CUL_HM_procQs(N/A)
1 - 2018-03-21 [Log]: s:11:00:02 e:11:00:04 f:2.421 d:no bad guy found :-(
1 - 2018-03-21 [Log]: s:11:01:04 e:11:01:07 f:3.009 d:no bad guy found :-(
1 - 2018-03-21 [Log]: s:11:02:08 e:11:02:10 f:2.042 d:TSCUL_SendPingHM(N/A) TSCUL_XmitAwaitTo(N/A)
1 - 2018-03-21 [Log]: s:11:03:11 e:11:03:13 f:2.859 d:no bad guy found :-(
1 - 2018-03-21 [Log]: s:11:04:13 e:11:04:16 f:3.007 d:no bad guy found :-(
1 - 2018-03-21 [Log]: s:11:05:17 e:11:05:19 f:2.084 d:DbLog_execmemcache(dblog) BlockingKill(TK.KG.FB)
1 - 2018-03-21 [Log]: s:11:06:20 e:11:06:22 f:2.067 d:DbLog_execmemcache(dblog) BlockingKill(KL.OG.FTV.pres)

Also in rund der Hälfte der Fälle ein "no bad guy found".

Mein System läuft auf einem NUC - generell habe ich keine Performance-Probleme - aber für Tipps, wie ich diesen freeze rauskriege (ohne device für device zu löschen) bin ich sehr dankbar.

Achja: Als Feedback: Gutes Modul - perfmon und apptime erledigen zwar auch viel von dem Job, aber so finde ich es komfortabler. Danke hierfür.

Gruß,

Tom

KernSani · 21 März 2018, 23:08:34

Hi Tom,

der erste Schritt wäre mal das fm_logFile Attribut zu setzen, dann bekommst du ein verbose 5 Log von jedem Freeze, das vielleicht zusätzliche Erkenntnisse liefert. Wenn du mutig bist kannst du auch noch die 2 Posts weiter oben angehängte Version ausprobieren, die nochmal ein paar mehr Erkenntnisse liefern kann. Bei mir läuft sie seit ein paar Tagen stabil im Produktivsystem.

Grüße,

Oli

sledge · 21 März 2018, 23:58:46

Hi Oli,

das Logfile läuft bei mir schon - das hat jetzt im ersten Ansatz auch nicht wirklich was gebracht. Dann habe ich schon diverse Module / Devices gekillt, die oben in der Liste uaftauchen - no avail. Hat auch nichts gebracht -nur mehr "no bad guys...". Und andere Kandidaten rücken nach vorne. Aber da geht es dann schon an echte phys. IO-Devices (Culs etc).

Ich teste ab morgen mal Deine neue Version.

Was mir aufgefallen ist (Irrtum oder falsche config) Das Logfile beginnt ziemlich genau dann, wenn der Freeze zuende ist - und nicht ein paar Sekunden vorher. Wenn also der Freeze laut Meldung um 10:05:02 beginnt und 3 sekunden dauert, beginnt das Logfile ungefähr um 10:05:05. Entweder mach ich was falsch oder ... works as designed - aber ich dachte, man müsse das log ab beginndes freezes betrachten - zumindest habe ihc das immer so bei perfmon gemacht.

In jedem Fall danke - morgen abend mehr feedback.

Tom

frank · 22 März 2018, 09:40:14

hallo tom,

ZitatDann habe ich schon diverse Module / Devices gekillt, die oben in der Liste uaftauchen - no avail. Hat auch nichts gebracht -nur mehr "no bad guys...". Und andere Kandidaten rücken nach vorne.

denk mal genau darüber nach, was bei sich bei dir alle 60 sek wiederholt. at's, sysmon, presence, fritzbox, ...
eventuell auch mal apptime clearen und nach genau einer stunde aufrufen und einträge mit count~60 suchen.

KernSani · 22 März 2018, 11:57:54

Hi Tom,

ich habe hier einen bösen Verdacht. Freezemon macht ein paar Dinge jede Minute (Überprüfen ob apptime läuft, wenn das Attribut gesetzt ist etc...). Mir ist nicht wirklich klar, wie das einen Freeze verursachen könnte, aber das würde auch erklären, warum dein Log nicht so aussieht, wie es aussehen sollte.
Das sollten wir heute abend mal genauer untersuchen...

Grüße,

Oli

sledge · 22 März 2018, 19:32:03

Zitat von: frank am 22 März 2018, 09:40:14
hallo tom,
denk mal genau darüber nach, was bei sich bei dir alle 60 sek wiederholt. at's, sysmon, presence, fritzbox, ...
eventuell auch mal apptime clearen und nach genau einer stunde aufrufen und einträge mit count~60 suchen.

Hi Frank,

was sich alle 60 Sekunde wiederholt - inklusive aller "at" - habe ich überprüft, auf 120sek gestellt, einfach gelöscht - keine Änderung. Das war die erste Maßnahme, die ich dieses Mal auch wieder angeleiert habe.

Das mit apptime und eine Stunde warten - gefällt mir.

Ich steige jetzt erstmal auf die neueste Version um und schaue mir dann das Verhalten an.

Gruß,

Tom

sledge · 22 März 2018, 19:42:31

Zitat von: KernSani am 22 März 2018, 11:57:54
Hi Tom,

ich habe hier einen bösen Verdacht. Freezemon macht ein paar Dinge jede Minute (Überprüfen ob apptime läuft, wenn das Attribut gesetzt ist etc...). Mir ist nicht wirklich klar, wie das einen Freeze verursachen könnte, aber das würde auch erklären, warum dein Log nicht so aussieht, wie es aussehen sollte.
Das sollten wir heute abend mal genauer untersuchen...

Grüße,

Oli

Jederzeit.

Und danke.

KernSani · 22 März 2018, 23:43:26

Hi Tom,

ich habe das nochmal gecheckt. Eigentlich macht freezemon nur wenige Dinge jede Minute:
1.) Checken ob apptime läuft und ggf. starten - kannst du einfach unterbinden, indem du fm_forceApptime löschst oder auf 0 setzt
2.) Checken ob wir einen neuen Tag haben und - wenn ja - die lastDay values setzen (das sollte wirklich keinen Freeze verursachen)
3.) ALte log files löschen - kannst du einfach unterbinden, indem du fm_logKeep löschst.

Kannst du 1. und 3. mal ausprobieren und zusätzlich ein list des freezemon-devices posten?

Danke,

Oli