Hi,
ich habe (glaube ich) eine neue Version der HMLAN-Disconnects. Es scheint damit zusammenzuhängen, dass ich die Fhem-Web-Oberfläche längere Zeit geöffnet habe und zwar nicht über das lokale Netzwerk. Ich habe zum Teil fehlende Daten über mehrere Minuten.
Hier ist ein typischer Auszug.
Erstmal ein Teil vom Logfile:
2014.04.23 19:17:54 1: HMLAN_Parse: HMLAN1 new condition ok
2014.04.24 12:40:09 1: 192.168.178.152:1000 disconnected, waiting to reappear
2014.04.24 12:40:09 1: HMLAN_Parse: HMLAN1 new condition disconnected
2014.04.24 12:40:11 1: 192.168.178.152:1000 reappeared (HMLAN1)
2014.04.24 12:40:11 1: HMLAN_Parse: HMLAN1 new condition init
2014.04.24 12:40:14 1: HMLAN_Parse: HMLAN1 new condition ok
...also ein Disconnect heute um 12:40.
Dazu jetzt mal ein FileLog von einem RT zur selben Zeit:
2014-04-24_12:24:55 eg_ws_HeizungOp T: 17.5 desired: 16.0 valve: 0
2014-04-24_12:27:59 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:30:48 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:40:09 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:40:12 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:40:13 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:40:45 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:43:27 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:45:53 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:48:06 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
2014-04-24_12:51:08 eg_ws_HeizungOp T: 17.6 desired: 16.0 valve: 0
Vor 12:40 ist der letzte Eintrag so ungefähr 12:30, dann kommt erstmal 10 Minuten nichts mehr. Die fehlenden Messages scheinen dann schnell hintereinander einzutrudeln. Das Bild ist dasselbe in allen FileLogs.
Da das oft hilft, habe ich auch mal apptime gestartet. Hier ist das Ergebnis:
name function max count total average maxDly
HeizParams readingsGroup_Notify 7767 9818 504694 51.40 0 HASH(0xffd5a0); HASH(0xe9b4a0)
tmr-at_Exec HASH(0xfac340) 3462 119 53433 449.02 29431 HASH(0xfac340)
HMLAN1 HMLAN_Read 1139 3029 246741 81.46 0 HASH(0xad1a60)
tmr-at_Exec HASH(0x10492f0) 833 594 82376 138.68 117101 HASH(0x10492f0)
tmr-PID20_Calc HeizRegler 518 589 51691 87.76 74661 HeizRegler
og_bd_params readingsGroup_Notify 416 9818 2107 0.21 0 HASH(0xf26930); HASH(0xe9b6f0)
HMLAN1 HMLAN_Ready 131 6 728 121.33 0 HASH(0xad1a60)
tmr-at_Exec HASH(0xf26730) 84 9 146 16.22 112 HASH(0xf26730)
tmr-at_Exec HASH(0xf23040) 82 9 145 16.11 111 HASH(0xf23040)
FileLog_DirksSensor FileLog_Log 75 9818 16128 1.64 0 HASH(0x10a8ac0); HASH(0x1046da8)
eg_ws_HeizungOp CUL_HM_Set 74 5 125 25.00 0 HASH(0xf21a08); eg_ws_HeizungOp; desired-temp; 17.0
dg_so_HeizungOp CUL_HM_Set 72 1 72 72.00 0 HASH(0xf22950); dg_so_HeizungOp; desired-temp; 17.0
FileLog_Heizraum FileLog_Log 55 9818 28024 2.85 0 HASH(0xf09690); HASH(0xe81b78)
FileLog_HeizRegler FileLog_Set 50 50 698 13.96 0 HASH(0x107f2f8); FileLog_HeizRegler; ?
FileLog_Heizraum FileLog_Set 50 50 656 13.12 0 HASH(0xf09690); FileLog_Heizraum; ?
FileLog_og_sz_HeizungOp FileLog_Log 50 9818 14851 1.51 0 HASH(0xe81028); HASH(0xffd5a0)
og_ku_HeizungOp CUL_HM_Set 49 189 2589 13.70 0 HASH(0xe65498); og_ku_HeizungOp; ?
tmr-HTTPMOD_GetUpdate HASH(0xe9b4a0) 48 589 4297 7.30 74796 HASH(0xe9b4a0)
FileLog_Everything FileLog_Log 46 9818 19500 1.99 0 HASH(0xe9bb20); HASH(0x1046da8)
eventTypes eventTypes_Notify 46 9818 11696 1.19 0 HASH(0xa87b98); HASH(0xe4fc70)
FileLog_HeizRegler FileLog_Log 43 9818 31399 3.20 0 HASH(0x107f2f8); HASH(0xe80cc8)
Dass das readingsGroup_Notify manchmal etwas lange dauert wundert mich etwas. Ich weiß allerdings nicht, was dahintersteckt. Außerdem ist das kein Grund für einen 10-Minuten Aussetzer, oder?
Der Vollständigkeit halber ist hier mal ein List der readingsGroup:
Internals:
DEF Heizkessel:<Soll Vorlauf>,VLSoll,< >,Hauptschalter Heizkessel:<Vorlauf>,VLTemp,smoothVL,<Rücklauf>,RLTemp,smoothRL Heizkessel:<Außen>,AusTemp,< >,<System>,SysTemp
NAME HeizParams
NR 78
NTFY_ORDER 50-HeizParams
STATE Initialized
TYPE readingsGroup
mayBeVisible 1
Content:
Heizkessel 1
DEVICES:
ARRAY(0x12193f8)
ARRAY(0x12df528)
ARRAY(0x12916b8)
Fhem:
last_update 1397462647.16794
Helper:
Bm:
Readingsgroup_get:
cnt 2
dmx 0
mAr
max 0
tot 0
Readingsgroup_notify:
cnt 9855
dmx 0
mAr HASH(0xffd5a0); HASH(0xe9b4a0)
max 7767
tot 504735
Attributes:
group Heizraum
mapping { "Heizkessel" => "" }
noheading 1
nostate 1
notime 1
room Heizraum
valueFormat {smoothVL => "(%u °C)", smoothRL => "(%u °C)", VLSoll => "%u °C", AusTemp => "%u °C" , VLTemp => "%u °C", RLTemp => "%u °C", SysTemp => "%u °C" }
valueIcon { "Hauptschalter.on" => "Heizung_Hauptschalter.on", "Hauptschalter.off" => "Heizung_Hauptschalter.off" }
valueStyle style="text-align:right"
Wie gesagt, das ganze scheint nur zu passieren, wenn ich die Web-Oberfläche eine Weile offen lasse und nicht über mein lokales Netzwerk reingehe.
Hat jemand Rat?
Gruß,
Thorsten
Hallo Thorsten,
Ich gehe erst einmal davon aus, dass irgend jemand hier "blockiert" - das muss nicht in FHEM intern sein.
Die verzögerten Messages sind interessant. Das Device sendet sicher Zyklich. HMLAN - vermute ich - kann die nicht speichern, also vermute ich, werden die messages in Puffer des OS hinterlegt - und FHEM wartet darauf dran zu kommen. Wenn der 'blockierer' fertig ist, geht es los.
=> wenn du rohmessages aufzeichnest kann ich einiges ablesen
apptime
mit apptime maxDly wird nach der maximalen Verzögerung sortiert. Die max Verarbeitungszeit ist mit 7 sec manchmal kritisch - aber das kann gelegentlich vorkommen. Die maxDly (ein Timer kommt nicht pünktlich, sondern verspätet an den start) ist deutlich schlechter. Da die Werte nicht nach maxDly sortiert sind können noch weitere anstehen. Hier sind Werte von bis zu 2 min zu sehen. Da ich keinen internen Langläufer in dieser Größenordnung sehen ist es wohl ein FHEM externen Prozess, der Ärger macht.
Dass das disconnect so spät gemeldet wird kann den gleichen Grund haben - FHEM kommt nicht dran.
Gruss Martin
ps: was sagt da HMLAN? Da werden auf delays ausgewertet
Hi,
hier ist das Ergebnis von "apptime maxDly":
name function max count total average maxDly
tmr-HMLAN_KeepAlive keepAlive:HMLAN1 11 4261 9664 2.27 120942 keepAlive:HMLAN1
tmr-HttpUtils_ConnErr HASH(0xe9b4a0) 3 1779 10 0.01 119095 HASH(0xe9b4a0)
tmr-HttpUtils_ReadErr HASH(0xe9b4a0) 1 1779 6 0.00 119092 HASH(0xe9b4a0)
tmr-at_Exec HASH(0x10492f0) 833 1785 204491 114.56 117101 HASH(0x10492f0)
tmr-FW_closeOldClients 14 1782 2363 1.33 79862
tmr-HMLAN_UpdtMsgCnt UpdtMsg:HMLAN1 10 1069 1118 1.05 79709 UpdtMsg:HMLAN1
tmr-CUL_HM_ActCheck ActionDetector 35 178 2611 14.67 79299 ActionDetector
tmr-HTTPMOD_GetUpdate HASH(0xe9b4a0) 75 1779 12769 7.18 74796 HASH(0xe9b4a0)
tmr-PID20_Calc HeizRegler 518 1779 138233 77.70 74661 HeizRegler
tmr-at_Exec HASH(0xfac340) 3462 357 88350 247.48 29431 HASH(0xfac340)
tmr-HMLAN_KeepAliveCheck keepAliveCk:HMLAN1 8 4256 36 0.01 1759 keepAliveCk:HMLAN1
tmr-at_Exec HASH(0xf26730) 84 29 387 13.34 112 HASH(0xf26730)
tmr-at_Exec HASH(0xf23040) 82 29 380 13.10 111 HASH(0xf23040)
tmr-HttpUtils_ConnErr HASH(0x12a3f20) 0 1 0 0.00 103
tmr-HttpUtils_ConnErr HASH(0x135e178) 0 1 0 0.00 103
tmr-HttpUtils_ReadErr HASH(0x12a3f20) 0 1 0 0.00 97
tmr-HttpUtils_ReadErr HASH(0x135e178) 0 1 0 0.00 97
tmr-HttpUtils_ConnErr HASH(0x12915f8) 0 1 0 0.00 71
tmr-HttpUtils_ReadErr HASH(0x12915f8) 0 1 0 0.00 66
tmr-HttpUtils_ConnErr HASH(0x12a0e68) 0 2 0 0.00 63
tmr-HttpUtils_ReadErr HASH(0x12a0e68) 0 2 0 0.00 57 Hilft das weiter?
Zitat von: martinp876 am 25 April 2014, 13:45:30ps: was sagt da HMLAN? Da werden auf delays ausgewertet
Ich weiß nicht genau, was Du meinst. Vielleicht ein "list HMLAN"? Et voílà:
Internals:
DEF 192.168.178.152:1000
DeviceName 192.168.178.152:1000
FD 20
HMLAN1_MSGCNT 45215
HMLAN1_TIME 2014-04-25 18:32:08
HM_CMDNR 145
NAME HMLAN1
NR 20
NTFY_ORDER 50-HMLAN1
PARTIAL
RAWMSG E6FB75E,0000,47557993,FF,FFC5,C4A2706FB75E21F83300E43703E5000000000943
RSSI -59
STATE opened
TYPE HMLAN
XmitOpen 1
assignedIDs 21F923,21FBB2,21FC81,21F833,21F83C
assignedIDsCnt 5
assignedIDsReport 5
firmware 0.961
msgKeepAlive dlyMax:989.776 bufferMin:-984
msgLoadEst 1hour:0% 10min steps: 0/0/0/0/0/0
msgParseDly min:-31 max:462142 last:6 cnt:44812
owner 23A3F4
serialNr KEQ0851839
uptime 013 332:26:24.019
Readings:
2014-04-24 14:25:58 Xmit-Events ok:1
2014-04-24 14:25:58 cond ok
2014-04-24 14:25:56 prot_disconnected last
2014-04-24 14:25:56 prot_init last
2014-04-24 14:25:58 prot_ok last
2014-04-11 22:08:33 prot_timeout last
Assids:
21F833 1
21F83C 1
21F923 1
21FBB2 1
21FC81 1
Helper:
000001:
flg 0
msg
to 1398342358.55178
21f833:
chn 02
flg 0
msg
name og_bd_Heizung
to 1398423727.5534
21f83c:
chn 02
flg 0
msg
name dg_so_Heizung
to 1398389814.29172
21f923:
chn 02
flg 0
msg
name og_sz_Heizung
to 1398382343.82832
21fbb2:
chn 02
flg 0
msg
name og_ku_Heizung
to 1398381302.40932
21fc81:
chn 02
flg 0
msg
name eg_ws_Heizung
to 1398382810.3759
23a3f4:
flg 0
6fb75e:
chn 02
flg 0
msg
name DirksSensor
to 1398283371.02146
Bm:
Hmlan_notify:
cnt 26983
dmx 0
mAr HASH(0xad1a60); HASH(0xe81b78)
max 33
tot 154
Hmlan_read:
cnt 9199
dmx 0
mAr HASH(0xad1a60)
max 1139
tot 684011
Hmlan_ready:
cnt 6
dmx 0
mAr HASH(0xad1a60)
max 131
tot 728
Dly:
cnt 44812
lst 6
max 462142
min -31
K:
BufMin -984
DlyMax 989.776
Next 1398443538.97202
Start 1398443513.97202
Log:
all 0
sys 0
ids:
Q:
HMcndN 0
answerPend 0
hmLanQlen 1
keepAliveRec 1
keepAliveRpt 0
apIDs:
Cap:
0 0
1 0
2 0
3 0
4 0
5 0
last 3
sum 0
Ref:
drft -7.99808046068943e-05
hmtL 1196769561
kTs 0
offL 1397246744418
sysL 1398443513979
Attributes:
hmId 23A3F4
hmLanQlen 1_min
logIDs
wdTimer 25
Rohmessages kann ich momentan nicht liefern, da ich innerhalb meines lokalen Netzes. Ich wollte meinen "Arbeits-Rechner" heute nicht einschalten...
Das werde ich aber noch nachliefern, falls es hilft.
Gruß,
Thorsten
hi
Zitathier ist das Ergebnis von "apptime maxDly":
du kannst klar ablesen, dass es eine Verzögerung von 2 min gibt. Auch keepalive ist betroffen (klar). wenn das nicht alle 30sec kommt gibt es einen Disconnect.
Zusammen mit der Auswertung der max zeiten bin ich mir sicher, dass das Problem
außerhalb von FHEM liegt. Ich sehen keinen FHEM task, der 2 min verbraucht.
ZitatVielleicht ein "list HMLAN"?
korrekt
ZitatmsgKeepAlive dlyMax:989.776 bufferMin:-984
msgParseDly min:-31 max:462142 last:6 cnt:44812
keepalive zeigt das Bild noch dramatischer. Hier ist eine Verzögerung von 989 sekunden eingetragen, das sind 15 minuten!
msgParseDly saget, dass eine Nachricht vom HMLAN nach FHEM zumindest einmal 462 sekunden gebracht hat - das sind auch schon 7 Minuten.
Du musst also besser extern suchen. Rohmessages werden nicht weiter helfen. Während dieser Zeit passiert etwas in deinem System, das du mit OS-mittlen fangen musst. Task-performance untersucht, top und ps nutzen, vielleicht hast du noch sonstige tools.
Macht dein Sytem in dieser Zeit irgend etwas? 15 min sind schon eine Hausnummer!
Zitat von: martinp876 am 26 April 2014, 08:14:36Du musst also besser extern suchen. Rohmessages werden nicht weiter helfen. Während dieser Zeit passiert etwas in deinem System, das du mit OS-mittlen fangen musst. Task-performance untersucht, top und ps nutzen, vielleicht hast du noch sonstige tools.
Macht dein Sytem in dieser Zeit irgend etwas? 15 min sind schon eine Hausnummer!
Hi,
vielen Dank soweit erstmal. Das ganze läuft (momentan noch) auf einer FritzBox. Ich werde demnächst wahrscheinlich auf einen RasPi umziehen. Wenn es was FHEM-externes sein sollte, dann ist die Wahrscheinlichkeit groß, dass es dann sowieso verschwindet.
...oder hat noch jemand eine Idee, wie man auf der FritzBox am einfachsten Prozesse mitloggt?
Gruß,
Thorsten
hallo thorsten,
probiere mal dies http://forum.fhem.de/index.php/topic,16347.msg106295.html#msg106295 (http://forum.fhem.de/index.php/topic,16347.msg106295.html#msg106295)
da in deinen apptime aufzeichnungen häufig "http" auftaucht, kann es mit modulen zusammenhängen die über lan arbeiten. ich hatte ähnliche erfahrungen.
gruss frank
Zitat von: frank am 26 April 2014, 10:32:22da in deinen apptime aufzeichnungen häufig "http" auftaucht, kann es mit modulen zusammenhängen die über lan arbeiten. ich hatte ähnliche erfahrungen.
Rein theoretisch müssten doch die Module, die mit http arbeiten, das asynchron tun. D.h. das dürfte eigentlich nichts blockieren. Naja, außer vielleicht es werden mehr Requests abgesetzt als die FritzBox verarbeiten kann (aus welchen Gründen auch immer). Dann muss vielleicht der HMLAN auch mal warten. (Keine Ahnung ob das, was ich da sage, sonderlich sinnvoll ist.)
Gruß,
Thorsten
probier den performance monitor einfach mal aus. ganz einfach.
nur das modul in den FHEM ordner kopieren und fhem neu starten. anscliessend siehst du fhem verzögerungen, die länger als eine sekunde dauern, durch logeinträge in fhem.log.
schon bist du ein schritt weiter.
gruss frank