Neues Modul: 98_FREEZEMON Freezes monitoren und Verursacher identifizieren

[sledge]

Hi,

keine konkrete Idee für den Verursacher, aber eine Idee, wie man dem auf die Schliche kommt.

1. Mittels Apptime versuchen, die Prozesse zu identifizieren, die ebenfalls minütlich ablaufen
2. Das Logging generell auf 5 hochdrehen und mit "tail -f <logfile>" auf Hinweise spähen (bei mir hat der freezemon-Logauszug nicht immer gepasst)

Somit habe ich bei mir einige freezes aus dem System beseitigt. Dann blieb noch einer im Minutentakt. Am Ende habe ich alles devices gelöscht, Stück für Stück, bis der Freeze ausblieb. Hat funktioniert, seitdem habe ich ein (nahezu) freeze-freies System - von einem Freeze pro Tag mal abgesehen, aber den kenne ich

Gruß,
Tom

[Marlen]

War STV für meinen Fernseher....  geht aber aus der Meldung nicht hervor!

LG
  Marlen

Gesendet von meinem Aquaris U Plus mit Tapatalk

[florian2833]

teste und lese mit

[t1me2die]

Moin Oli,

ich probiere gerade dein Modul aus.
Ich habe lediglich die Definition vorgenommen und schon fingen an sich die Readings zu füllen.

Hier mal ein kurzer Auszug

Code Auswählen Erweitern


1 - 2018-09-11 [Log]: s:10:02:54 e:10:02:57 f:3.052 d:no bad guy found :-(
1 - 2018-09-11 [Log]: s:10:03:14 e:10:03:16 f:2.212 d:HMUARTLGW_CheckCredits(N/A) HMUARTLGW_CheckCredits(N/A)
1 - 2018-09-11 [Log]: s:10:03:57 e:10:04:00 f:3.006 d:no bad guy found :-(
1 - 2018-09-11 [Log]: s:10:04:16 e:10:04:19 f:3.005 d:no bad guy found :-(
1 - 2018-09-11 [Log]: s:10:05:00 e:10:05:03 f:3.007 d:PRESENCE_StartLocalScan(PRESENCE_rr_Mathze) BlockingKill(N/A)
1 - 2018-09-11 [Log]: s:10:05:19 e:10:05:22 f:3.006 d:HttpUtils_Err(N/A)
1 - 2018-09-11 [Log]: s:10:06:03 e:10:06:06 f:3.007 d:PRESENCE_StartLocalScan(PRESENCE_rr_Mathze) BlockingKill(N/A)
1 - 2018-09-11 [Log]: s:10:06:23 e:10:06:25 f:2.081 d:HMUARTLGW_CheckCredits(N/A) HMUARTLGW_CheckCredits(N/A) PRESENCE_StartLocalScan(PRESENCE_rr_Mathze) BlockingKill(N/A)
1 - 2018-09-11 [Log]: s:10:07:07 e:10:07:09 f:2.172 d:MQTT((Timer(myBroker) SIGNALduino_KeepAlive(SIGNALduino) HUEBridge_GetUpdate(HueBridge) DLCD_GetUpdate(dlcd_WeMoS_LCD) SONOS_IsSub...
1 - 2018-09-11 [Log]: s:10:07:26 e:10:07:28 f:2.094 d:HMUARTLGW_CheckCredits(N/A) HMUARTLGW_CheckCredits(N/A)
1 - 2018-09-11 [Log]: s:10:07:36 e:10:07:41 f:5.319 d:at_Exec(check_Rollo) BlockingKill(N/A)
1 - 2018-09-11 [Log]: s:10:08:10 e:10:08:12 f:2.116 d:MQTT((Timer(myBroker) SIGNALduino_KeepAlive(SIGNALduino) HUEBridge_GetUpdate(HueBridge)
1 - 2018-09-11 [Log]: s:10:08:29 e:10:08:31 f:2.467 d:HMUARTLGW_CheckCredits(N/A) HMUARTLGW_CheckCredits(N/A) at_Exec(at_fl_Zeit)
1 - 2018-09-11 [Log]: s:10:09:12 e:10:09:15 f:3.043 d:PRESENCE_StartLocalScan(QNAP) BlockingKill(N/A)
1 - 2018-09-11 [Log]: s:10:09:31 e:10:09:34 f:3.019 d:no bad guy found :-(
1 - 2018-09-11 [Log]: s:10:10:16 e:10:10:18 f:2.219 d:MQTT((Timer(myBroker) SIGNALduino_KeepAlive(SIGNALduino) HUEBridge_GetUpdate(HueBridge) DLCD_GetUpdate(dlcd_WeMoS_LCD) SONOS_IsSub...
1 - 2018-09-11 [Log]: s:10:10:35 e:10:10:37 f:2.188 d:HMUARTLGW_CheckCredits(N/A) HMUARTLGW_CheckCredits(N/A)
1 - 2018-09-11 [Log]: s:10:11:19 e:10:11:21 f:2.203 d:MQTT((Timer(myBroker) SIGNALduino_KeepAlive(SIGNALduino) HUEBridge_GetUpdate(HueBridge) DLCD_GetUpdate(dlcd_WeMoS_LCD) SONOS_IsSub...
1 - 2018-09-11 [Log]: s:10:11:38 e:10:11:40 f:2.247 d:HMUARTLGW_CheckCredits(N/A) HMUARTLGW_CheckCredits(N/A) ESPEasy_statusRequest(WeMos_LCD)
1 - 2018-09-11 [Log]: s:10:12:22 e:10:12:24 f:2.178 d:MQTT((Timer(myBroker) SIGNALduino_KeepAlive(SIGNALduino) HUEBridge_GetUpdate(HueBridge) DLCD_GetUpdate(dlcd_WeMoS_LCD) SONOS_IsSub...
1 - 2018-09-11 [Log]: s:10:12:41 e:10:12:43 f:2.225 d:HMUARTLGW_CheckCredits(N/A) HMUARTLGW_CheckCredits(N/A)
1 - 2018-09-11 [Log]: s:10:13:24 e:10:13:27 f:3.012 d:no bad guy found :-(
1 - 2018-09-11 [Log]: s:10:13:44 e:10:13:46 f:2.293 d:HMUARTLGW_CheckCredits(N/A) HMUARTLGW_CheckCredits(N/A)
1 - 2018-09-11 [Log]: s:10:14:27 e:10:14:30 f:3.004 d:HttpUtils_Err(N/A)
1 - 2018-09-11 [Log]: s:10:14:46 e:10:14:49 f:3.006 d:no bad guy found :-(
1 - 2018-09-11 [Log]: s:10:15:30 e:10:15:33 f:3.006 d:no bad guy found :-(
1 - 2018-09-11 [Log]: s:10:15:50 e:10:15:52 f:2.058 d:HMUARTLGW_CheckCredits(N/A) HMUARTLGW_CheckCredits(N/A)
1 - 2018-09-11 [Log]: s:10:16:34 e:10:16:36 f:2.131 d:MQTT((Timer(myBroker) SIGNALduino_KeepAlive(SIGNALduino) HUEBridge_GetUpdate(HueBridge) DLCD_GetUpdate(dlcd_WeMoS_LCD) SONOS_IsSub...
1 - 2018-09-11 [Log]: s:10:16:53 e:10:16:55 f:2.155 d:HMUARTLGW_CheckCredits(N/A) HMUARTLGW_CheckCredits(N/A)
1 - 2018-09-11 [Log]: s:10:17:37 e:10:17:39 f:2.21 d:MQTT((Timer(myBroker) SIGNALduino_KeepAlive(SIGNALduino) HUEBridge_GetUpdate(HueBridge) DLCD_GetUpdate(dlcd_WeMoS_LCD) SONOS_IsSubp...


Man kann fast sagen, dass es im Minuten- / Sekundentakt zu neuen Einträgen kommt.

Einige Einträge, wie z.B. HMUARTLGW, PRESENCE sagt mir auch was. Hierbei handelt es sich ja um eins meiner HM Module (habe zwei, 1x WLAN und 1x USB), beim PRESENCE vermute ich Bluetooth.
Bei beiden Geräten habe ich aber aber keinerlei Einfluss auf die Freeze's.
Beim letzten Freeze in der Liste, habe ich eine Routine in meiner 99_myUtils, welche alle 15Minuten per AT aufgerufen wird, wieso hier ein Freeze von über 5Sekunden zustande kommt, ist mir bisher ein Rätsel.

Ich weiß nun leider nicht wie ich weiter vorgehen soll, um die Freezes zu entfernen?

Habe nun zuerst einmal auf die aktuellste Version 0.0.20 geupdatet.
Ich lege zuerst einmal mein Hauptaugenmerkt auf die bad guys.
Nachdem ich ein

Code Auswählen Erweitern

attr myFreezemon fm_CatchFnCalls 0
gemacht habe, hat FHEM den Dienst quittiert.
Musste FHEM per SSH und restart neustarten, danach lief es ohne das Attribut dann wieder.

Ein

Code Auswählen Erweitern

attr myFreezemon fm_CatchCmds 0
hat FHEM angenommen.


Gruß
Mathze

[hgw77]

Hallo,

irgendwie kann ich den Freezmon nicht laden,

das steht in der fhem.cfg

Code Auswählen Erweitern


define myFreezemon freezemon


und das steht dann im fhem log

Code Auswählen Erweitern


reload: Error:Modul 98_freezemon deactivated:
Global symbol "$FW_ME" requires explicit package name at ./FHEM/98_freezemon.pm line 1206, <$fh> line 17.

2018.09.13 07:50:32 0: Global symbol "$FW_ME" requires explicit package name at ./FHEM/98_freezemon.pm line 1206, <$fh> line 17.


fhem ist soweit aktuell, das letzte update ist ca 2 wochen her.

irgendwelche ideen?

[Amenophis86]

fhem ist soweit aktuell, das letzte update ist ca 2 wochen her.

Ähm nein, ist es nicht. Es ist zwei Wochen alt. Bring es doch mal auf den wirklich aktuellen Stand oder prüfe zumindest mit updatecheck, ob bei Freezmon etwas geändert wurde seit deinem letzten Update.

[PatrickR]

Mahlzeit!

Ich habe aktuell eine Reihe von Freezes der Art:

Code Auswählen Erweitern

Mon 08.10.2018 16:07:44  freezemon s:16:07:40 e:16:07:44 f:4.028 d:tmr-CODE(0x9952408)(__ANON__)
Kann man dem irgendwie weiter auf die Spur kommen? An Hand der Freezelogs habe ich zwar einen Verdacht, aber eine genauere Eingrenzung wäre hilfreich.

Patrick

[vbs]

Ich finde das Modul ja super, aber ich werde aus ihm einfach nicht schlau

Aktuelles Beispiel:
Ich hatte regelmäßig Freezes. Freezemon schlägt auch an. Das Log dazu:

Code Auswählen Erweitern

[Freezemon] sys_freezemon: possible freeze starting at 17:39:37, delay is 2.378 possibly caused by: tmr-DbLog_execmemcache(benDbLog) tmr-EspLedController_Check(ku_lightLedCeil) tmr-EspLedController_Check(wz_lightLedCouch) tmr-EspLedController_Check(wz_lightLedTv) tmr-EspLedController_Check(ku_lightLedFloor) tmr-EspLedController_Check(sz_lightLedWall) tmr-HMUARTLGW_CheckCredits(N/A) tmr-PRESENCE_StartLocalScan(sz_s8_pres)

2018.11.18 17:39:39.360 4: ku_lightLedCeil: EspLedController_CheckConnection: Connection still alive. Last data received 54.8333749771118 s ago

2018.11.18 17:39:39.360 4: wz_lightLedCouch: EspLedController_CheckConnection: Connection still alive. Last data received 49.5493350028992 s ago

2018.11.18 17:39:39.360 4: wz_lightLedTv: EspLedController_CheckConnection: Connection still alive. Last data received 13.2357280254364 s ago

2018.11.18 17:39:39.361 4: ku_lightLedFloor: EspLedController_CheckConnection: Connection still alive. Last data received 52.7793941497803 s ago

2018.11.18 17:39:39.361 4: sz_lightLedWall: EspLedController_CheckConnection: Connection still alive. Last data received 23.6232011318207 s ago

2018.11.18 17:39:39.361 5: HMUARTLGW sys_culHm checking credits (from timer)

2018.11.18 17:39:39.361 5: HMUARTLGW sys_culHm send: 00 08

2018.11.18 17:39:39.361 5: HMUARTLGW sys_culHm send: (8): fd0003005008f836

2018.11.18 17:39:39.361 5: SW: fd0003005008f836

2018.11.18 17:39:39.364 5: PRESENCE (sz_s8_pres) - stopping timer

2018.11.18 17:39:39.364 5: PRESENCE (sz_s8_pres) - starting blocking call for mode function

2018.11.18 17:39:39.377 4: BlockingCall (PRESENCE_DoLocalFunctionScan): created child (112068), uses telnetPort to connect back

2018.11.18 17:39:39.379 5: [Freezemon] sys_freezemon: ----------- Starting Freeze handling at 2018.11.18 17:39:39.379 ---------------------

[Freezemon] sys_freezemon: possible freeze starting at 17:39:37, delay is 2.378 possibly caused by: tmr-DbLog_execmemcache(benDbLog) tmr-EspLedController_Check(ku_lightLedCeil) tmr-EspLedController_Check(wz_lightLedCouch) tmr-EspLedController_Check(wz_lightLedTv) tmr-EspLedController_Check(ku_lightLedFloor) tmr-EspLedController_Check(sz_lightLedWall) tmr-HMUARTLGW_CheckCredits(N/A) tmr-PRESENCE_StartLocalScan(sz_s8_pres)

Verstehe nicht so ganz, welches jetzt der vermutete Übeltäter ist. Oder sind das hier einfach mehrere mögliche Kandidaten?

Code Auswählen Erweitern

tmr-DbLog_execmemcache(benDbLog) tmr-EspLedController_Check(ku_lightLedCeil) tmr-EspLedController_Check(wz_lightLedCouch) tmr-EspLedController_Check(wz_lightLedTv) tmr-EspLedController_Check(ku_lightLedFloor) tmr-EspLedController_Check(sz_lightLedWall) tmr-HMUARTLGW_CheckCredits(N/A) tmr-PRESENCE_StartLocalScan(sz_s8_pres)

Interessanterweise zeigte apptime nur genau ein Modul mit >1 Sekunde Delay an und das war mein Device "wz_tv" vom Typ "STV". Das taucht in der Freezemon-Liste jedoch nicht auf.

[Pfriemler]

Das mit den mehreren Kandidaten begreife ich jetzt auch langsam...

Ich stelle mich hier auch mal ganz doof und bitte um eine grobe Einschätzung oder einen Vergleich. fm_freezeThreshold = 4 Sekunden.
Ich habe in einem halben Monat fast 1200 Freezes in der Logdatei. "Verursacher" (ist ja nicht klar ob) sind diverse Kandidaten, mal kein "bad guy", mal ein Dutzend.
Bis zu 22 Sekunden werden gemeldet, wobei ich noch nie aktiv eine solche Verzögerung erlebt habe. Dass das System für 10 Sekunden mal nicht reagiert, kommt schon öfter vor, aber noch zu selten um sich ernsthaft einen Reim drauf machen zu können.
Um einen groben Überblick zu bekommen, habe ich mir kurz ein Proggi zusammengehauen, was die "möglichen Kandidaten" einzeln erfasst und die dazugehörigen Freeze-Zeiten. Nachfolgend nach Häufigkeit sortiert also Anzahl, Kandidat und Zeitspanne der Freezes. Ich erhoffte mir dadurch eine eindeutige Identifikation, aber das Ergebnis ist immer noch "querbeet".

Code Auswählen Erweitern

Freezeanalyzing for D:\VolkerDaten\Documents\Diverse\VB\UNDEF\fhem-2018-11.log
1183 freezes total

362x tmr-FileLog_dailySwitch(N/A), 4,29-5,22s
362x tmr-IrBlaster_TimerStatusRequest(IRBl3), 4-15s
362x tmr-MQTT::Timer(myBroker), 4-15s
362x tmr-ENIGMA2_GetStatus(DB500HD), 4-11,8s
362x tmr-IrBlaster_TimerStatusRequest(IRWz), 4-19,3s
307x tmr-IrBlaster_TimerStatusRequest(IRBl2), 4-15s
155x tmr-HMUARTLGW_CheckCredits(N/A), 4-19,3s
154x tmr-PRESENCE_StartLocalScan(GretkesHandy_WLAN), 4-13,9s
151x tmr-PRESENCE_StartLocalScan(RobotronFB), 4,02-15s
145x tmr-PRESENCE_StartLocalScan(RobertsHandy_FB), 4,02-15s
129x tmr-PRESENCE_StartLocalScan(VolkersHandy_FB), 4,02-15s
112x tmr-PRESENCE_StartLocalScan(VolkersEifonFB), 4-15s
108x tmr-PRESENCE_StartLocalScan(GretkesHandy_FB), 4-15s
107x tmr-PRESENCE_StartLocalScan(TeufelConnector1), 4-19,3s
107x tmr-sequence_Trigger(N/A), 5,33-5,33s
107x tmr-CUL_HM_respPendTout(N/A), 4,01-13,6s
107x tmr-PRESENCE_StartLocalScan(PhilipsTV), 4,03-15s
105x tmr-FW_closeInactiveClients(N/A), 4-13,6s
103x tmr-PRESENCE_StartLocalScan(VolkersPCPing), 4-13,6s
84x tmr-DOIF_SleepTrigger(FK_KGSuedL), 4,08-5,99s
83x tmr-PRESENCE_StartLocalScan(TeufelConnector3), 4,03-15s
81x tmr-HMUARTLGW_CheckCmdResp(HMUART), 4,05-15s
76x tmr-HMUARTLGW_CheckCmdResp(HMWLAN1), 4,05-15s
67x no bad guy found :-(, 4-22,5s
64x tmr-CUL_HandleWriteQueue(CUL1), 4,07-10,3s
62x tmr-DOIF_SleepTrigger(di_AlarmanlageLicht), 4,49-9,26s
56x tmr-PRESENCE_StartLocalScan(VolkersHandy_WLAN), 4-14,4s
53x tmr-PRESENCE_StartLocalScan(VolkersHandy_BT), 4,02-12,9s
48x tmr-BlockingKill(N/A), 4,22-15s
44x tmr-DOIF_TimerTrigger(di_LogPresenceEveryHour), 4,03-7,5s
43x tmr-DOIF_TimerTrigger(di_SaveDewpoints), 4,01-7,77s
41x tmr-DOIF_TimerTrigger(di_SaveIndoorValues), 4,01-7,77s
38x tmr-DOIF_TimerTrigger(di_SaveOutdoorValues), 4,01-7,77s
35x tmr-DOIF_TimerTrigger(di_UpdateFHEMStatusOnHMSA), 4,01-15s
31x tmr-HMUARTLGW_SendPendingTimer(HMWLAN1), 4,08-6,67s
29x tmr-PRESENCE_StartLocalScan(GretkesHandy_BT), 4,02-15s
28x tmr-PRESENCE_StartLocalScan(BennisIPhone), 4,01-12s
14x tmr-PRESENCE_StartLocalScan(Dreambox), 4,23-11,4s
13x tmr-HttpUtils_Err(N/A), 4-21,1s
12x tmr-PRESENCE_StartLocalScan(RobertsHandy_WLAN),


Irgendwie werde ich den Eindruck nicht los, dass hier eigentlich ein ganz anderes Problem vorliegt. Es sind auffallend viele Aktionen, die mit dem Netzwerk zu tun haben, meist Erreichbarkeitstests (PRESENCE - aber auch Bluetooth, IR-Blaster, HMLAN-WLAN-Gateway, ENIGMA), aber auch DOIFs. Aber auch die "no bad guys" sind nicht selten - und die längsten Freezes.
Ich gehe den 15-Sekunden-Freezes auch mal näher. Außerdem werde ich mal eine neue Speicherkarte avisieren, wobei die meisten Freezes definitiv keine Speicherkartenaktionen auslösen oder davon abhängen. Bis dahin:

Irgendeiner ne Idee was da nicht läuft?

edit: PRESENCE mit _FB sind Fritzbox-Abfragen, und die rangieren ja wirklich recht weit vorn.

[vbs]

Ich hab wenig Glück generell, mit dem Freezemon den Verursacher zu identifizieren... Was sagt denn "apptime" bei dir?

Und mir ist auch öfter aufgefallen, dass freezemon einen Freeze meldet (sagen wir 2 s), aber apptime gar kein Delay festgestellt hat. Ist das erklärbar?

[frank]

Und mir ist auch öfter aufgefallen, dass freezemon einen Freeze meldet (sagen wir 2 s), aber apptime gar kein Delay festgestellt hat. Ist das erklärbar?

das kenne ich auch.
manchmal habe ich den verdacht, dass dann eventuell freezes von einem fhem-fork festgestellt werden. ist das technisch überhaupt möglich?

in die verursacher liste schaue ich schon gar nicht mehr. echte hinweise bringt eigentlich nur die log option, finde ich.

[KölnSolar]

in die verursacher liste schaue ich schon gar nicht mehr. echte hinweise bringt eigentlich nur die log option, finde ich.

Das sehe ich auch so. Wenn einmal die "schlimmsten" Verursacher identifiziert sind, wird es sehr zäh und freezemon liefert "nur" den Anstoß mal in das freeze-log zu gucken.

manchmal habe ich den verdacht, dass dann eventuell freezes von einem fhem-fork festgestellt werden. ist das technisch überhaupt möglich?

So einen Verdacht habe ich auch. Ich hatte zufällig heute Morgen einen 15 Sek. freeze im Log. Im freeze-Log war noch nicht einmal die typische Zeile ...---log skips.....  Davor aber ein "kurzer" freeze. Ich habs mal übersichtlich zusammenkopiert. Unverdächtige wie RFXTRX entfernt.

Code Auswählen Erweitern

=========================================================
[Freezemon] freezedetect: possible freeze starting at 07:53:40, delay is 1.177 possibly caused by: tmr-GPIO4_DeviceUpdateLoop(RPi_OW_VL)
2018.11.21 07:53:39.196 4: Connection accepted from telnetForBlockingFn_1542634689_127.0.0.1_55124
2018.11.21 07:53:39.201 5: Cmd: >{BlockingRegisterTelnet($cl,66153)}<
2018.11.21 07:53:39.245 5: Cmd: >{BlockingStart('66153')}<
2018.11.21 07:53:39.251 5: Cmd: >{SYSMON_blockingFinish('name|sys_mon|fhemuptime|148526|fhemstarttime_text|19.11.2018 14:38:13|fhemstarttime|1542634693|fhemuptime_text|1 days, 17 hours, 15 minutes')}<
2018.11.21 07:53:39.252 5: SYSMON sys_mon: blockingFinish.1041 name|sys_mon|fhemuptime|148526|fhemstarttime_text|19.11.2018 14:38:13|fhemstarttime|1542634693|fhemuptime_text|1 days, 17 hours, 15 minutes
2018.11.21 07:53:39.252 5: SYSMON sys_mon: updateReadings.1060
.
.
2018.11.21 07:53:39.631 4: https://layla.amazon.de/api/device-preferences: HTTP response code 200
2018.11.21 07:53:39.632 5: HttpUtils https://layla.amazon.de/api/device-preferences: Got data, length: 1045
2018.11.21 07:53:39.632 5: HttpUtils response header: .....
2018.11.21 07:53:39.632 4: [echomaster] [echodevice_Parse] [getdevicesettings]
2018.11.21 07:53:39.634 5: [echomaster] [echodevice_Parse] [getdevicesettings] DATA Dumper=$VAR1 = ...
2018.11.21 07:53:39.648 5: End notify loop for echomaster
2018.11.21 07:53:39.670 5: End notify loop for echo
2018.11.21 07:53:39.672 4: [echomaster] [echodevice_HandleCmdQueue] [listitems_shopping] send command=...
2018.11.21 07:53:39.672 5: HttpUtils url=https://layla.amazon.de/api/todos?size=......
2018.11.21 07:53:39.675 5: IP: layla.amazon.de -> 52.94.220.236
2018.11.21 07:53:39.945 5: HttpUtils request header: GET /api/todos?size=100&...type=SHOPPING_ITEM.....
2018.11.21 07:53:39.948 5: GPIO4: GPIO4_DeviceUpdateLoop(RPi_OW_VL), pollingInterval:40
2018.11.21 07:53:39.966 4: BlockingCall (GPIO4_Get): created child (19707), uses telnetForBlockingFn_1542634689 to connect back
2018.11.21 07:53:39.976 5: TRX/RAW: ...
.
.
2018.11.21 07:53:39.986 5: TRX_WEATHER: name=Mess_4 device=REVOLT_40da energy_freq=50
--- log skips     1.186 secs.
2018.11.21 07:53:41.173 5: End notify loop for Mess_4
2018.11.21 07:53:41.173 5: TRX_Read END
2018.11.21 07:53:41.175 4: Connection accepted from telnetForBlockingFn_1542634689_127.0.0.1_55128
2018.11.21 07:53:41.177 5: [Freezemon] freezedetect: ----------- Starting Freeze handling at 2018.11.21 07:53:41.177 ---------------------
[Freezemon] freezedetect: possible freeze starting at 07:53:40, delay is 1.177 possibly caused by: tmr-GPIO4_DeviceUpdateLoop(RPi_OW_VL)
=========================================================
[Freezemon] freezedetect: possible freeze starting at 07:53:42, delay is 15.067 possibly caused by: tmr-NEUTRINO_GetStatus(DBox)
2018.11.21 07:53:56.952 4: Connection accepted from WEB_192.168.178.35_65451
2018.11.21 07:53:56.953 5: Cmd: >{BlockingStart('66152')}<
2018.11.21 07:53:56.957 5: Cmd: >{GPIO4_GetfinishFn('RPi_OW_ZW|28|000005fab536|T: 1.437|1.437')}<
2018.11.21 07:53:56.958 5: GPIO4: GPIO4_GetfinishFn(RPi_OW_ZW) Start
2018.11.21 07:53:56.959 5: GPIO4: GPIO4_GetfinishFn(RPi_OW_ZW) End
2018.11.21 07:53:56.963 4: https://layla.amazon.de/api/todos?size=100&startTime=&endTime=&completed=false&type=SHOPPING_ITEM...
2018.11.21 07:53:56.963 5: HttpUtils https://layla.amazon.de/api/todos??size=100...&type=SHOPPING_ITEM...
2018.11.21 07:53:56.963 5: HttpUtils response header: .....
2018.11.21 07:53:56.963 4: [echomaster] [echodevice_Parse] [listitems_shopping]
2018.11.21 07:53:56.965 5: [echomaster] [echodevice_Parse] [listitems_shopping] DATA Dumper=$VAR1 = '{"values":[]}';
2018.11.21 07:53:56.978 5: End notify loop for echomaster
2018.11.21 07:53:56.991 5: End notify loop for echomaster
2018.11.21 07:53:56.993 4: [echomaster] [echodevice_HandleCmdQueue] [listitems_task] send command=https:...
2018.11.21 07:53:56.993 5: HttpUtils url=https://layla.amazon.de/api/todos?size=....
2018.11.21 07:53:56.996 5: IP: layla.amazon.de -> 52.94.220.236
2018.11.21 07:53:56.998 5: TRX/RAW: /.....
.
.
2018.11.21 07:53:57.058 5: End notify loop for Mess_4
2018.11.21 07:53:57.058 5: TRX_Read END
2018.11.21 07:53:57.060 4: Connection accepted from telnetForBlockingFn_1542634689_127.0.0.1_55130
2018.11.21 07:53:57.064 5: NEUTRINO DBox [NEUTRINO_GetStatus] called function
2018.11.21 07:53:57.064 5: NEUTRINO DBox [NEUTRINO_SendCommand] called function CMD = 
2018.11.21 07:53:57.064 5: NEUTRINO DBox [NEUTRINO_SendCommand] using unencrypted connection via HTTP
2018.11.21 07:53:57.064 4: NEUTRINO DBox [NEUTRINO_SendCommand] SERVICE = powerstate
2018.11.21 07:53:57.065 5: NEUTRINO DBox [NEUTRINO_HD_SendCommand] - append to queue http://192.168.178.30:80/control/standby
2018.11.21 07:53:57.065 5: NEUTRINO DBox [NEUTRINO_HD_HandleCmdQueue] - send command
2018.11.21 07:53:57.065 5: HttpUtils url=http://192.168.178.30:80/control/standby
2018.11.21 07:53:57.066 5: IP: 192.168.178.30 -> 192.168.178.30
2018.11.21 07:53:57.067 5: [Freezemon] freezedetect: ----------- Starting Freeze handling at 2018.11.21 07:53:57.067 ---------------------
[Freezemon] freezedetect: possible freeze starting at 07:53:42, delay is 15.067 possibly caused by: tmr-NEUTRINO_GetStatus(DBox)
=========================================================

Das NEUTRINO-Modul ist sicherlich nicht der eigentliche Verursacher. Zwar hat es meines Wissens tatsächlich blocking calls, aber die Kiste ist die ganze Zeit aus und der freeze müsste folglich regelmäßig auftauchen.
GPIO4 hab ich höchst persönlich auf non-blocking umgestellt.
SYSMON hab ich immer mal im Verdacht, aber glaub ich eher nicht.
Das echo-Modul scheint am auffälligsten, arbeitet aber meines Wissens non-blocking. Irritierend ist aber, dass kurz vor dem langen freeze ein kurzer freeze war. Und dass erst mit dem 2. freeze der echo um 07:53:56.965 e ine Antwort der Abfrage von 07:53:39.945 zu liefern scheint(Stichwort: listitems_shopping), diese dann aber mit DATA Dumper=$VAR1 = '{"values":[]}, was mich annehmen lässt dass der HTTP-Zugriff fehlgeschlagen ist ? 
Grüße Markus

[Pfriemler]

Das sagt apptime bei mir:

Code Auswählen Erweitern

active-timers: 108; max-active timers: 128; max-timer-load: 18  min-tmrHandlingTm: 0.0ms; max-tmrHandlingTm: 6401.0ms; totAvgDly: 397.1ms

name                                     function                               max    count      total  average   maxDly   avgDly TS Max call     param Max call
HMWLAN1                                  HMUARTLGW_Read                       12482    43363 2213463.02    51.04     0.00     0.00 21.11. 19:12:33 HASH(HMWLAN1)
tmr-Weather_GetUpdate                    HASH(0x43a05a0)                       5044      116    8997.99    77.57  6593.49   247.91 20.11. 18:33:30 HASH(MeinWetter)
tmr-DOIF_SleepTrigger                    HASH(0x3f057e0)                       4699       35   13086.08   373.89  3085.34   395.48 21.11. 10:04:25 HASH(di_GaragentorSensorAntriebscheck)
tmr-DOIF_SleepTrigger                    HASH(0x3fecae0)                       4460        8   11747.81  1468.48  2646.27   760.91 19.11. 20:09:34 HASH(di_MakroMusik)
VolkerFon                                andnotify_Set                         4435       73   15151.66   207.56     0.00     0.00 21.11. 10:04:24 HASH(VolkerFon); VolkerFon; send; Garagentor-Zu-Ersatzmeldung|FHEM:; Garagentor; zu; ohne; Antriebsmeldung|Garagentor:; unklar; geschlossen|Problem|2
IRcmd                                    dummy_Set                             4196       13    9729.31   748.41     0.00     0.00 19.11. 20:09:34 HASH(IRcmd); IRcmd; YamahaReceiverOFF
di_Send_IRcmd                            DOIF_Notify                           4130   172290   47742.74     0.28     0.00     0.00 19.11. 20:09:34 HASH(di_Send_IRcmd); HASH(IRcmd)
CUL433                                   CUL_Read                              4049    51408 1686737.39    32.81     0.00     0.00 19.11. 13:25:33 HASH(CUL433)
HMUART                                   HMUARTLGW_Read                        3802    63987 6440959.57   100.66     0.00     0.00 19.11. 13:25:37 HASH(HMUART)
tmr-HMUARTLGW_CheckCmdResp               HASH(0x26db2d8)                       3418      809   26812.41    33.14 16482.34   170.72 21.11. 19:13:06 HASH(HMUART)
di_AlarmanlageZustand                    DOIF_Notify                           3103   172290   58190.63     0.34     0.00     0.00 19.11. 13:29:09 HASH(di_AlarmanlageZustand); HASH(AAZS)
MySensorsGW                              MYSENSORS::Ready                      3019   824717 10194384.30    12.36     0.00     0.00 21.11. 18:39:48 HASH(MySensorsGW)
HMLAN1                                   HMLAN_Ready                           3012   824717 10221801.62    12.39     0.00     0.00 19.11. 23:41:51 HASH(HMLAN1)
AlarmanlageZustand                       dummy_Set                             2935       38   18273.37   480.88     0.00     0.00 19.11. 13:29:09 HASH(AlarmanlageZustand); AlarmanlageZustand; Vollscharf
tmr-DOIF_SleepTrigger                    HASH(0x3fe8ea0)                       2869       10    7272.85   727.28  2538.23   434.57 20.11. 00:00:18 HASH(di_MakroTV)
tmr-HMUARTLGW_CheckCmdResp               HASH(0x449d528)                       2544      946   18437.86    19.49 11129.18   193.09 19.11. 13:25:43 HASH(HMWLAN1)
tmr-at_Exec                              HASH(0x341a278)                       2491        2    4192.77  2096.39     6.81     5.49 21.11. 06:59:06 HASH(VergesseneLichterAus)
nfyAlarmAnlZustandNotify                 notify_Exec                           2304       18    8349.48   463.86     0.00     0.00 19.11. 13:29:09 HASH(nfyAlarmAnlZustandNotify); HASH(AlarmanlageZustand)
tmr-DOIF_SleepTrigger                    HASH(0x3d76850)                       2293        4    7999.13  1999.78  1144.92   290.36 19.11. 13:29:12 HASH(di_AlarmanlageLicht)
AlleFon                                  andnotify_Set                         2186       41    7051.28   171.98     0.00     0.00 19.11. 13:29:09 HASH(AlleFon); AlleFon; send; Alarmanlage; wurde; auf; Vollscharf; geschaltet|FHEM:; Alarmanlage=Vollscharf|Alarmanlagenzustand:; Vollscharf|Statusmeldung|2
Alle_Lichter                             structure_Set                         2155     1218    7634.93     6.27     0.00     0.00 19.11. 13:29:12 HASH(Alle_Lichter); Alle_Lichter; aus
tmr-DOIF_SleepTrigger                    HASH(0x3ee4220)                       1968       19   17562.86   924.36  3203.59   176.59 21.11. 10:05:31 HASH(di_GaragentorZustandByDF)
myDuoFernStick                           DUOFERNSTICK_Read                     1926      249   21690.55    87.11     0.00     0.00 20.11. 20:50:47 HASH(myDuoFernStick)
GaragentorZustand                        dummy_Set                             1847      119   32664.25   274.49     0.00     0.00 21.11. 10:05:31 HASH(GaragentorZustand); GaragentorZustand; closed
tmr-DOIF_SleepTrigger                    HASH(0x3ec6bc0)                       1825       15   23444.53  1562.97  3416.59   582.62 21.11. 16:40:40 HASH(FK_EGWzTerrasse)
tmr-DOIF_SleepTrigger                    HASH(0x402df98)                       1691        8   12685.47  1585.68  3762.87  1111.86 19.11. 22:26:20 HASH(FK_KGSuedL)
tmr-DOIF_SleepTrigger                    HASH(0x36a3c20)                       1645        3    4832.87  1610.96  1025.71   345.19 19.11. 23:11:50 HASH(di_AlarmanlageZustand)
di_GaragentorZustand_Mitteilung          DOIF_Notify                           1490   172290   49696.61     0.29     0.00     0.00 21.11. 10:05:30 HASH(di_GaragentorZustand_Mitteilung); HASH(GaragentorZustand)
CUL1                                     CUL_Read                              1457     6216  543297.96    87.40     0.00     0.00 19.11. 12:51:51 HASH(CUL1)
myDuoFernStick                           DUOFERNSTICK_Set                      1455      194    3684.76    18.99     0.00     0.00 19.11. 18:52:39 HASH(myDuoFernStick); myDuoFernStick; reopen
VolkersHandy                             structure_Notify                      1448   172290  150343.30     0.87     0.00     0.00 21.11. 17:32:57 HASH(VolkersHandy); HASH(VolkersHandy_BT)
tmr-DOIF_SleepTrigger                    HASH(0x4348c38)                       1443       14    6946.96   496.21  7688.88  1492.61 21.11. 00:51:20 HASH(di_MakroHeimkino)
CUL433                                   CUL_Get                               1363       12    5766.48   480.54     0.00     0.00 19.11. 12:36:56 HASH(CUL433);  ; raw; is1110D1F11F00
FK_KGSuedL                               DOIF_Notify                           1338   172290   53384.56     0.31     0.00     0.00 21.11. 01:00:19 HASH(FK_KGSuedL); HASH(SensorKGSzLiU)
di_Briefklappe                           DOIF_Notify                           1329   172290   41518.00     0.24     0.00     0.00 21.11. 15:15:34 HASH(di_Briefklappe); HASH(Briefkastenklappe)
di_AutofernbedienungGaragentor           DOIF_Notify                           1295   172290   43813.46     0.25     0.00     0.00 19.11. 13:27:04 HASH(di_AutofernbedienungGaragentor); HASH(DUOFERN_A707A8)
tmr-CUL_HM_respPendTout                  respPend                              1291     1150   72259.03    62.83 12676.83   302.02 19.11. 18:00:20 respPend:41D287
tmr-IrBlaster_TimerStatusRequest         HASH(0x4470068)                       1248     3303  567181.95   171.72 15832.92  2914.02 20.11. 20:28:30 HASH(IRBl3)
GretkesHandy                             structure_Notify                      1247   172290  217109.95     1.26     0.00     0.00 20.11. 18:55:18 HASH(GretkesHandy); HASH(GretkesHandy_BT)
tmr-DOIF_TimerTrigger                    REF(0x59974f8)                        1239        1    1239.16  1239.16     6.67     6.67 19.11. 10:50:01 REF(0x59974f8)
di_GarageAussentaster                    DOIF_Notify                           1223   172290   38975.77     0.23     0.00     0.00 19.11. 19:49:27 HASH(di_GarageAussentaster); HASH(GarageAussentaster)

Die fettesten Hänger entstehen nach meiner Interpretation rund um das HM-WLAN-Dingens sowie meine Infrarot-Blaster - also beides Netzwerksachen. Was die DOIF-Sleeptrigger da zu suchen haben, erschließt sich mir hingegen gar nicht, das ist eigentlich alles ganz unkompliziertes Zeugs.

Sind da behandlungswürdige Ausreißer dabei oder gehört das noch zum Grundrauschen?

[vbs]

Also alles größer 1 Sekunde find ich behandlungswürdig, ehrlich gesagt. Ist ja ein richtiges Schlachtfest bei dir

Kann es sein, dass dein FHEM als Ganzes bzw. der ganze Rechner ab und zu blockiert ist? Kernel-Hänger oder andere Prozesse, die sich die CPU mopsen? Kann mir kaum was anderes vorstellen bei der Vielzahl und Verschiedenartigkeit der betroffenen Module?

[Pfriemler]

Also alles größer 1 Sekunde find ich behandlungswürdig, ehrlich gesagt. Ist ja ein richtiges Schlachtfest bei dir

Na toll. Ist's also doch so schlimm 

Kann es sein, dass dein FHEM als Ganzes bzw. der ganze Rechner ab und zu blockiert ist? Kernel-Hänger oder andere Prozesse, die sich die CPU mopsen? Kann mir kaum was anderes vorstellen bei der Vielzahl und Verschiedenartigkeit der betroffenen Module?

Das dachte ich mir irgendwie auch schon mal. Generell ist der Raspi 2B seit geraumer Zeit unaufgeräumt, rannte vor zwei Jahren einwandfrei, hat danach eigentlich nur ein JeeLink-Gateway dazubekommen und MQTT. Ein Quell ständigen Ärgernisses ist die WLAN-Verbindung. Ich werde mal das HM-WLAN rauswerfen und das alte HMLAN reaktivieren und den Raspi per LAN ankoppeln - und der 3er liegt seit einem halben Jahr für die Neueinrichtung. Das scheint sich ja dann wirklich endlich mal zu lohnen...

edit: Ich bin sowas von gar kein LINUX-Experte. Ne Idee, wie man dem Raspi auf Betriebssystemebene ein Monitoring bezüglich solcher Hänger verpassen kann? grobe Richtung reicht.