Neues Modul: 98_FREEZEMON Freezes monitoren und Verursacher identifizieren

[sledge]

Moin,

also in der Nacht haben sich natürlich die erwarteten 400++ freezes angesammelt Immerhin ist Verlass auf das Phänomen.

Habe jetzt die von Dir vorgeschlagenen Änderungen durchgeführt, das Device nochmal neu initialisiert (nicht, dass da noch bit-rot rumliegt) und schaue zu, wie der Zähler minütlich hochgeht.

Alle 62-64 Sekunden wieder zuverlässig der Eintrag. Vermutlich werde ich am Wochenende tatsächlich mal Device für Device rauslöschen.

Code Auswählen Erweitern

Internals:
   CFGFN     
   NAME       freeze
   NR         515
   NTFY_ORDER 99-freeze
   STATE      s:08:10:19 e:08:10:22 f:3.009 d:no bad guy found :-(
   TYPE       freezemon
   VERSION    0.0.16
   READINGS:
     2018-03-23 08:10:22   fcDay           4
     2018-03-23 08:07:04   fcDayLast       0
     2018-03-23 08:10:22   freezeDevice    no bad guy found :-(
     2018-03-23 08:10:22   freezeTime      3.009
     2018-03-23 08:10:22   ftDay           10.968
     2018-03-23 08:07:04   ftDayLast       0
     2018-03-23 08:10:22   state           s:08:10:19 e:08:10:22 f:3.009 d:no bad guy found :-(
   helper:
     DISABLED   0
     TIMER      1521789031
     apptime    1521789030.56895-at_Exec:SZ.OG.CUL.at 1521789038.37998-PRESENCE_StartLocalScan:KL.OG.FTV.pres
     fn         
     freeze     3.00900793075562
     intCount   2
     logfile    ./log/freeze-20180323-081022.log
     msg        [Freezemon] freeze: possible freeze starting at 08:10:19, delay is 3.009 possibly caused by: no bad guy found :-(
     now        1521789022.00901
     logqueue:
       ARRAY(0x56400bfdbc08)
       ARRAY(0x56400bf002f0)
       ARRAY(0x56400bfa02b8)
       ARRAY(0x56400bde7d48)
       ARRAY(0x56400beeb758)
       ARRAY(0x56400bfba460)
       ARRAY(0x56400bf01780)
       ARRAY(0x56400bfc5740)
       ARRAY(0x56400bf93e08)
       ARRAY(0x56400b3297d0)
       ARRAY(0x56400bf8ce38)
       ARRAY(0x56400bf55cc0)
       ARRAY(0x56400bfbbc00)
       ARRAY(0x56400beeacf0)
       ARRAY(0x56400bf48d18)
       ARRAY(0x56400be156f0)
Attributes:
   fm_extDetail 1
   fm_forceApptime 0
   fm_freezeThreshold 2
   fm_logFile ./log/freeze-%Y%m%d-%H%M%S.log
   room       ,system


Ein paar Minuten weiter und ich habe wieder folgende Meldungen beisammen:

Code Auswählen Erweitern

1 - 2018-03-23 [Log]: s:08:07:10 e:08:07:13 f:3.007 d:no bad guy found :-(
1 - 2018-03-23 [Log]: s:08:08:14 e:08:08:16 f:2.452 d:PWM_Calculate(FBH.COMF.PWM) DbLog_execmemcache(dblog) TSCUL_SendPingHM(N/A)
1 - 2018-03-23 [Log]: s:08:09:17 e:08:09:19 f:2.5 d:PWM_Calculate(FBH.COMF.PWM) DbLog_execmemcache(dblog) TSCUL_SendPingHM(N/A) JeeLink_OnTimer(N...
1 - 2018-03-23 [Log]: s:08:10:19 e:08:10:22 f:3.009 d:no bad guy found :-(
1 - 2018-03-23 [Log]: s:08:11:23 e:08:11:25 f:2.363 d:PWM_Calculate(FBH.COMF.PWM) LaCrosseGateway_OnConnectTimer(KU.ELW.LGW) DbLog_execmemcache(d...
1 - 2018-03-23 [Log]: s:08:12:26 e:08:12:28 f:2.354 d:PWM_Calculate(FBH.COMF.PWM) DbLog_execmemcache(dblog) TSCUL_SendPingHM(N/A)
1 - 2018-03-23 [Log]: s:08:13:28 e:08:13:31 f:3.014 d:FW_closeInactiveClients(N/A)


Bin echt clueless - zumal ich beide regelmäßig auftretende Devices (PWM/PWMR zur Heizungssteuerung und DBLOG) schon gelöscht habe - dann rutschen nur andere Kandidaten nach und es gibt mehr "no bad guys found" Meldungen. Bleibt wohl nur systematisches Löschen der devices - und bei den klassischen IO-Devs (MAX, TSCUL, 1-wire, Lacrosse Gateway...) habe ich bisher diesen Schritt nicht machen wollen.

Danke in jedem Fall für die Hilfe.

Tom

[sledge]

So,

gelöst.

Es blieb ja nichts anderes übrig als Device für Device zu löschen und zu schauen, ob die Freezes aufhören. Angefangen bei 20 Fensterkontakten,15 Homematic devices, der gesamten PWM-Steuerung für die Fußbodenheizung und 17 Heizkreisläufe, sämtliche Timer... bis hin zu den IO-Devices (CUL, 1wire, CUN, HM-CFG-LAN...)

Naja, am Ende ist es immer so, dass erst ganz am Ende der Freeze ausblieb... als ich eine XBMC-Definition gelöscht habe (jetzt KODI).

Von vermeintlich 4 XBMC-Devices war bei dem fraglichen Device das "fork" Attribut nicht gesetzt - und das hat bei ausgeschalteten XBMC dafür gesorgt, dass regelmäßig diese Freezes auftraten. Steht sogar in der commandref. Wäre ich aber trotz mehrfachen Lesens nicht drauf gekommen, da ich solche Attribute über cmdalias direkt auf alles Devices eines Typs setze.

Egal.

Danke an alle, die mir bei der Suche geholfen haben, insbesondere an KernSani für freezemon, hermannj für perfmon und alle anderen, die mir via PM oder Antwort Tips gegeben haben.

Endlich ein nahezu freezefreier FHEM-Server.

Danke, Tom

[KernSani]

Ist ja cool, dass du es gefunden hast, was mich aber sehr irritiert, ist das der Kodi nicht in den "possibly caused by" auftaucht. Ich habe mir das Modul angesehen und es verwendet (wie nicht anders zu erwarten) die ganz normale InternalTimer Funktion - und die sollte Freezemon eigentlich finden...Kannst du mal noch eines der logfiles posten?
Btw.: Ich würde dir empfehlen, das fm_logKeep Attribut zu setzen (bei mir steht es auf 100), sonst müllt dir Freezemon die Platte voll...

[KölnSolar]

Hi Oli,

über folgenden Fall bin ich etwas verwundert

Code Auswählen Erweitern

2018.03.24 04:57:06 3: FRITZBOX: get Fritzbox tr064Command WANIPConnection:1 wanipconnection1 ForceTermination
2018.03.24 04:57:07 2: FRITZBOX Fritzbox: TR064_Cmd.4302 TR064-Error 707:DisconnectInProgress (service='WANIPConnection:1', control='wanipconnection1', action='ForceTermination')
2018.03.24 04:57:07 3: act_on_FB_Inet_check return value: Service='WANIPConnection:1'   Control='wanipconnection1'   Action='ForceTermination'
----------------------------------------------------------------------
$VAR1 = {
          'UPnPError' => {
                           'errorDescription' => 'DisconnectInProgress',
                           'errorCode' => '707'
                         }
        };

2018.03.24 04:57:12 1: [Freezemon] freezedetect: possible freeze starting at 04:57:07, delay is 5.873 possibly caused by: NEUTRINO_GetStatus(DBox) at_Exec(check_jammer) echodevice_GetSettings(echo) GPIO4_DeviceUpdateLoop(RPi_OW_KS)
2018.03.24 04:57:13 3: [Freezemon] freezedetect: possible freeze starting at 04:57:13, delay is 0.507 possibly caused by: GPIO4_DeviceUpdateLoop(RPi_OW_VT) GPIO4_DeviceUpdateLoop(RPi_OW_RT) GPIO4_DeviceUpdateLoop(RPi_OW_WW) GPIO4_DeviceUpdateLoop(RPi_OW_WZ) GPIO4_DeviceUpdateLoop(RPi_OW_TC1) GPIO4_DeviceUpdateLoop(RPi_OW_TCar) GPIO4_DeviceUpdateLoop(RPi_OW_TK) GPIO4_DeviceUpdateLoop(RPi_OW_SL) GPIO4_DeviceUpdateLoop(RPi_OW_ZW) fitbit_poll(fitbit_D485470325) SYSMON_Update(sys_mon) STV_Init(Fernseher) fitbit_poll(fitbit_U62ZJV3) HttpUtils_Err(N/A) GPIO4_DeviceUpdateLoop(RPi_OW_WWL) at_Exec(check_jammer) HttpUtils_Err(N/A) BlockingKill(N/A)
2018.03.24 04:57:13 3: [Freezemon] freezedetect: dumping 41 log entries to ./log/freeze-20180324.log
2018.03.24 04:57:13 3: [Freezemon] freezedetect: dumping 79 log entries to ./log/freeze-20180324.log


Der Verursacher ist klar. Aber wieso ein kurzer freeze während einem langen  Ggfs. kann ich das Freeze-Log zur Verfügung stellen.

Könntest Du die Ausgabe der "gedumpten Log-Entries" auf Level 4 oder 5 stellen ? Hat irgendwie nicht so wirklich einen besonderen Informationsgehalt und macht das Log aber unübersichtlicher/voller.

<OT> hier könnte ich Dich unterstützen<OT>

Grüße Markus

[KernSani]

Hi Markus,

die Freezes kommen direkt hintereinander. Die Dumpausgabe erfolgt per blockingCall und kommt deshalb verzögert.
Loglevel ist bei meiner aktuellen Testversion schon geändert (hat mich auch genervt )
Bez. Offtopic: Danke


Kurz, weil mobil...

[sledge]

Ist ja cool, dass du es gefunden hast, was mich aber sehr irritiert, ist das der Kodi nicht in den "possibly caused by" auftaucht. Ich habe mir das Modul angesehen und es verwendet (wie nicht anders zu erwarten) die ganz normale InternalTimer Funktion - und die sollte Freezemon eigentlich finden...Kannst du mal noch eines der logfiles posten?
Btw.: Ich würde dir empfehlen, das fm_logKeep Attribut zu setzen (bei mir steht es auf 100), sonst müllt dir Freezemon die Platte voll...

Siehe PM - bei logfiles ist das so ne Sache


Danke für den Tip mit den Logfiles - aber da läuft bei mir logrotate...

[Amenophis86]

Wie bekomme ich diese Meldung weg:

Code Auswählen Erweitern

MQTT((Timer(Mosquitto)

Weder fm_ignoreDev Mosquitto noch fm_whitelistSub MQTT hat geholfen. Irgendwas mache ich falsch. Das Device heißt Mosquitto und die Funktion doch MQTT, wenn ich das richtig sehe, oder nicht?

[KernSani]

Hi Etienne,

irgendwie sieht das komisch aus... die Klammersetzung stimmt nicht...
Das Device Mosquitto ist korrekt, aber die sub die aufgerufen wird ist MQTT::Timer. Da der Doppelpunkt bei Freezemon als Trennzeichen verwendet wird, scheint das nicht korrekt aufgelöst (und später bei der Ausgabe dann nicht korrekt formatiert) zu werden. Du kannst mal versuchen, "MQTT::Timer" in die whitelist aufzunehmen.

Grüße,

Oli     

[Amenophis86]

Na schau an, werde ich heute Abend mal versuchen. Dank dir.

[KernSani]

Hallo zusammen,

ich nehme gerade einen größeren (internen) Umbau an Freezemon vor. in diesem Zuge würde ich gerne zwei Attribute entfernen, da ich sie persönlich für unnötig halte, würde aber gerne eure Meinung dazu hören:
* disable: die Funktionalität ist durch set inactive/active abgedeckt. die Kombination der beiden kann meiner Meinung nach nur zu Verwirrung führen.
* fm_logExtraSeconds: Aus meiner persönlichen Erfahrung macht es keinen Sinn hier einen Sekundenwert anzugeben, der default (1 Sekunde vor Beginn des Freezes) ist m.E. ausrecihend

Wenn irgendwer diese Attribute nutzt, bitte melden, ansonsten werde ich sie ausbauen.

Grüße,

Oli

[Amenophis86]

Ich persönlich bin ja lieber ein Freund von disable, als von einem eigenen inactive oder so. Finde das passt besser zum gesamt System, weil es auch bei anderen Modulen so ist.

[Motivierte linke Hände]

Ja, wollte auch gerade schreiben, dass das disable-Attribut der in fhem deutlich üblicher zu sein scheint.

[KölnSolar]

* disable: die Funktionalität ist durch set inactive/active abgedeckt

mir egal. Habs immer aktiv. Immer interessant. 

* fm_logExtraSeconds: Aus meiner persönlichen Erfahrung macht es keinen Sinn hier einen Sekundenwert anzugeben

braucht man nicht.

[KernSani]

Ich persönlich bin ja lieber ein Freund von disable, als von einem eigenen inactive oder so. Finde das passt besser zum gesamt System, weil es auch bei anderen Modulen so ist.

Ok, dann lass ich das drin... Attribut benötigt nur immer ein "Save"... Ich schau mir mal genau an, wie andere Module (z.B. "at") das handhaben, wenn active/inactive und disable nicht zusammen passen.

[CoolTux]

Nimm lieber das Attribut dann kannst mit der Funktion

Code Auswählen Erweitern


IsDisabled($name)

abfragen.