FREEZEMON - Ursache von freezes ermitteln FW_NOTIFY

Begonnen von KölnSolar, 11 Oktober 2018, 09:33:08

Vorheriges Thema - Nächstes Thema

KölnSolar

erst einmal wiederholten Dank an Oli für das Modul.

Bei mir zeigen sich häufige(ca. 10/h) freezes mit dem selben Symptom, aber unterschiedlichen Modulen, weshalb ich ein "Systemproblem" vermute.

Auffälligkeit:
2018.10.10 03:16:01.628 5: OBIS (zaehler) - Msg-Parse: 1-0:96.50.0*5(02)
--- log skips     3.954 secs.
2018.10.10 03:16:05.582 4: Closing connection WEB_192.168.xyz_52811 due to full buffer in FW_Notify
2018.10.10 03:16:05.584 5: End notify loop for zaehler

Die freezes sind begleitet von der Meldung zum buffer-Überlauf und der Beendigung der notify-Loop des vor dem freeze upgedateten devices.

Ich hab mir dann mal die fhem.pl angesehen. Ich verstehe dort zwar recht wenig  :-[, hab aber in der Funktion addToWritebuffer in Zeile 5066 den Wert von 102400 auf 1024000 verzehnfacht. Effekt: die Meldungen zu FW_Notify bleiben aus.  :D, aber die freezes bleiben  :'( 2018.10.11 02:47:02.108 5: OBIS (zaehler) - Msg-Parse: 1-0:51.7.0*255(000.21*A)
2018.10.11 02:47:02.108 5: Msg 1-0:51.7.0*255(000.21*A) is of type Channels
--- log skips     3.472 secs.
2018.10.11 02:47:05.580 5: End notify loop for zaehler


Hintergrund des Systems: ne ganze Menge notify's, HttpUtils_NonblockingGet- und BlockingCall-Aufrufe. Irgendwas scheint sich da im Hintergrund "aufzustauen" und dann mehr oder weniger gegenseitig zu blockieren.

Jemand eine Idee wo und wie ich weitersuchen kann ?

Was bedeutet der buffer in FW_NOTIFY(addToWritebuffer) genau ? Könnte ich mir dessen "Belegung"(Inhalt, genutzte Größe) irgendwie ansehen ?

Grüße Markus
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

rudolfkoenig

ZitatWas bedeutet der buffer in FW_NOTIFY(addToWritebuffer) genau ?
FW_Notify ist fuer die "longpoll" Benachrichtigung zustaendig, vulgo dass bei Schaltvorgaengen die Lampen auf der FHEMWEB Oberflaeche an oder ausgehen.

Vor addToWritebuffer kam es vor, dass eine tote Verbindung (z.Bsp. ein Telefon, was nicht mehr im WLAN ist, oder sich verklemmt hat) die Daten nicht mehr abgeholt hat, und nachdem der OS-Puffer voll war, FHEMWEB beim Schreiben sich blockiert hat.Da der OS-TCP-Puffer (je nach OS) nicht sehr gross ist, haben wir einen zusaetzlichen Puffer in fhem.pl. Dieser kann beliebig grosse Daten entgegennehmen, aber wenn die im Puffer beim addToWritebuffer bereits befindlichen Daten eine Groesse (100k) ueberschreiten, dann geht fhem.pl vorn einer toten Verbindung aus, da offensichtlich die Daten nicht abgeholt werden.

Die Daten werden in $hash->{".WRITEBUFFER"} geschrieben, und dieser Wert wird normalerweise (wg. Punkt am Anfang) nicht angezeigt.

KölnSolar

Danke Dir. Ein bißchen habe ich verstanden.  :D :'( :-[ Die Meldung ist also eher nur eine "Begleiterscheinung"
Ich hab die Angewohnheit permanent ca 10 Tabs geöffnet zu haben. Da wird der Buffer dann vermutlich schon ganz schön voll. Ausschalten heißt bei mir in den Standby-Modus des Windoof-Rechners zu gehen. Nachts sollte dann aber Ruhe sein, oder ? Wird die Verbindung nicht geschlossen/gelöscht ?

2018.10.10 04:29:48.302 4: Closing connection WEB_192.168.xyz_52811 due to full buffer in FW_Notify
.
.
2018.10.10 04:37:12.694 4: Closing connection WEB_192.168.xyz_52811 due to full buffer in FW_Notify
.
.
2018.10.10 05:11:20.093 4: Closing connection WEB_192.168.xyz_52811 due to full buffer in FW_Notify
.
.
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

rudolfkoenig

ZitatAusschalten heißt bei mir in den Standby-Modus des Windoof-Rechners zu gehen. ... Wird die Verbindung nicht geschlossen/gelöscht ?
Genau in diesem Fall nicht, damit es nach dem Aufwachen direkt weitergehen kann, FHEM kriegt also keine Nachricht. Hat aber das Problem, fuer alle Tabs jeweils viele MB an Daten vorzuhalten, was je nach Szenario zu viel werden kann, deswegen wird die Verbindung nach 100k geschlossen. Die Meldung ist normal.

KölnSolar

Ich greif den Thread mal wieder auf, weil mir jetzt aufgefallen ist, dass Rudi mir zwar damals erklärt hat, was "closing connection" Meldungen bedeuten, aber offen geblieben ist, was die freezes(die ja vielleicht gar keine sind ?) verursacht.  ???

Ein aktuelles Beispiel sieht so aus, wobei ich die fraglichen Stellen fett markiert habe
Zitat[Freezemon] freezedetect: possible freeze starting at 12:54:43, delay is 15.122 possibly caused by: cmd-{GPIO4_PollfinishFn('RPi_OW_TC1|28|80000007e747|T: 11.625|11.625')}(telnetForBlockingFn_1575994468) fn-NotifyFn(Testlog) fn-ReadFn(telnetForBlockingFn_1575994468_127.0.0.1_46924) tmr-HttpUtils_Err(N/A) tmr-at_Exec(check_jammer)
2020.01.07 12:54:42.066 4: https://layla.amazon.de/api/traffic/settings: HTTP response code 200
2020.01.07 12:54:42.066 5: HttpUtils https://layla.amazon.de/api/traffic/settings: Got data, length: 511
2020.01.07 12:54:42.066 5: HttpUtils response header:
2020.01.07 12:54:42.067 4: [echomaster] [echodevice_Parse] [getsettingstraffic]
2020.01.07 12:54:42.802 5: [echomaster] [echodevice_Parse] [getsettingstraffic] DATA Dumper=$VAR1 = .....
2020.01.07 12:54:42.808 4: [echomaster] [echodevice_HandleCmdQueue] [getbehavior] send command=https://layla.amazon.de/api/behaviors/automations?limit=100 Data=
2020.01.07 12:54:42.808 5: HttpUtils url=https://layla.amazon.de/api/behaviors/automations?limit=100
2020.01.07 12:54:42.809 4: IP: layla.amazon.de -> 99.86.111.54
2020.01.07 12:54:42.822 5: TRX: TRX_Read '0f5c014040dae600000008a806643240'
2020.01.07 12:54:42.822 5: TRX_Read rmsg '0f5c014040dae600000008a806643240'
2020.01.07 12:54:42.822 5: TRX_Read TRX_data '0f5c014040dae600000008a806643240'
2020.01.07 12:54:42.822 5: TRX_Parse() '0f5c014040dae600000008a806643240'
2020.01.07 12:54:42.824 5: TRX_WEATHER: decoding delay=1 hex=0f5c014040dae600000008a806643240
2020.01.07 12:54:42.825 5: TRX_WEATHER: parsing sensor_id=5c message='0f5c014040dae600000008a806643240'
2020.01.07 12:54:42.826 5: TRX_WEATHER: name=Mess_4 device=REVOLT_40da energy_voltage=230
2020.01.07 12:54:42.866 5: End notify loop for Mess_4
2020.01.07 12:54:42.866 5: TRX_Read END
2020.01.07 12:54:42.869 4: Connection accepted from telnetForBlockingFn_1575994468_127.0.0.1_46922
2020.01.07 12:54:42.875 4: Connection accepted from telnetForBlockingFn_1575994468_127.0.0.1_46924
2020.01.07 12:54:42.877 5: Cmd: >{BlockingStart('1217032')}<
2020.01.07 12:54:42.884 5: Cmd: >{GPIO4_PollfinishFn('RPi_OW_AG|28|031771d639ff|T: 14.062|14.062')}<
2020.01.07 12:54:42.885 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_AG) Start
2020.01.07 12:54:42.886 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_AG) EndreadingsBulkUpdate
2020.01.07 12:54:42.886 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_AG) EndreadingsUpdate
2020.01.07 12:54:42.886 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_AG) End
2020.01.07 12:54:42.981 5: HttpUtils request header:
GET /api/behaviors/automations?limit=100 HTTP/1.1
2020.01.07 12:54:42.982 5: exec at command check_jammer
2020.01.07 12:54:42.983 5: Cmd: >{if (ReadingsAge('TRXUSB','state',0) > 40 || ReadingsVal('CULFB','state','opened') ne 'Initialized') {Voicecmd('jammer')}}<
2020.01.07 12:54:42.984 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.07 12:54:42.996 5: End notify loop for check_jammer
2020.01.07 12:54:42.999 5: Cmd: >{BlockingStart('1217034')}<
2020.01.07 12:54:43.002 5: Cmd: >{GPIO4_PollfinishFn('RPi_OW_TC1|28|80000007e747|T: 11.625|11.625')}<
2020.01.07 12:54:43.003 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_TC1) Start
2020.01.07 12:54:43.003 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_TC1) EndreadingsBulkUpdate
--- log skips    15.097 secs.
2020.01.07 12:54:58.100 5: [Freezemon] freezedetect: Long function call detected NotifyFn:Testlog - 15.081093 seconds
2020.01.07 12:54:58.115 5: End notify loop for RPi_OW_TC1
2020.01.07 12:54:58.115 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_TC1) EndreadingsUpdate
2020.01.07 12:54:58.115 5: GPIO4: GPIO4_PollfinishFn(RPi_OW_TC1) End
2020.01.07 12:54:58.115 5: [Freezemon] freezedetect: Long running Command detected {GPIO4_PollfinishFn('RPi_OW_TC1|28|80000007e747|T: 11.625|11.625')}:telnetForBlockingFn_1575994468 - 15.112951 seconds
2020.01.07 12:54:58.116 5: [Freezemon] freezedetect: Long function call detected ReadFn:telnetForBlockingFn_1575994468_127.0.0.1_46924 - 15.116548 seconds
2020.01.07 12:54:58.122 5: [Freezemon] freezedetect: ----------- Starting Freeze handling at 2020.01.07 12:54:58.122 ---------------------
[Freezemon] freezedetect: possible freeze starting at 12:54:43, delay is 15.122 possibly caused by: cmd-{GPIO4_PollfinishFn('RPi_OW_TC1|28|80000007e747|T: 11.625|11.625')}(telnetForBlockingFn_1575994468) fn-NotifyFn(Testlog) fn-ReadFn(telnetForBlockingFn_1575994468_127.0.0.1_46924) tmr-HttpUtils_Err(N/A) tmr-at_Exec(check_jammer)
Da ist also zum einen eine 0,8s Verzögerung beim echodevice-Modul, die ich mir nicht erklären kann. Da werde ich mich aber mit dem Modulautor abstimmen.

Der 2. fett markierte Teil ist für mich der wesentlichere/allgemeinere, denn das "Muster" finde ich häufiger. Bei dem konkreten Fall habe ich extra ein paar Loggings eingebaut. Die 1. Zeile ist in einer finishFn eines BlockingCall. Sie steht vor einem abschließenden readingsEndUpdate. Die letzte fett markierte nach dem readingsEndUpdate.

Hat jemand eine Erklärung für 2020.01.07 12:54:58.100 5: [Freezemon] freezedetect: Long function call detected NotifyFn:Testlog - 15.081093 seconds(Testlog ist ein eigentlich unkritisches filelog-device, welches durch ein event des vorhergehenden readingsEndUpdate befüllt wird)

Das "Muster" ist immer wieder ein "Long function call detected NotifyFn:......"

Danke&Grüße
Markus
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

rudolfkoenig

readingsEndUpdate berechnet erst die userReadings, und loest danach die Events aus, und ruft damit alle auf, die benachrichtigt werden wollen (notify, DOIF, FHEMWEB, FileLog, etc).

KölnSolar

Hi Rudi,
schön, dass Du antwortest. Mir ist schon klar was da "eigentlich" abläuft. Aber das dauert ja keine 15 Sek.  :o
Die Frage ist daher, was da der Abarbeitung im Wege gestanden haben könnte. Könnte es das Speicherproblem beim BlockingCall sein ? Ein Speicherfehler der SD ? Oder halt etwas, was nur jemand mit Deinem Wissen über die Internas von FHEM spekulieren kann.  ;) Vielleicht blockierte FHEM auch gar nicht und ich werde nur durch Freezemon auf die falsche Fährte geschickt ?  :-\
Im Grundatz ist mein System stabil und performant. Seit heute morgen 7 freezes > 3 Sek.
Grüße Markus
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

rudolfkoenig

Hast du Probleme beobachtet, oder laeuft Freezemon nur aus Vorsicht mit?
Falls Letzteres, dann wuerde ich es abschalten, und sowohl Dir, als auch FHEM Kopfschmerzen erpsaren :)

KernSani

Kurze Erklärung, was freezemon hier macht:
1.) Log skips 15 Sec.: Freezemon loggt ja intern auf verbose 5 mit. Hier wurde für 15 Sekunden tatsächlich nichts ins Log geschrieben - ein nahezu sicherer Indikator, dass tatsächlich nichts passiert ist, also das System blockiert war.
2.) Long function call detected. Wenn das entsprechende Attribut gesetzt ist, hängt sich Freezemon in die Main::CallFn und zieht vor und nach der eigentlichen CallFn einen Timestamp. Dadurch kann der Verursacher des Freezes stärker eingegrenzt werden.
Meine Interpretation des Ganzen wäre tatsächlich, dass das Testlog so lange braucht, warum auch immer...

Als Gegencheck: Schalte doch Freezemon mal ab und ändere dein Logging auf 1  o.ä., dann siehst du ja, ob auch dann ein größeres gap zwischen den beiden Logeinträgen auftaucht.
RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...

KölnSolar

#9
Zitatlaeuft Freezemon nur aus Vorsicht mit?
Ja, eigentlich schon. Aber es hat mir bisher super Dienste geleistet. Erst heute bin ich drauf gestoßen, was bei einem verwaisten und von mir inoffiziell betreuten Modul zu einem spürbaren freeze führt. Dann in den vergangenen Tagen die echodevice-Geschichte. Als Prophylaxe ist es schon toll. Und manchmal liegen Sek. zwischen 2 in einem at oder notify geschalteten devices. Also irgendwas stimmt da nicht
ZitatFalls Letzteres, dann wuerde ich es abschalten, und sowohl Dir, als auch FHEM Kopfschmerzen erpsaren
Nicht der schlechteste Tipp.  ;D
ZitatAls Gegencheck: Schalte doch Freezemon mal ab und ändere dein Logging auf 1  o.ä., dann siehst du ja, ob auch dann ein größeres gap zwischen den beiden Logeinträgen auftaucht
Dann sehe ich es ja nicht mehr.  ;D ;D ;D
Ich kriege es leider  nicht wirklich reproduziert. Einzige Auffälligkeit: Immer(gefühlt), wenn ich mit FHEMWEB aktiv bin und das ist in der Regel im Zusammenhang meiner 13 1W-Sensoren, den dazugehörigen filelogs....und immer wieder dieses Modul. OK, auch das einzige womit ich 27/min. polle. Und das jedesmal open/read/close einer Datei in /sys/.... macht.
ZitatMeine Interpretation des Ganzen wäre tatsächlich, dass das Testlog so lange braucht, warum auch immer...
So sehe ich das auch. Aber 15 Sek. ? 

Ich gucke..
Edit: gerade den obigen Extrakt überflogen. Da fiel mir ins Auge, dass ein paar Zeilen höher ein Sensor innerhalb 1/100 Sek. verarbeitet war.  ::)
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

KernSani

#10
Zitat von: KölnSolar am 07 Januar 2020, 20:50:35
Dann sehe ich es ja nicht mehr.  ;D ;D ;D
Doch, wenn du auf Level 1 loggst, dann steht es ja mit Zeitstempel im normalen Log.

Edit: Und 15 Sekunden ist tatsächlich verwirrend lange... Das Filelog liegt nicht auf einem gemountetem Drive o.ä. ?
RasPi: RFXTRX, HM, zigbee2mqtt, mySensors, JeeLink, miLight, squeezbox, Alexa, Siri, ...