Neues Modul: 98_FREEZEMON Freezes monitoren und Verursacher identifizieren

[MadMax-FHEM]

Dann bin ich mal so fei und probiere das aus

Dann wieder "nur" get Log bei FreezeMon!?

Ohne irgendwas verbose bei global (steht verm. auf 3) oder beim echodevice (steht verm. auf 0   ) zu drehen!?

Ergebnis dann im anderen Thread: https://forum.fhem.de/index.php/topic,107465.msg1015391.html#msg1015391

Danke, Joachim

[KölnSolar]

Ohne irgendwas verbose bei global (steht verm. auf 3) oder beim echodevice (steht verm. auf 0   ) zu drehen!?

Genau. Jetzt stehen fm_logExtraSeconds zusätzlich im freeze-log. Ich denke Du solltest es auf 3 setzen.

Klingt gut Oli. Danke.

Grüße Markus

[MadMax-FHEM]

Dann sollte ich es mit 5 ja richtig gemacht haben...

Bin aber nicht sicher, ob da wirklich mehr drin steht...
Siehe anderer Thread...

EDIT: oder soll ich den wieder "schließen" und (nur noch) hier weiter machen!?

Wir werden sehen...

Gruß, Joachim

[KernSani]

Wenn keine Einwände kommen, würde ich dann demnächst mal die Version aus dem Post oben (https://forum.fhem.de/index.php/topic,83909.msg1015390.html#msg1015390) im SVN einchecken...

[KölnSolar]

Hi Oli,
wie kommt die freeze Dauer zustande ? Nur für mein Verständnis.

Die beiden blocking calls machen doch nix böses, oder ? Könnte man(also Du )  dann nicht deren Funktionen aus dem "possibly caused" rausnehmen ?

Code Auswählen Erweitern

2020.04.19 18:35:35 3: [Freezemon] freezedetect: possible freeze starting at 18:35:35, delay is 0.474 possibly caused by: tmr-echodevice_GetSettings(echomaster) tmr-Nina_Start(myNina) tmr-USBWRF_GetUpdate(Fronius) tmr-GPIO4_DeviceUpdateLoop(RPi_OW_KS)


Code Auswählen Erweitern

[Freezemon] freezedetect: possible freeze starting at 18:35:35, delay is 0.474 possibly caused by: tmr-echodevice_GetSettings(echomaster) tmr-Nina_Start(myNina) tmr-USBWRF_GetUpdate(Fronius) tmr-GPIO4_DeviceUpdateLoop(RPi_OW_KS)
2020.04.19 18:35:34.332 5: [echomaster] [echodevice_GetSettings] start refresh settings
2020.04.19 18:35:34.332 4: [echomaster] [echodevice_SendCommand] [getnotifications] START
2020.04.19 18:35:34.333 4: [echomaster] [echodevice_SendCommand] [getnotifications] PushToCmdQueue SendURL =https://layla.amazon.de/api/notifications
2020.04.19 18:35:34.333 4: [echomaster] [echodevice_SendCommand] [getnotifications] PushToCmdQueue SendData=
2020.04.19 18:35:34.334 4: [echomaster] [echodevice_HandleCmdQueue] [getnotifications] send command=https://layla.amazon.de/api/notifications Data=
2020.04.19 18:35:34.335 5: HttpUtils url=https://layla.amazon.de/api/notifications
2020.04.19 18:35:34.335 5: HttpUtils request header:
GET /api/notifications HTTP/1.1
Host: layla.amazon.de
Accept-Encoding: gzip,deflate
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:62.0) Gecko/20100101 Firefox/62.0
Accept-Language: de,en-US;q=0.7,en;q=0.3
DNT: 1
Connection: keep-alive
Upgrade-Insecure-Requests: 1
Cookie:meinCokie
csrf: -642580457
Content-Type: application/json; charset=UTF-8

2020.04.19 18:35:34.336 4: [echomaster] [echodevice_SendCommand] [alarmvolume] START
2020.04.19 18:35:34.336 4: [echomaster] [echodevice_SendCommand] [alarmvolume] PushToCmdQueue SendURL =https://layla.amazon.de/api/device-notification-state?_=1587314134
2020.04.19 18:35:34.336 4: [echomaster] [echodevice_SendCommand] [alarmvolume] PushToCmdQueue SendData=
2020.04.19 18:35:34.337 4: [echomaster] [echodevice_SendCommand] [bluetoothstate] START
2020.04.19 18:35:34.338 4: [echomaster] [echodevice_SendCommand] [bluetoothstate] PushToCmdQueue SendURL =https://layla.amazon.de/api/bluetooth?cached=true&_=1587314134
2020.04.19 18:35:34.338 4: [echomaster] [echodevice_SendCommand] [bluetoothstate] PushToCmdQueue SendData=
2020.04.19 18:35:34.339 4: [echomaster] [echodevice_SendCommand] [getdnd] START
2020.04.19 18:35:34.339 4: [echomaster] [echodevice_SendCommand] [getdnd] PushToCmdQueue SendURL =https://layla.amazon.de/api/dnd/device-status-list?_=1587314134
2020.04.19 18:35:34.339 4: [echomaster] [echodevice_SendCommand] [getdnd] PushToCmdQueue SendData=
2020.04.19 18:35:34.340 4: [echomaster] [echodevice_SendCommand] [wakeword] START
2020.04.19 18:35:34.341 4: [echomaster] [echodevice_SendCommand] [wakeword] PushToCmdQueue SendURL =https://layla.amazon.de/api/wake-word?_=1587314134
2020.04.19 18:35:34.341 4: [echomaster] [echodevice_SendCommand] [wakeword] PushToCmdQueue SendData=
2020.04.19 18:35:34.341 4: [echomaster] [echodevice_SendCommand] [listitems_task] START
2020.04.19 18:35:34.342 4: [echomaster] [echodevice_SendCommand] [listitems_task] PushToCmdQueue SendURL =https://layla.amazon.de/api/todos?size=100&startTime=&endTime=&completed=false&type=TASK&deviceSerialNumber=&deviceType=&_=1587314134
2020.04.19 18:35:34.342 4: [echomaster] [echodevice_SendCommand] [listitems_task] PushToCmdQueue SendData=TASK
2020.04.19 18:35:34.343 4: [echomaster] [echodevice_SendCommand] [listitems_shopping] START
2020.04.19 18:35:34.343 4: [echomaster] [echodevice_SendCommand] [listitems_shopping] PushToCmdQueue SendURL =https://layla.amazon.de/api/todos?size=100&startTime=&endTime=&completed=false&type=SHOPPING_ITEM&deviceSerialNumber=&deviceType=&_=1587314134
2020.04.19 18:35:34.343 4: [echomaster] [echodevice_SendCommand] [listitems_shopping] PushToCmdQueue SendData=SHOPPING_ITEM
2020.04.19 18:35:34.344 4: [echomaster] [echodevice_SendCommand] [getdevicesettings] START
2020.04.19 18:35:34.344 4: [echomaster] [echodevice_SendCommand] [getdevicesettings] PushToCmdQueue SendURL =https://layla.amazon.de/api/device-preferences
2020.04.19 18:35:34.344 4: [echomaster] [echodevice_SendCommand] [getdevicesettings] PushToCmdQueue SendData=
2020.04.19 18:35:34.345 4: [echomaster] [echodevice_SendCommand] [getisonline] START
2020.04.19 18:35:34.345 4: [echomaster] [echodevice_SendCommand] [getisonline] PushToCmdQueue SendURL =https://layla.amazon.de/api/devices-v2/device?cached=true&_=1587314134
2020.04.19 18:35:34.345 4: [echomaster] [echodevice_SendCommand] [getisonline] PushToCmdQueue SendData=
2020.04.19 18:35:34.346 4: [echomaster] [echodevice_SendCommand] [devicesstate] START
2020.04.19 18:35:34.347 4: [echomaster] [echodevice_SendCommand] [devicesstate] PushToCmdQueue SendURL =https://layla.amazon.de/api/devices-v2/device?cached=true&_=1587314134
2020.04.19 18:35:34.347 4: [echomaster] [echodevice_SendCommand] [devicesstate] PushToCmdQueue SendData=
2020.04.19 18:35:34.347 4: [echomaster] [echodevice_SendCommand] [account] START
2020.04.19 18:35:34.348 4: [echomaster] [echodevice_SendCommand] [account] PushToCmdQueue SendURL =https://alexa-comms-mobile-service.amazon.com/accounts
2020.04.19 18:35:34.348 4: [echomaster] [echodevice_SendCommand] [account] PushToCmdQueue SendData=
2020.04.19 18:35:34.349 4: [echomaster] [echodevice_SendLoginCommand] [cookielogin6]
2020.04.19 18:35:34.350 5: HttpUtils url=https://layla.amazon.de/api/bootstrap
2020.04.19 18:35:34.350 4: IP: layla.amazon.de -> 99.84.157.56
2020.04.19 18:35:34.352 5: [echomaster] [echodevice_GetSettings] refresh voice command
2020.04.19 18:35:34.352 4: [echomaster] [echodevice_SendCommand] [activities] START
2020.04.19 18:35:34.352 4: [echomaster] [echodevice_SendCommand] [activities] PushToCmdQueue SendURL =https://layla.amazon.de/api/activities?startTime=&size=50&offset=1&_=1587314134
2020.04.19 18:35:34.352 4: [echomaster] [echodevice_SendCommand] [activities] PushToCmdQueue SendData=
2020.04.19 18:35:34.353 4: [echomaster] [echodevice_SendCommand] [getbehavior] START
2020.04.19 18:35:34.354 4: [echomaster] [echodevice_SendCommand] [getbehavior] PushToCmdQueue SendURL =https://layla.amazon.de/api/behaviors/automations?limit=100
2020.04.19 18:35:34.354 4: [echomaster] [echodevice_SendCommand] [getbehavior] PushToCmdQueue SendData=
2020.04.19 18:35:34.354 4: [echomaster] [echodevice_SendCommand] [getsettingstraffic] START
2020.04.19 18:35:34.355 4: [echomaster] [echodevice_SendCommand] [getsettingstraffic] PushToCmdQueue SendURL =https://layla.amazon.de/api/traffic/settings
2020.04.19 18:35:34.355 4: [echomaster] [echodevice_SendCommand] [getsettingstraffic] PushToCmdQueue SendData=
2020.04.19 18:35:34.356 4: [echomaster] [echodevice_GetSettings] Timer INTERVAL = 60
2020.04.19 18:35:34.380 4: BlockingCall (Nina_Run): created child (16938), uses telnetForBlockingFn_1586790614 to connect back
2020.04.19 18:35:34.422 4: Connection accepted from telnetForBlockingFn_1586790614_127.0.0.1_40506
2020.04.19 18:35:34.426 5: Cmd: >{BlockingRegisterTelnet($cl,247973)}<
2020.04.19 18:35:35.424 5: HttpUtils request header:
GET /api/bootstrap HTTP/1.1
Host: layla.amazon.de
User-Agent: fhem
Accept-Encoding: gzip,deflate
Connection: Close
Cookie: meinCookie
2020.04.19 18:35:35.430 4: USBWRF device Fronius request message sent(hex): 8080800001011012
2020.04.19 18:35:35.430 5: SW: 8080800001011012
2020.04.19 18:35:35.432 4: USBWRF device Fronius request message sent(hex): 8080800001021013
2020.04.19 18:35:35.432 5: SW: 8080800001021013
2020.04.19 18:35:35.433 4: USBWRF device Fronius request message sent(hex): 8080800001011214
2020.04.19 18:35:35.433 5: SW: 8080800001011214
2020.04.19 18:35:35.434 4: USBWRF device Fronius request message sent(hex): 8080800001021215
2020.04.19 18:35:35.434 5: SW: 8080800001021215
2020.04.19 18:35:35.436 4: USBWRF device Fronius request message sent(hex): 8080800001011719
2020.04.19 18:35:35.436 5: SW: 8080800001011719
2020.04.19 18:35:35.437 4: USBWRF device Fronius request message sent(hex): 808080000102171a
2020.04.19 18:35:35.437 5: SW: 808080000102171a
2020.04.19 18:35:35.438 4: USBWRF device Fronius request message sent(hex): 808080000101181a
2020.04.19 18:35:35.439 5: SW: 808080000101181a
2020.04.19 18:35:35.440 4: USBWRF device Fronius request message sent(hex): 808080000102181b
2020.04.19 18:35:35.440 5: SW: 808080000102181b
2020.04.19 18:35:35.441 4: USBWRF device Fronius request message sent(hex): 8080800001013739
2020.04.19 18:35:35.441 5: SW: 8080800001013739
2020.04.19 18:35:35.443 4: USBWRF device Fronius request message sent(hex): 808080000102373a
2020.04.19 18:35:35.443 5: SW: 808080000102373a
2020.04.19 18:35:35.444 4: USBWRF Fronius timer set for automatic value requests, period: 60 seconds
2020.04.19 18:35:35.469 4: BlockingCall (GPIO4_Poll): created child (16939), uses telnetForBlockingFn_1586790614 to connect back
2020.04.19 18:35:35.476 5: [Freezemon] freezedetect: ----------- Starting Freeze handling at 2020.04.19 18:35:35.475 ---------------------
[Freezemon] freezedetect: possible freeze starting at 18:35:35, delay is 0.474 possibly caused by: tmr-echodevice_GetSettings(echomaster) tmr-Nina_Start(myNina) tmr-USBWRF_GetUpdate(Fronius) tmr-GPIO4_DeviceUpdateLoop(RPi_OW_KS)
=========================================================


Grüße Markus

[KernSani]

Moin Markus,

Das müsstest du über White- bzw. Blacklist machen. Freezemon weiss ja nur, dass er nicht zur geplanten Zeit dran kam und diese 4 Kollegen vor ihm an der Reihe waren... Wenn du eine gute Idee hast, herauszufinden, wer harmlos ist, baue ich das gerne ein:-)

Grüße,

Oli


Kurz, weil mobil....

[KölnSolar]

Wenn du eine gute Idee hast, herauszufinden, wer harmlos ist, baue ich das gerne ein:-)

Ha, natürlich nicht auf Modulebene. Da ist sicherlich blacklist das Mittel.  Aber im konkreten Fall

.
.
.
2020.04.19 18:35:34.380 4: BlockingCall (Nina_Run): created child (16938), uses telnetForBlockingFn_1586790614 to connect back
2020.04.19 18:35:34.422 4: Connection accepted from telnetForBlockingFn_1586790614_127.0.0.1_40506
2020.04.19 18:35:34.426 5: Cmd: >{BlockingRegisterTelnet($cl,247973)}<
.
.
.
2020.04.19 18:35:35.469 4: BlockingCall (GPIO4_Poll): created child (16939), uses telnetForBlockingFn_1586790614 to connect back
.
.
.

ist es ja eine Ebene höher(tiefer ?  ), der BlockingCall. Der ist ja erst einmal im Grundsatz unverdächtig/harmlos. Ließe der sich nicht generell wie blacklist behandeln ?

Ich versteh halt in dem Fall nicht, was da überhaupt geblocked haben soll und wieso 0,474 s ? Warum mag da das echodevice einen "Sprung" von 1s (zw. letztem Logging u. httputils[wieder das SSL-Thema ?])haben, obwohl der blockingcall dazwischen gefunkt hat.

2020.04.19 18:35:34.355 4: [echomaster] [echodevice_SendCommand] [getsettingstraffic] PushToCmdQueue SendData=
2020.04.19 18:35:34.356 4: [echomaster] [echodevice_GetSettings] Timer INTERVAL = 602020.04.19 18:35:34.380 4: BlockingCall (Nina_Run): created child (16938), uses telnetForBlockingFn_1586790614 to connect back
2020.04.19 18:35:34.422 4: Connection accepted from telnetForBlockingFn_1586790614_127.0.0.1_40506
2020.04.19 18:35:34.426 5: Cmd: >{BlockingRegisterTelnet($cl,247973)}<
2020.04.19 18:35:35.424 5: HttpUtils request header:
GET /api/bootstrap HTTP/1.1
Host: layla.amazon.de
User-Agent: fhem
Accept-Encoding: gzip,deflate
Connection: Close
Cookie: meinCookie
2020.04.19 18:35:35.430 4: USBWRF device Fronius request message sent(hex): 8080800001011012

Nimm mich bitte an die Hand, wenn Du etwas mehr Zeit hast, den Vorgang genauer zu analysieren.

Grüße Markus

[KölnSolar]

Hi Oli,
Michael hatte dann doch ein spätes Einsehen und an einer Stelle noch ein keepalive ins echodevice eingebaut.

Ich bin jetzt runter auf TRESHOLD 0,2. Mal sehen, was nun so kommt. 

Vielleicht kannst Du mir bei Gelegenheit ja mal erklären, wie das gemeldete delay sich bestimmt. Da stolpere ich immer wieder drüber.

Grüße Markus

[Tommy82]

Hi, hab immer mal wieder so ein paar Meldungen, wie kann ich die noch beseitigen?

Code Auswählen Erweitern

2020.06.07 00:00:30.466 1: [Freezemon] myFreezemon: possible freeze starting at 00:00:29, delay is 1.463 possibly caused by: fn-ReadFn(Myalexa)

Code Auswählen Erweitern

2020.06.07 08:10:26.565 1: [Freezemon] myFreezemon: possible freeze starting at 08:10:21, delay is 5.562 possibly caused by: fn-ReadFn(WEBtablet_192.168.188.30_34902) fn-ReadFn(WEBtablet_192.168.188.30_34894) tmr-ENIGMA2_GetStatus(Uno_Schlafzimmer)
2020.06.07 10:02:29.485 1: [Freezemon] myFreezemon: possible freeze starting at 10:02:28, delay is 1.482 possibly caused by: fn-ReadFn(WEBtablet_192.168.188.30_36022)
2020.06.07 10:03:00.919 1: [Freezemon] myFreezemon: possible freeze starting at 10:02:42, delay is 18.916 possibly caused by: fn-ReadFn(WEBtablet_192.168.188.30_36020) fn-ReadFn(WEBtablet_192.168.188.30_36026)

Code Auswählen Erweitern

2020.06.07 10:03:07.065 1: [Freezemon] myFreezemon: possible freeze starting at 10:03:04, delay is 3.063 possibly caused by: fn-ReadFn(WEBtablet_192.168.188.30_36026)

Danke

[KernSani]

Moin,
die Webtablet Dinger kommen mit ziemlicher Sicherheit daher, dass du einen Raum aufrufst wo der Seitenaufbau lange braucht, z.B. wegen  umfangreichen Plots. Damit musst du leben (oder die Plots optimieren, z.B. weniger Datenpunkte durch event-on-change-reading mit Threshold)
Grüße,
Oli


Kurz, weil mobil....

[rudolfkoenig]

Plots optimieren, z.B. weniger Datenpunkte durch event-on-change-reading mit Threshold

Und/oder mit plotEmbed=2 / plotFork das Rendern vom Haupt-FHEM entkoppeln.

[Tommy82]

Und/oder mit plotEmbed=2 / plotFork das Rendern vom Haupt-FHEM entkoppeln.

Danke für den Tip, hab beides mal gesetzt und gefühlt wird die Seite jetzt deutlich schneller aufgerufen. Werd es mal im Auge behalten

[FhemPiUser]

Hallo Zusammen,
ich habe seit einiger Zeit die Fehlermeldung "cannot fork" im log. Nach einem Fhem Neustart kommt sie erstmal nicht mehr, aber nach ca. 2 Tagen kommt sie wieder und dann immer häufiger. Scheinbar gibt es also ein Speicherleck irgendwo und ich versuche dies mit Hilf evon freezemon herauszufinden.

Freezemon meldet mir nun als mögliche freezeDevices

Code Auswählen Erweitern

tmr-CODE(0x72f6fa0)(ProcessRequestQueue) tmr-CODE(0x71f3138)(ResponseTimeout) tmr-CODE(0x71f3138)(ResponseTimeout) tmr-CODE(0x71f91c8)(GetUpdate) tmr-CODE(0x71f91c8)(GetUpdate)

Kann mir jemand sagen, was das bedeutet bzw. wie ich daraus die möglichlerweise verursachenden fhem devices herausfinden kann?

[KölnSolar]

Damit lässt sich noch nicht viel anfangen.

Es sind timer, aber scheinbar aus Systemfunktionen(in den Klammern würde sonst ein echter devicename stehen).

nofork hast Du nicht im global device gesetzt ?
Mehr fällt mir erst einmal nicht ein.

Den freezes könntest Du über das zusätzliche Logfile im freezemon device auf die Spur kommen.

Grüße Markus

[FhemPiUser]

danke erstmal.

Nein, nofork habe ich nicht gesetzt.

Ich habe jetzt erstmal zwei zuletzt hinzugefügte devices disabled und beobachte 2 Tage, ob es an einem dieser beiden liegt. Falls das Problem bestehen bleibt, probiere ich mal mit dem vorgeschlagenem freezemon logfile mehr herauszufinden.