[gelöst] seltene minutenlange "Hänger" auf der Fritzbox

[rudolfkoenig]

Koennt ihr bitte das Problem mit dem neuen Patch (siehe mein Kommentar hier) testen?

[herrmannj]

Hallo Rudi,

yes !

herzlichen Dank an Dich!
Jörg

[herrmannj]

Hallo Rudi,

gleiche Symptome, fhem friert für 18min ein.

Verwendete fhem version:

Code Auswählen Erweitern


# $Id: fhem.pl 4189 2013-11-09 13:46:31Z rudolfkoenig $
# $Id: 00_CUL.pm 3853 2013-09-04 06:54:57Z rudolfkoenig $
# $Id: 10_CUL_HM.pm 4193 2013-11-09 17:15:13Z martinp876 $
# $Id: 01_FHEMWEB.pm 4092 2013-10-21 20:58:57Z rudolfkoenig $
# $Id: 10_FS20.pm 3764 2013-08-22 07:09:38Z rudolfkoenig $
# $Id: 92_FileLog.pm 3759 2013-08-21 08:13:08Z rudolfkoenig $
# $Id: 00_HMLAN.pm 4184 2013-11-08 16:36:13Z martinp876 $
# $Id: 98_HMinfo.pm 4101 2013-10-23 14:25:19Z martinp876 $
# $Id: 99_SUNRISE_EL.pm 3738 2013-08-18 14:13:59Z rudolfkoenig $
# $Id: 98_SVG.pm 4187 2013-11-09 09:55:16Z rudolfkoenig $
# $Id: 45_TRX.pm 3784 2013-08-24 19:04:30Z wherzig $
# $Id: 46_TRX_ELSE.pm 3774 2013-08-23 21:36:21Z wherzig $
# $Id: 46_TRX_LIGHT.pm 3996 2013-10-03 16:24:44Z wherzig $
# $Id: 46_TRX_SECURITY.pm 3918 2013-09-16 20:14:27Z wherzig $
# $Id: 46_TRX_WEATHER.pm 3874 2013-09-08 04:26:07Z wherzig $
# $Id: 99_Utils.pm 3595 2013-08-05 05:38:48Z tobiasfaust $
# $Id: 90_at.pm 4011 2013-10-06 08:15:26Z rudolfkoenig $
# $Id: 98_autocreate.pm 4114 2013-10-26 09:44:34Z rudolfkoenig $
# $Id: 98_dummy.pm 3738 2013-08-18 14:13:59Z rudolfkoenig $
# $Id: 91_eventTypes.pm 2982 2013-03-24 17:47:28Z rudolfkoenig $
# $Id: 99_Utils.pm 3595 2013-08-05 05:38:48Z tobiasfaust $
# $Id: 91_notify.pm 3738 2013-08-18 14:13:59Z rudolfkoenig $
# $Id: 98_telnet.pm 3738 2013-08-18 14:13:59Z rudolfkoenig $


fhem auf fb 7390, browser ff 25 auf linux.

Steps to replicate:

• longpoll aktiviert
• eventmonitor im browser aufgerufen
• telnet session auf fhem geöffnet, inform timer aktiviert
• abwarten, dann notebookdeckel schliessen

Zum Überwachen habe ich ein 99_perfmon.pm geschrieben das im Falle von freeze logeinträge erzeugt, ich werde das in "Ankündigungen" gleich mit Beschreibung zur Verfügung stellen. (btw, dabei ist mir aufgefallen das im Fall von CommandReload kein undef aufgerufen wird, führt dazu das Timer nicht entfernt werden können)

Edit:
Da ich in "Ankündigungen" nichts erstellen darf unter "Sonstiges" : http://forum.fhem.de/index.php/topic,16347.0.html

Logeintrag:

Code Auswählen Erweitern

2013.11.10 11:49:45.586 1: Perfmon: possible freeze starting at 11:31:21, delay is 1104.585

Ich werde die Tests jetzt wiederholen (jeweils mit eventmonitor, longpoll auf device und telnet einzeln) um zu sehen ob alle drei betroffen sind. SVG longpoll verwende ich aktuell nicht.

vg
Jörg

[herrmannj]

Sowohl der Eventmonitor als auch Telnet sind zeigen weiterhin die freeze.

Eventmonitor:
* NB Deckel zu um 12:55:00, freeze von 12:58 bis 13:11:24

2013.11.10 13:11:24.804 1: Perfmon: possible freeze starting at 12:58:37, delay is 767.803

Telnet:
* NB Deckel zu im 13:15:00, freeze von 13:18:13 bis 13:30:55

2013.11.10 13:30:55.776 1: Perfmon: possible freeze starting at 13:18:13, delay is 762.775

Longpoll schenk ich mir jetzt ...

D&G
Jörg

[rudolfkoenig]

Da meine Tests funktionieren, schlage ich vor zusaetzliche Debug-Ausgaben vor und nach dem Schreiben in fhem.pl (syswrite, Aktuell Zeile 521) einzubauen, um zu sehen ob es daran liegt.

[herrmannj]

sieht jetzt so aus:

Code Auswählen Erweitern


Log 2, "start syswrite";                                                 
my $ret = syswrite($hash->{CD}, $wb);                                   
Log 2, "finish syswrite: $ret";     


Im log sehe ich nur Einträge wenn ich über telnet auf das fhem gehe. Wenn ich im browser fhem aufrufe werden keine Einträge dazu erzeugt. Ist das korrekt ?

Grüße
Jörg

[herrmannj]

Test mit telnet / inform timer:

NB geschlossen um 21:55:00

Log:
... (syswrites start / finish)

Code Auswählen Erweitern


2013.11.10 21:57:50.532 2: start syswrite
2013.11.10 21:57:50.534 2: finish syswrite: 247
2013.11.10 21:57:50.881 2: start syswrite
2013.11.10 21:57:50.883 2: finish syswrite: 424
2013.11.10 22:10:55.471 1: Perfmon: possible freeze starting at 21:57:51, delay is 784.47
2013.11.10 22:10:57.776 1: 192.168.178.20:1000 disconnected, waiting to reappear
2013.11.10 22:10:57.823 2: HMLAN_Parse: HMLAN1 new condition disconnected
2013.11.10 22:10:57.846 2: start syswrite
2013.11.10 22:10:57.849 2: finish syswrite: 13865
2013.11.10 22:10:57.864 1: 192.168.178.20:1000 reappeared (HMLAN1)
2013.11.10 22:10:57.874 2: HMLAN_Parse: HMLAN1 new condition init
2013.11.10 22:10:57.991 1: Perfmon: possible freeze starting at 22:10:56, delay is 1.99
2013.11.10 22:11:00.967 1: Perfmon: possible freeze starting at 22:10:58, delay is 2.966
2013.11.10 22:11:04.004 1: Perfmon: possible freeze starting at 22:11:01, delay is 3.003
2013.11.10 22:11:06.993 1: Perfmon: possible freeze starting at 22:11:05, delay is 1.992
2013.11.10 22:11:08.074 1: Perfmon: possible freeze starting at 22:11:07, delay is 1.073
2013.11.10 22:11:59.602 1: Perfmon: possible freeze starting at 22:11:09, delay is 50.6
2013.11.10 22:12:00.355 2: HMLAN_Parse: HMLAN1 new condition ok
2013.11.10 22:12:00.776 2: start syswrite
2013.11.10 22:12:00.779 2: finish syswrite:
2013.11.10 22:12:00.790 1: 192.168.178.20:1000 disconnected, waiting to reappear
2013.11.10 22:12:00.828 2: HMLAN_Parse: HMLAN1 new condition disconnected
2013.11.10 22:12:00.861 1: 192.168.178.20:1000 reappeared (HMLAN1)


so wie ich das sehe hing er nie _im_ syswrite.

Der Effekt ist trotzdem sicher durch das "kappen" der bestehen (hier telnet) Verbindung zu provozieren ...

Ich geh jetzt noochmal auf verbose 5 ...

vg
joerg

[herrmannj]

Der Hänger ist gut getarnt

Setup wie oben, NB Deckel zu um 22:33. Bis 22:37:30 alles ok, TRX_Read meldet Ende, danach Stillstand bis 22:54:35. (Gewerkschaftlich zugesicherte Pause

Code Auswählen Erweitern


2013.11.10 22:37:30.927 5: TRX_Read END
2013.11.10 22:54:35.913 5: TRX/RAW: /


Das komplette log hängt dran. Soll ich weitere Breakpoints einbauen ? Wenn ja, wo ?

vg
Jörg

[rudolfkoenig]

>  Wenn ich im browser fhem aufrufe werden keine Einträge dazu erzeugt. Ist das korrekt ?

Nein. Habs gerade entdeckt, dass ich FHEMWEB nicht eingecheckt habe, obwohl ich haette darauf schwoeren koennen.
Habs jetzt eingecheckt, und fuer update bereitgestellt. Kannst Du es bitte erneut testen?

[herrmannj]

Vielen Dank, funktioniert: Eventmonitor und Telnet.

XHR mit inform und longpoll beobachte ich.

Das Du einen (den richtigen) Verdacht hattest war Gold wert, ich habe gefühlte 20.000 Breakpoints gesetzt ohne die Stelle exakt festmachen zu können. Wenn ich das richtig interpretiere ist die fb auch nach einem write durchaus noch einige wenige ms weitergelaufen bevor sie stand.

Danke und Grüße
Jörg

[rudolfkoenig]

> Wenn ich das richtig interpretiere ist die fb auch nach einem write durchaus noch einige wenige ms weitergelaufen bevor sie stand.

Nee, der Stand ziemlich sicher in 01_FHEMWEB.pm, FW_FlushInform(), print $c $hash->{INFORMBUF}
Dies  wurde inzwischen durch addToWritebuffer ersetzt, ist also im Code nicht mehr vorhanden.

[herrmannj]

Feedback:

mit den von Rudi gemachten Änderungen seid 5 Tagen kein Einfrieren mehr. Gelegentliche 1-3 sec. Aussetzer lassen sich jeweils einzelnen Modulen zuordnen, die langen Aussetzer sind komplett verschwunden.

Markiert als "gelöst", Danke nochmal

vg
Jörg

[cwagner]

Moin,,
richtig, auch bei mir haben sich diese Hänger verflüchtigt. Danke dafür an den Mentor von FHEM, Rudolf König.

Allerdings finde ich seit der neuen 01_FHEMWEB kurz nach dem Neustart von FHEM über Telnet diese Meldung

syswrite() on closed filehandle GEN320 at fhem.pl line 522.


Herzliche Grüße

Christian

[rudolfkoenig]

> syswrite() on closed filehandle GEN320 at fhem.pl line 522.

Ich kann diese Meldung nicht reproduzieren, ich habe shutdown und shutdown restart per telnet und per FHEMWEB eingegeben. Kannst Du bitte den Vorgang sehr genau beschreiben?

[justme1968]

dir meldungen hab ich bei mir auch gesehen. aber nur im nachhinein und noch nich gefunden wie ich sie reproduzieren kann.

gruss
andre