Neues Modul: 98_FREEZEMON Freezes monitoren und Verursacher identifizieren

[KernSani]

Markus,

sorry, aber ich glaube du bist mit dem DNS auf dem Holzweg... aus deinem ausführlichen Log: Ganz oben wird der Call für die notifications an die Queue von echodevice übergeben und quasi sofort abgearbeitet, HTTPUtils_nonBolocking Get beginnt mit dem DNS Call:

Code Auswählen Erweitern

2020.01.16 10:47:44.181 4: [echomaster] [echodevice_SendCommand] [getnotifications] START
2020.01.16 10:47:44.183 4: [echomaster] [echodevice_SendCommand] [getnotifications] PushToCmdQueue SendURL =https://layla.amazon.de/api/notifications
2020.01.16 10:47:44.183 4: [echomaster] [echodevice_SendCommand] [getnotifications] PushToCmdQueue SendData=
2020.01.16 10:47:44.185 4: [echomaster] [echodevice_HandleCmdQueue] [getnotifications] send command=https://layla.amazon.de/api/notifications Data=
2020.01.16 10:47:44.185 5: HttpUtils url=https://layla.amazon.de/api/notifications
2020.01.16 10:47:44.187 5: DNS QUERY 707201000001000000000000056c61796c6106616d617a6f6e0264650000010001

FHEM (bzw. hier echodevice) arbeitet ganz normal weiter (baut weitere Calls auf), bis der DNS antwortet:

Code Auswählen Erweitern


2020.01.16 10:47:44.357 5: DNS ANSWER 166:707281800001000400000000056c61796c6106616d617a6f6e0264650000010001c00c000500010000029f0012056c61796c6106616d617a6f6e03636f6d00c02d00050001000005a10020056c61796c6106616d617a6f6e03636f6d0866726f6e746965720361327ac03ac04b000500010000003c001f0e64337273717570337463786a31610a636c6f756466726f6e74036e657400c077000100010000003c000463566f36
2020.01.16 10:47:44.358 4: DNS result for layla.amazon.de: 99.86.111.54, ttl:60
2020.01.16 10:47:44.358 4: IP: layla.amazon.de -> 99.86.111.54

bis hier ist m.E. alles ok, aber dann macht HTTPUtils irgendwas, was blockiert, noch bevor der eigentliche GET rausgeht:

Code Auswählen Erweitern


--- log skips     1.944 secs.
2020.01.16 10:47:46.302 5: HttpUtils request header:
GET /api/notifications HTTP/1.1
Host: layla.amazon.de


Was ich interessant finde, ist das zwischendrin:

Code Auswählen Erweitern


2020.01.16 10:47:44.206 4: [echomaster] [echodevice_SendLoginCommand] [cookielogin6]
2020.01.16 10:47:44.207 5: HttpUtils url=https://layla.amazon.de/api/bootstrap
2020.01.16 10:47:44.208 5: DNS QUERY 707201000001000000000000056c61796c6106616d617a6f6e0264650000010001


Echodevice sendet das Login ebenfalls über nonBlocking, geht dabei aber nicht über seine eigene Queue, sondern ruft direkt den nonBlocking auf, ich nehme an, damit pfuscht er dem zuvor erfolgten nonBlocking-Aufruf irgendwie ins Handwerk...

[KölnSolar]

Echodevice sendet das Login ebenfalls über nonBlocking, geht dabei aber nicht über seine eigene Queue

Ich glaube, da bist Du auf dem Holzweg.  Meines Erachtens gibt es keine Queue.

Code Auswählen Erweitern

echodevice_SendCommand($hash,"getnotifications","");
echodevice_SendCommand($hash,"alarmvolume","");
echodevice_SendCommand($hash,"bluetoothstate","");
echodevice_SendCommand($hash,"getdnd","");
echodevice_SendCommand($hash,"wakeword","");
echodevice_SendCommand($hash,"listitems_task","TASK");
echodevice_SendCommand($hash,"listitems_shopping","SHOPPING_ITEM");
echodevice_SendCommand($hash,"getdevicesettings","");
echodevice_SendCommand($hash,"getisonline","");

echodevice_SendCommand($hash,"devices","")     if ($hash->{helper}{VERSION} eq "");
echodevice_SendCommand($hash,"devicesstate","");

echodevice_SendCommand($hash,"account","") if ($hash->{helper}{".COMMSID"} eq "");
echodevice_SendLoginCommand($hash,"cookielogin6","");
in sendCommand erfolgt jeweils ein nonblocking_get.

es gab nicht zu tun in FHEM(außer anstehende requests) ? Es hat nur lange gedauert bis der request von "außen"(von was ?) "getriggered" wurde ?

Und wenn der FHEM-Prozess keine CPU-Zeit mehr bekam(requests mit niedriger Priorität) und der trigger von außen ist nur wieder neue Zuteilung von Rechenzeit ? 

[KernSani]

Ich glaube, da bist Du auf dem Holzweg.  Meines Erachtens gibt es keine Queue.

doch gibt es (außer du hast lange kein Update gemacht), ganz am Ende von SendCommand kommt:

Code Auswählen Erweitern


#2018.01.14 - PushToCmdQueue
push @{$hash->{helper}{CMD_QUEUE}}, $SendParam; 
echodevice_HandleCmdQueue($hash);


steht übrigens auch in deinem Log

Code Auswählen Erweitern


2020.01.16 10:47:44.183 4: [echomaster] [echodevice_SendCommand] [getnotifications] PushToCmdQueue SendData=
2020.01.16 10:47:44.185 4: [echomaster] [echodevice_HandleCmdQueue] [getnotifications] send command=https://layla.amazon.de/api/notifications Data=


es gab nicht zu tun in FHEM(außer anstehende requests) ? Es hat nur lange gedauert bis der request von "außen"(von was ?) "getriggered" wurde ?

FHEM hat immer was zu tun Wenn Freezemon läuft dann ruft FHEM zumindest jede Sekunde einmal Freezemon auf (oder versucht es - nur wenn Freezemon um <threshold> Sekunden verspätet aufgerufen wird, kommt es zum Freeze).


EDIT: Ich habe versucht das Szenario mit zwei unmittelbar aufeinander folgenden nonBlockingGets in myUtils nachzustellen, gelingt mir aber irgendwie nicht, einen Freeze zu produzieren, habe aber gelernt, dass HTTPUtils einen DNS Cache hat.

[KölnSolar]

nur nicht richtig geguckt 

einen DNS Cache hat.

Ja den sah ich auch schon. Hab ihn aber noch nicht wirklich verstanden.

Wenn Freezemon läuft dann ruft FHEM zumindest jede Sekunde einmal Freezemon auf

OK, dann eher

Und wenn der FHEM-Prozess keine CPU-Zeit mehr bekam(requests mit niedriger Priorität) und der trigger von außen ist nur wieder neue Zuteilung von Rechenzeit ? 

Es muss ja irgendetwas mit der hohen Nicht-FHEM-Belastung auf dem Rpi zu tun haben. Heute nacht nur ein einziger winziger freeze gemeldet. Woran "sieht" freezemon den hier ?

Code Auswählen Erweitern

[Freezemon] freezedetect: possible freeze starting at 05:30:00, delay is 0.48 possibly caused by: tmr-GPIO4_DeviceUpdateLoop(RPi_OW_WWL) tmr-at_Exec(tMH) tmr-at_Exec(check_jammer)
2020.01.17 05:29:59.404 5: GPIO4: GPIO4_DeviceUpdateLoop(RPi_OW_WWL), pollingInterval:5
2020.01.17 05:29:59.425 4: BlockingCall (GPIO4_Poll): created child (20213), uses telnetForBlockingFn_1578672571 to connect back
2020.01.17 05:30:00.009 5: exec at command tMH
2020.01.17 05:30:00.010 5: Cmd: >set schalter1 on<
2020.01.17 05:30:00.012 3: FS20 set schalter1 on
2020.01.17 05:30:00.014 5: CULFB sending F35aa3811
2020.01.17 05:30:00.015 5: SW: F35aa3811
2020.01.17 05:30:00.052 5: Triggering act_on_Heizung
2020.01.17 05:30:00.053 4: act_on_Heizung exec {heiz_toggle($EVENT)}
2020.01.17 05:30:00.053 5: Cmd: >{heiz_toggle($EVENT)}<
2020.01.17 05:30:00.056 5: Cmd: >set schalter4 off<
2020.01.17 05:30:00.057 3: FS20 set schalter4 off
2020.01.17 05:30:00.058 5: CULFB sending F35aa3b00
2020.01.17 05:30:00.113 5: End notify loop for schalter4
2020.01.17 05:30:00.114 5: Cmd: >set schalter4 off<
2020.01.17 05:30:00.114 3: FS20 set schalter4 off
2020.01.17 05:30:00.114 5: CULFB sending F35aa3b00
2020.01.17 05:30:00.136 5: End notify loop for schalter4
2020.01.17 05:30:00.136 5: Cmd: >set schalter3 on-for-timer 192<
2020.01.17 05:30:00.137 3: FS20 set schalter3 on-for-timer 192
2020.01.17 05:30:00.137 5: CULFB sending F35aa3a396c
2020.01.17 05:30:00.145 4: Follow: +00:03:12 setstate schalter3 off
2020.01.17 05:30:00.156 5: End notify loop for schalter3_timer
2020.01.17 05:30:00.159 5: createNotifyHash
2020.01.17 05:30:00.185 5: statistics stat_sl: Notify.280 Notification of 'global' received. Device not monitored.
2020.01.17 05:30:00.186 5: statistics stat_wr: Notify.280 Notification of 'global' received. Device not monitored.
2020.01.17 05:30:00.199 5: End notify loop for global
2020.01.17 05:30:00.227 5: End notify loop for schalter3
2020.01.17 05:30:00.227 5: Cmd: >set schalter3 on-for-timer 192<
2020.01.17 05:30:00.228 3: FS20 set schalter3 on-for-timer 192
2020.01.17 05:30:00.228 5: CULFB sending F35aa3a396c
2020.01.17 05:30:00.230 5: statistics stat_sl: Notify.280 Notification of 'global' received. Device not monitored.
2020.01.17 05:30:00.230 5: statistics stat_wr: Notify.280 Notification of 'global' received. Device not monitored.
2020.01.17 05:30:00.241 5: End notify loop for global
2020.01.17 05:30:00.241 4: Follow: +00:03:12 setstate schalter3 off
2020.01.17 05:30:00.252 5: End notify loop for schalter3_timer
2020.01.17 05:30:00.253 5: createNotifyHash
2020.01.17 05:30:00.278 5: statistics stat_sl: Notify.280 Notification of 'global' received. Device not monitored.
2020.01.17 05:30:00.279 5: statistics stat_wr: Notify.280 Notification of 'global' received. Device not monitored.
2020.01.17 05:30:00.290 5: End notify loop for global
2020.01.17 05:30:00.316 5: End notify loop for schalter3
2020.01.17 05:30:00.317 5: Cmd: >attr schalter3 ignore 1<
2020.01.17 05:30:00.318 5: statistics stat_sl: Notify.280 Notification of 'global' received. Device not monitored.
2020.01.17 05:30:00.318 5: statistics stat_wr: Notify.280 Notification of 'global' received. Device not monitored.
2020.01.17 05:30:00.344 5: End notify loop for global
2020.01.17 05:30:00.345 5: Cmd: >defmod temp_mixer_on at +00:04:00 deleteattr schalter3 ignore<
2020.01.17 05:30:00.356 5: End notify loop for temp_mixer_on
2020.01.17 05:30:00.358 5: createNotifyHash
2020.01.17 05:30:00.385 5: statistics stat_sl: Notify.280 Notification of 'global' received. Device not monitored.
2020.01.17 05:30:00.385 5: statistics stat_wr: Notify.280 Notification of 'global' received. Device not monitored.
2020.01.17 05:30:00.396 5: End notify loop for global
2020.01.17 05:30:00.397 5: Cmd: >set schalter1 on-for-timer 9216<
2020.01.17 05:30:00.397 3: FS20 set schalter1 on-for-timer 9216
2020.01.17 05:30:00.398 5: CULFB sending F35aa3839c9
2020.01.17 05:30:00.398 4: Follow: +02:33:36 setstate schalter1 off
2020.01.17 05:30:00.408 5: End notify loop for schalter1_timer
2020.01.17 05:30:00.409 5: createNotifyHash
2020.01.17 05:30:00.434 5: statistics stat_sl: Notify.280 Notification of 'global' received. Device not monitored.
2020.01.17 05:30:00.434 5: statistics stat_wr: Notify.280 Notification of 'global' received. Device not monitored.
2020.01.17 05:30:00.446 5: End notify loop for global
2020.01.17 05:30:00.446 5: Cmd: >setreading schalter1 temperature 16.25<
2020.01.17 05:30:00.447 5: Cmd: >setreading schalter1 running off<
2020.01.17 05:30:00.467 5: End notify loop for schalter1
2020.01.17 05:30:00.467 5: redefine at command tMH as *05:30:00 set schalter1 on
2020.01.17 05:30:00.469 5: exec at command check_jammer
2020.01.17 05:30:00.469 5: Cmd: >{if (ReadingsAge('TRXUSB','state',0) > 40 || ReadingsVal('CULFB','state','opened') ne 'Initialized') {Voicecmd('jammer')}}<
2020.01.17 05:30:00.470 5: redefine at command check_jammer as +*00:00:05 {if (ReadingsAge('TRXUSB','state',0) > 40 || ReadingsVal('CULFB','state','opened') ne 'Initialized') {Voicecmd('jammer')}}
2020.01.17 05:30:00.480 5: End notify loop for check_jammer
2020.01.17 05:30:00.481 5: [Freezemon] freezedetect: ----------- Starting Freeze handling at 2020.01.17 05:30:00.480 ---------------------
[Freezemon] freezedetect: possible freeze starting at 05:30:00, delay is 0.48 possibly caused by: tmr-GPIO4_DeviceUpdateLoop(RPi_OW_WWL) tmr-at_Exec(tMH) tmr-at_Exec(check_jammer)

Ich seh da nur den BlockingCall und dann 0,5s später den pünktlichen Start meines at's. Danach dann normale Verarbeitung. Was hat denn da die freeze-Meldung ausgelöst ? Ist es die Ausführung des at's aber erst 05:30:00.467 das redefine dieses zyklischen at's ?

Ich hab an anderer Stelle Rudi mal gebeten einen Blick auf unsere echodevice/httputils Diskussion zu werfen...

[PSI69]

Mein dns u. pi-hole läuft auf dem rpi, wo auch fhem läuft. global dnsServer ist auf dessen IP gesetzt.
Nun hatte ich heute morgen relativ viel lokalen Netzverkehr. Und nun bekam ich ne Menge freezes angezeigt

Diese Idee hatte ich auch - FHEM und pi-Hole liefen im letzten Jahr kurzzeitig auf einem Pi3. In dieser Konstallation hatte ich freezes ohne Ende. Inzwischen läuft FHEM auf einem Pi4 und pi-Hole auf einem ausgemustertem Pi2.
So ist Ruhe...
Peter

[KernSani]

Diese Idee hatte ich auch - FHEM und pi-Hole liefen im letzten Jahr kurzzeitig auf einem Pi3. In dieser Konstallation hatte ich freezes ohne Ende. Inzwischen läuft FHEM auf einem Pi4 und pi-Hole auf einem ausgemustertem Pi2.
So ist Ruhe...
Peter

Exakt mein Szenario (nur dass ich Pihole nie auf dem FHEM Server hatte)

[KernSani]

Ich seh da nur den BlockingCall und dann 0,5s später den pünktlichen Start meines at's. Danach dann normale Verarbeitung. Was hat denn da die freeze-Meldung ausgelöst ? Ist es die Ausführung des at's aber erst 05:30:00.467 das redefine dieses zyklischen at's ?

Der Start dürfte das hier sein:

Code Auswählen Erweitern

05:30:00.009 5: exec at command tMH
Danach kommt eine Kette von Verarbeitungsschritten, die keinen anderen Timer mehr reinlässt. Dein Threshold von 0,5 ist natürlich auch extrem

einen DNS Cache hat.

erfolgreiche DNS Anfragen werden in einen Hash geschrieben und bleiben die vom DNS Server gemeldete TTL Sekunden da drin.

Code Auswählen Erweitern

Ich hab an anderer Stelle Rudi mal gebeten einen Blick auf unsere echodevice/httputils Diskussion zu werfen...
yep, da lese ich auch mit

[KölnSolar]

Dein Threshold von 0,5 ist natürlich auch extrem

0,4 

Danach kommt eine Kette von Verarbeitungsschritten, die keinen anderen Timer mehr reinlässt.

Ich verstehe Deine Aussage, aber nicht den Grund. Es wird eine Funktion aufgerufen. In dieser laufen ein paar FHEM-Befehle mit fhem(".."). Der letzte ist dann ("set schalter1 running off") und dann kommt das von mir angesprochene redefine des zyklischen at's. Das at hat dann tatsächlich 0,458s+ gedauert. Ich glaub beim schreiben hab ich es verstanden....Jetzt kann ich erkannte "freezes" und das freeze-Log wieder etwas besser interpretieren.

[KernSani]

du bringst mich gerade ins Grübeln... wenn die mit fhem() aufgerufen werden, sollten die eigentlich in die fhem-command-queue gehen und damit den freezemon-timer (oder andere anstehende Prozesse) reinlassen... Muss ich mir heute Abend nochmal anschauen... 

[rudolfkoenig]

man sieht den freeze von 1,944 sec. Davor die DNS-Auflösung und danach den http-request

Vmtl. liegt das an der Aushandlung der HTTPS Verschluesselung, das ist naemlich das, was zwischen "IP: layla.amazon.de -> 99.86.111.54" und "HttpUtils request header" erfolgt. Das ist leider blockierend, um es zu fixen muesste ich IO::Socket::SSL umbauen.

Ich versteh aber auch nicht, was das setzen des dnsServers konkret bedeutet.

Falls gesetzt, ruft HttpUtils_NonblockingGet nicht die (blockierende) Linux Bibliothek fuer Namensaufloesung auf, sondern die nicht blockierende Implementation in HttpUtils.pm. Diese kann man auch separat testen mit:

Code Auswählen Erweitern

{ HttpUtils_gethostbyname({timeout=>4}, "fhem.de", 1,sub(){my($h,$e,$a)=@_;; Log 1, $e ? "ERR:$e": ("IP:".ip2str($a)) }) }

aufgrund der Vielzahl der dns-Anfragen verschlimmert das echodevice-Modul das Problem

Die DNS-Aufloesung in HttpUtils.pm implementiert einen Cache, d.h. fuer ttl (TimeToLive) Sekunden nach der ersten Anfrage wird keine weitere fuer diesen Namen gemacht. ttl wird vom "Auskunftsgeber" bzw. Domain-Owner vorgegeben. Wenn man die Aussage korrigiert: "Aufgrund der vielen neu aufzubauenden verschluesselten Verbindungen", dann stimmt sie

Ich wuerde versuchen mehrere Request ueber die gleiche Verbindung abzusetzen (in der Hoffnung, dass der Server das unterstuetzt), damit spart man N-1 SSL-Verdindungsaufbauten. Dafuer muss man beim HttpUtils_NonblockingGet den gleichen Hash verwenden, und keepalive setzen. In etwa so:

Code Auswählen Erweitern

fhem> { $data{mhc} = { callback=>sub($$$){ Log 1,"ERR:$_[1] DATA:".length($_[2]) }, keepalive=>1 } }
fhem> { $data{mhc}{url} = "https://fhem.de/index.html", HttpUtils_NonblockingGet($data{mhc}) }
fhem> { $data{mhc}{url} = "https://fhem.de/MAINTAINER.txt", HttpUtils_NonblockingGet($data{mhc}) }


[KernSani]

Na da hat doch der Rudi kurz mal aus dem Ärmel geschüttelt was wir in tagelanger Diskussion nicht zur Hälfte verstanden haben und gleich eine (mögliche) Lösung geliefert

Vielleicht ergänzend noch zum DNS: Die TTL bei layla.amazon.de ist bei gerade mal 30 Sekunden, d.h. der Cache überlebt im Normalfall gerade mal einen Status Refresh, aber da der DNS ja hier nicht das Problem ist, kann man das ja ignorieren. Was mich irritiert ist, warum das SSL aushandeln dann bei dir manchmal so lange dauert, aber nicht immer...

[KölnSolar]

Erst mal danke Rudi. Und ich lag dann ja gar nicht soooo falsch mit meinen Annahmen. Nur die konkrete Erklärung fehlte noch.

Ich wuerde versuchen mehrere Request ueber die gleiche Verbindung abzusetzen (in der Hoffnung, dass der Server das unterstuetzt), damit spart man N-1 SSL-Verdindungsaufbauten. Dafuer muss man beim HttpUtils_NonblockingGet den gleichen Hash verwenden, und keepalive setzen.

Oder mein anderes Thema: ganz auslagern.  (ich weiß, auch nicht Allheilmittel und .....)
Aber prima, dann kennen wir jetzt den 2. Grund warum nonblocking nicht unbedingt non-blocking ist. Und da ohne TLS heute fast nichts mehr geht, ist eigentlich jedes Modul potenziell betroffen, dass per https(vermutlich auch mqtts....?) kommuniziert. 

um es zu fixen muesste ich IO::Socket::SSL umbauen.

Macht ja eher wenig Sinn ein Standard-Modul zu verändern.

Was mich irritiert ist, warum das SSL aushandeln dann bei dir manchmal so lange dauert, aber nicht immer...

Mich nicht. Ich schrieb ja mehrfach, dass es irgendwie mit dem traffic zusammenhängen muss. Und wenn hier im lokalen Netzwerk viel los ist, dann dauert es halt, bis die TLS-Kommunikation aufgebaut ist. Sind ja ein paar Kommunikationsschritte hin-und-her.

[herrmannj]

Non blocking SSL Connect würde aber eigentlich gehen

[KernSani]

und mir hat die ganze Experimentiererei einen Hinweis gegeben, wo "no bad guy found" herkommen kann, auch wenn ich noch keine Idee habe, wie ich den "bad guy" in so einem Szenario abfangen könnte...

Ich nehme an, wenn die Callback-Verarbeitung einen Freeze verursacht (und im fraglichen Zeitraum kein anderer Kandidat vorhanden ist) kommt es zu "no bad guy found". Wenn so ein nonBlockingGet zurück kommt (und wahrscheinlich auch sein Kollege, der fork) dann fällt der Aufruf - aus FHEM Sicht - spontan vom Himmel. Das Command oder der Timer, die urspünglich mal den nonBlockingGet aufgerufen haben sind beendet, daher kommen sie nicht als Kandidaten in Frage. Der Callback meldet sich aber nicht irgendwo im FHEM und sagt: "Hier bin ich, darf ich mal", sondern wird einfach abgearbeitet... Grübel (ich denke laut), das heißt Freezemon müsste mich in nonBlockingGet reinhängen, sich den Callback merken und bei einem Freeze auswerten... Nicht schön, aber wäre einen Versuch Wert... Danke für's zuhören
   

[KernSani]

0,4  Ich verstehe Deine Aussage, aber nicht den Grund. Es wird eine Funktion aufgerufen. In dieser laufen ein paar FHEM-Befehle mit fhem(".."). Der letzte ist dann ("set schalter1 running off") und dann kommt das von mir angesprochene redefine des zyklischen at's. Das at hat dann tatsächlich 0,458s+ gedauert. Ich glaub beim schreiben hab ich es verstanden....Jetzt kann ich erkannte "freezes" und das freeze-Log wieder etwas besser interpretieren.

Ich habe das gerade nochmal empirisch untersucht. Ich habe ein DOIF (weil besser zum Testen als ein at) gebaut, das hintereinander ziemlich oft die gleiche Lampe einschaltet. Das führt zu einem Freeze von fast 5 Sekunden. Der Versuch währenddessen ein anderes Licht (manuell über WebUI) einzuschalten hat eine merkliche Verzögerung, und schaltet erst, wenn das DOIF durch ist.
Im echten Leben ist es vermutlich sehr unwahrscheinlich, dass während solcher Ketten von Kommandos ein kritisches Ereignis eintritt, wo die verzögerte Ausführung einen echten Impact hat, aber trotzdem was, was man sich merken sollte.