Neues Modul: 98_FREEZEMON Freezes monitoren und Verursacher identifizieren

michael.winkler · 08 März 2018, 09:15:59

Bei mir im LOG erscheinen zur Zeit immer wieder folgende Einträge:


2018.03.08 07:01:24 1: PERL WARNING: Use of uninitialized value $link in concatenation (.) or string at ./FHEM/98_freezemon.pm line 837.
2018.03.08 07:01:24 1: stacktrace:
2018.03.08 07:01:24 1:     main::__ANON__                      called by ./FHEM/98_freezemon.pm (837)
2018.03.08 07:01:24 1:     main::freezemon_logLink             called by ./FHEM/98_freezemon.pm (290)
2018.03.08 07:01:24 1:     main::freezemon_ProcessTimer        called by fhem.pl (3089)
2018.03.08 07:01:24 1:     main::HandleTimeout                 called by fhem.pl (618)

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

Zitat von: michael.winkler am 08 März 2018, 09:15:59
Bei mir im LOG erscheinen zur Zeit immer wieder folgende Einträge:

Code Auswählen Erweitern
2018.03.08 07:01:24 1: PERL WARNING: Use of uninitialized value $link in concatenation (.) or string at ./FHEM/98_freezemon.pm line 837. 2018.03.08 07:01:24 1: stacktrace: 2018.03.08 07:01:24 1: main::__ANON__ called by ./FHEM/98_freezemon.pm (837) 2018.03.08 07:01:24 1: main::freezemon_logLink called by ./FHEM/98_freezemon.pm (290) 2018.03.08 07:01:24 1: main::freezemon_ProcessTimer called by fhem.pl (3089) 2018.03.08 07:01:24 1: main::HandleTimeout called by fhem.pl (618)

Hi Michael,
habe aktuell keinen Zugriff, da ich beruflich unterwegs bin, aber auch ohne das Cosing zu sehen ist mir klar wo der Fehler liegt - werde ich am Wochenende fixen (Du hast das neue fm_fileLog Attribut nicht gepflegt, richtig?)
Grüße,
Oli

michael.winkler · 09 März 2018, 07:40:21

Zitat von: KernSani am 08 März 2018, 23:34:42
Hi Michael,
habe aktuell keinen Zugriff, da ich beruflich unterwegs bin, aber auch ohne das Cosing zu sehen ist mir klar wo der Fehler liegt - werde ich am Wochenende fixen (Du hast das neue fm_fileLog Attribut nicht gepflegt, richtig?)
Grüße,
Oli

ja, das ist richtig

Gisbert · 11 März 2018, 09:17:17

Hallo Oli,

Ich bin auf dein Modul aufmerksam geworden und versuche es gerade zu nutzen.
Da ich seit ca. 1.5 Stunden noch keinen freeze hatte, und deshalb noch keine Erfahrungswerte bei mir vorliegen, wollte ich fragen, wie ich das folgende Attribut verstehen muss:

Code Auswählen

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

Heißt das, dass bei LogLevel 1 viel geloggt wird?
Bei verbose ist es aber genau umgekehrt.

Vielen Dank
Gisbert

KernSani · 11 März 2018, 09:31:54

Hallo Gisbert,
das Attribut sorgt dafür dass du nur die kritischen Freezes siehst. Nehmen wir an, verbose ist auf 2, dann würdest du - mit den angegebenen Beispielwerten - nur Freezes ab einer Dauer von 5 Sekunden sehen, da diese mit level 2 (oder ab 10 Sekunden sogar mit level 1) geloggt werden.
War das verständlich?

Zum Testen habe ich übrigens ein AT, in dem ich einfach ein perl-sleep aufrufe

Kurz, weil mobil...

Gisbert · 11 März 2018, 09:46:04

Hallo Oli,

dankeschön, deine Erklärung ist jetzt verständlich.

Noch 3 Fragen:
Was ist eine sinnvolle Zeit für das Attribut fm_logExtraSeconds? Ist 60 Sekunden viel zu lang?
Ist es richtig, dass der Logfile der mit dem Attribut fm_logFile erzeugt wird, nicht in der Übersicht (FileLog) in Fhem erscheint, sondern nur im Fileverzeichnis im RPi?
Wie sieht dein Test "AT ... sleep" genau aus?

Viele Grüße Gisbert

KernSani · 11 März 2018, 10:11:29

Hi Gisbert,
Ja, 60 Sekunden sind viel zu viel. Default (1 Sekunde) reicht normalerweise.
Das Logfile das erzeugt wird, wird nur in den angegebenen Folder gedumpt. Erreichbar ist es auch über die Übersicht, die man mit ,,get freezes" erhält

Code Auswählen

define myat at +00:00:02 {sleep(2)}

Kurz, weil mobil...

PatrickR · 11 März 2018, 15:44:29

Mahlzeit!

Eine kurze Frage: Das Plotbeispiel für die Zahl der Freezes pro Tag plottet ja um einen Tag versetzt durch die Nutzung von fcDayLast, d. h. dem 10.03. wird der Wert vom 09.03. zugeordnet. Gibt es dafür eine elegante Lösung?

Patrick

KernSani · 11 März 2018, 17:19:57

Zitat von: PatrickR am 11 März 2018, 15:44:29
Mahlzeit!

Eine kurze Frage: Das Plotbeispiel für die Zahl der Freezes pro Tag plottet ja um einen Tag versetzt durch die Nutzung von fcDayLast, d. h. dem 10.03. wird der Wert vom 09.03. zugeordnet. Gibt es dafür eine elegante Lösung?

Patrick

Ich arbeite mit logproxy und einem negativem Offset...

KernSani · 11 März 2018, 17:24:23

Neue Version ist eingecheckt und steht morgen mit dem Update zur Verfügung:
1.) das zusätzliche Logfile (fm_logFile), das mitunter einige hundert EInträge haben kann, wird jetzt non-blocking geschrieben
2.) ein neues Attribut fm_whitelistSub ermöglicht es Subs, die permanent etwas tun (und daher immer bei "possibly caused by" auftauchen) zu ignorieren.
3.) Die Warnung (siehe Michaels Beitrag etwas weiter oben) kommt nicht mehr und ein/zwei andere kleine Bugfixes.

michael.winkler · 13 März 2018, 06:51:49

Hi,

leider habe ich immer noch Fehlermeldungen in meinem LOG

Code Auswählen


2018.03.13 03:21:19.414 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/98_freezemon.pm line 190.
2018.03.13 03:21:19.414 3: eval: {freezemon_freezeDone('myFreezemon')}
2018.03.13 03:21:19.414 1: stacktrace:
2018.03.13 03:21:19.414 1:     main::__ANON__                      called by ./FHEM/98_freezemon.pm (190)
2018.03.13 03:21:19.414 1:     main::freezemon_freezeDone          called by (eval 3420) (1)
2018.03.13 03:21:19.414 1:     (eval)                              called by fhem.pl (1095)
2018.03.13 03:21:19.414 1:     main::AnalyzePerlCommand            called by fhem.pl (1118)
2018.03.13 03:21:19.414 1:     main::AnalyzeCommand                called by fhem.pl (1042)
2018.03.13 03:21:19.414 1:     main::AnalyzeCommandChain           called by ./FHEM/98_telnet.pm (241)
2018.03.13 03:21:19.414 1:     main::telnet_Read                   called by fhem.pl (3546)
2018.03.13 03:21:19.414 1:     main::CallFn                        called by fhem.pl (706)

Gruß
Michael

KernSani · 13 März 2018, 07:24:16

Oh Mann, ich Hirsch...Den einen Bug gefixt, aber bei der Umstellung auf non-Blocking den gleichen Fehler nochmal gemacht. Sorry, kommt heute Abend...

Kurz, weil mobil...

KernSani · 13 März 2018, 22:27:40

Hi Michael,

Ich kann die Warnung bei mir leider nicht nachstellen... EIgentlich sollte die Sub garnicht ausgeführt werden, wenn du kein fm_logfile gepflegt hast, aber selbst wenn, dann dürfte keine WARNING kommen. Könntest du ein list von myFreezemon posten?

Danke,

Oli

michael.winkler · 13 März 2018, 22:32:17

Zitat von: KernSani am 13 März 2018, 22:27:40
Hi Michael,

Ich kann die Warnung bei mir leider nicht nachstellen... EIgentlich sollte die Sub garnicht ausgeführt werden, wenn du kein fm_logfile gepflegt hast, aber selbst wenn, dann dürfte keine WARNING kommen. Könntest du ein list von myFreezemon posten?

Danke,

Oli

anbei ein List ...

Code Auswählen


Internals:
   NAME       myFreezemon
   NR         55
   NTFY_ORDER 99-myFreezemon
   STATE      s:07:00:08 e:07:00:09 f:1.092 d:HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A)
   TYPE       freezemon
   VERSION    0.0.17
   READINGS:
     2018-03-13 07:00:09   fcDay           9
     2018-03-13 00:01:15   fcDayLast       3
     2018-03-13 07:00:09   freezeDevice    HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A)
     2018-03-13 07:00:09   freezeTime      1.092
     2018-03-13 07:00:09   ftDay           1083.85
     2018-03-13 00:01:15   ftDayLast       3.43
     2018-03-13 07:00:09   state           s:07:00:08 e:07:00:09 f:1.092 d:HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A)
   helper:
     DISABLED   0
     TIMER      1520976683
     apptime    1520976689.68532-echodevice_GetSettings:ECHO_G000MW07735605DQ 1520976689.7019-echodevice_GetSettings:Amazon.echo 1520976689.96264-echodevice_GetSettings:ECHO_G090LV0363720DLW 1520976689.96495-echodevice_GetSettings:ECHO_G090L90964350E96 1520976690.39603-echodevice_GetSettings:ECHO_G090LF0964830SVM 1520976690.39903-echodevice_GetSettings:ECHO_G090L90964430DS6 1520976690.40217-echodevice_GetSettings:ECHO_774e1637fa004eae8a62a05adf3fdf64 1520976693.90135-echodevice_GetSettings:ECHO_G090L910732605D0 1520976702-FW_closeInactiveClients:N/A 1520976723.45121-echodevice_GetSettings:ECHO_f97a21db1d8e4f58b1e9e9936bd48051 1520976723.45142-echodevice_GetSettings:ECHO_960afe2ab0ad494c9256e39d443b0a90 1520976986.78941-CUL_HM_ActCheck:N/A 1520981940-at_Exec:FHEM.Backup 1520981940-at_Exec:MariaDB.Backup 1520982000-at_Exec:reboot 1520982001-FileLog_dailySwitch:N/A 1521039615.48292-CUL_HM_statCntRfresh:N/A 
     fn         
     freeze     1.09249305725098
     intCount   6
     logfile    
     msg        [Freezemon] myFreezemon: possible freeze starting at 07:00:08, delay is 1.092 possibly caused by: HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A) HttpUtils_Err(N/A)
     now        1520920809.09249
     logqueue:
Attributes:
   room       ZZ_FHEM

KernSani · 13 März 2018, 22:56:07

Danke für die schnelle Antwort... Ich bekomme es aber immernoch nicht nachgestellt (und kann es auch nicht logisch nachvollziehen, wie es an der Stelle zu einer WARNING kommen kann).

Angehängte Version sollte das Problem aber trotzdem beheben. Wäre dankbar für ein kurzes Feedback.

Danke,

Oli