FHEM Forum

FHEM - Hausautomations-Systeme => Homematic => Thema gestartet von: bugster_de am 12 November 2013, 15:43:29

Titel: HM-LAN Disconnect
Beitrag von: bugster_de am 12 November 2013, 15:43:29
Hi Leute,

ich weiß, das Thema hatten wir schon ein paar mal hier, jetzt will ich auch mal :-)

Seit ca. 2 Wochen macht der HM-LAN mucken. Er disconnected sich dauernd und nach ca. 1 Minute ist er wieder da. Siehe Logfile

2013.11.12 14:42:11 1: 192.168.2.50:1000 disconnected, waiting to reappear
2013.11.12 14:43:12 1: 192.168.2.50:1000 reappeared (OG_HMLAN)
2013.11.12 14:44:11 1: 192.168.2.50:1000 disconnected, waiting to reappear
2013.11.12 14:45:12 1: 192.168.2.50:1000 reappeared (OG_HMLAN)
2013.11.12 14:46:11 1: 192.168.2.50:1000 disconnected, waiting to reappear
2013.11.12 14:47:12 1: 192.168.2.50:1000 reappeared (OG_HMLAN)
2013.11.12 14:54:11 1: 192.168.2.50:1000 disconnected, waiting to reappear
2013.11.12 14:55:12 1: 192.168.2.50:1000 reappeared (OG_HMLAN)
2013.11.12 15:02:11 1: 192.168.2.50:1000 disconnected, waiting to reappear
2013.11.12 15:03:12 1: 192.168.2.50:1000 reappeared (OG_HMLAN)
2013.11.12 15:04:11 1: 192.168.2.50:1000 disconnected, waiting to reappear
2013.11.12 15:05:13 1: 192.168.2.50:1000 reappeared (OG_HMLAN)
2013.11.12 15:06:11 1: 192.168.2.50:1000 disconnected, waiting to reappear
2013.11.12 15:07:13 1: 192.168.2.50:1000 reappeared (OG_HMLAN)
2013.11.12 15:20:11 1: 192.168.2.50:1000 disconnected, waiting to reappear
2013.11.12 15:21:13 1: 192.168.2.50:1000 reappeared (OG_HMLAN)
2013.11.12 15:22:11 1: 192.168.2.50:1000 disconnected, waiting to reappear
2013.11.12 15:23:12 1: 192.168.2.50:1000 reappeared (OG_HMLAN)
2013.11.12 15:30:11 1: 192.168.2.50:1000 disconnected, waiting to reappear
2013.11.12 15:31:13 1: 192.168.2.50:1000 reappeared (OG_HMLAN)
2013.11.12 15:32:11 1: 192.168.2.50:1000 disconnected, waiting to reappear
2013.11.12 15:33:12 1: 192.168.2.50:1000 reappeared (OG_HMLAN)
2013.11.12 15:34:11 1: 192.168.2.50:1000 disconnected, waiting to reappear
2013.11.12 15:35:13 1: 192.168.2.50:1000 reappeared (OG_HMLAN)


Das System ist aktuell (gerade heute morgen noch ein Update gemacht
ich habe keine PRESENCE oder WOL Devices drin
alles andere im Netzwerk ist ausgeschaltet (NAS etc.)

Und das beste: wenn ich attr global verbose 5 setze, dann habe ich keine disconnects (zumindest nichts mehr im Logfile)?

Ich blick nicht mehr, was ich sonst noch so probieren könnte
Titel: Das leidige Thema - HMLAN disconnected
Beitrag von: MarkusN am 12 November 2013, 15:51:50
Hallo FHEM-Gemeinschaft!

Seit zwei Wochen betreibe ich eine minimale HM-Konfiguration, die derzeit lediglich aus einem HMLAN und einem Temperatur-/Luftfeuchtesensor HM-WDS10-TH-O besteht. Die Inbetriebnahme (zu dem Zeitpunkt lief bei mir noch FHEM 5.4) lief reibungslos, auch die restlichen Devices die ich momentan noch nicht nutze funktionieren wunderbar, auch die BidCos-Kommunikation läuft. Jedoch habe ich recht früh bemerkt dass FHEM mehr oder weniger regelmäßig die Verbindung zum HMLAN-Adapter verliert, das sah in der Logfile dann so aus:

[...]
2013.11.06 08:25:04 1: hmlan:1000 reappeared (hmlan)
2013.11.06 08:24:59 1: hmlan:1000 disconnected, waiting to reappear
2013.11.06 08:11:02 1: hmlan:1000 reappeared (hmlan)
2013.11.06 08:10:57 1: hmlan:1000 disconnected, waiting to reappear
2013.11.06 07:59:04 1: hmlan:1000 reappeared (hmlan)
2013.11.06 07:58:54 1: hmlan:1000 disconnected, waiting to reappear
2013.11.06 07:45:05 1: hmlan:1000 reappeared (hmlan)
2013.11.06 07:45:00 1: hmlan:1000 disconnected, waiting to reappear
2013.11.06 06:29:02 1: hmlan:1000 reappeared (hmlan)
2013.11.06 06:28:57 1: hmlan:1000 disconnected, waiting to reappear
2013.11.06 06:17:03 1: hmlan:1000 reappeared (hmlan)
2013.11.06 06:16:58 1: hmlan:1000 disconnected, waiting to reappear
2013.11.06 05:55:05 1: hmlan:1000 reappeared (hmlan)
2013.11.06 05:55:00 1: hmlan:1000 disconnected, waiting to reappear
2013.11.06 05:41:03 1: hmlan:1000 reappeared (hmlan)
2013.11.06 05:40:58 1: hmlan:1000 disconnected, waiting to reappear
2013.11.06 05:37:04 1: hmlan:1000 reappeared (hmlan)
2013.11.06 05:36:59 1: hmlan:1000 disconnected, waiting to reappear
2013.11.06 04:09:50 1: hmlan:1000 reappeared (hmlan)
2013.11.06 04:09:45 1: hmlan:1000 disconnected, waiting to reappear
[...]


Kommt relativ häufig vor, meistens mind. 1x pro Stunde.  Man sieht jedoch deutlich dass der HMLAN nach wenigen Sekunden wieder da ist.
Mutig wie ich bin habe ich vor drei Tagen ein FHEM-Update angestoßen, in der Hoffnung dass meine restliche Installation (hauptsächlich 1-Wire und Max!) darunter nicht leidet. Glücklicherweise funktioniert auch noch alles, das HMLAN-Problem hat sich jedoch nicht verbessert, ganz im Gegenteil:

[...]
2013.11.12 15:26:48 1: hmlan:1000 reappeared (hmlan)
2013.11.12 15:25:47 1: hmlan:1000 disconnected, waiting to reappear
2013.11.12 15:19:43 1: hmlan:1000 reappeared (hmlan)
2013.11.12 15:18:43 2: HMLAN_Parse: hmlan new condition disconnected
2013.11.12 15:18:43 1: hmlan:1000 disconnected, waiting to reappear
2013.11.12 15:07:47 2: HMLAN_Parse: hmlan new condition ok
2013.11.12 15:07:47 2: HMLAN_Parse: hmlan new condition init
2013.11.12 15:07:47 1: hmlan:1000 reappeared (hmlan)
2013.11.12 15:06:43 2: HMLAN_Parse: hmlan new condition disconnected
2013.11.12 15:06:43 1: hmlan:1000 disconnected, waiting to reappear
2013.11.12 14:16:44 2: HMLAN_Parse: hmlan new condition ok
2013.11.12 14:16:44 2: HMLAN_Parse: hmlan new condition init
2013.11.12 14:16:44 1: hmlan:1000 reappeared (hmlan)
2013.11.12 14:15:43 2: HMLAN_Parse: hmlan new condition disconnected
2013.11.12 14:15:43 1: hmlan:1000 disconnected, waiting to reappear
2013.11.12 13:56:45 2: HMLAN_Parse: hmlan new condition ok
2013.11.12 13:56:44 2: HMLAN_Parse: hmlan new condition init
2013.11.12 13:56:44 1: hmlan:1000 reappeared (hmlan)
2013.11.12 13:55:43 2: HMLAN_Parse: hmlan new condition disconnected
2013.11.12 13:55:43 1: hmlan:1000 disconnected, waiting to reappear
2013.11.12 13:38:46 2: HMLAN_Parse: hmlan new condition ok
2013.11.12 13:38:46 2: HMLAN_Parse: hmlan new condition init
2013.11.12 13:38:46 1: hmlan:1000 reappeared (hmlan)
2013.11.12 13:37:43 2: HMLAN_Parse: hmlan new condition disconnected
2013.11.12 13:37:43 1: hmlan:1000 disconnected, waiting to reappear
2013.11.12 13:36:47 2: HMLAN_Parse: hmlan new condition ok
2013.11.12 13:36:47 2: HMLAN_Parse: hmlan new condition init
2013.11.12 13:36:47 1: hmlan:1000 reappeared (hmlan)
2013.11.12 13:35:43 2: HMLAN_Parse: hmlan new condition disconnected
2013.11.12 13:35:43 1: hmlan:1000 disconnected, waiting to reappear
[...]


Die Disconnects sind im Schnitt gleich viele, allerdings ist die Zeit in der der HMLAN weg ist länger geworden, nämlich ca. eine Minute. Und das ist für eine vernünftige Installation nicht mehr tragbar.

FHEM läuft mittlerweile seit über einem Jahr auf einem RaspberryPi mit 256MB Ram und hat seinen Dienst immer problemlos verrichtet, die Sache mit dem HMLAN verärgert mich jedoch sehr.  Der HMLAN hat die aktuelle Firmware (0.961), eine feste IP-Adresse und die AES-Encrypted LAN Communication ist deaktiviert. Eine saubere LAN-Verbindung besteht auch, zwischen dem RaspberryPi und dem HMLAN liegen zwei Gbit-Switche.

Diskussionen wie diese (http://forum.fhem.de/index.php/topic,13490.msg83587.html#msg83587) sind leider im Sand verlaufen, ohne dass sich der OP wieder gemeldet hat.

Wie bekomme ich das in den Griff?

Grüße,

Markus
Titel: Antw:HM-LAN Disconnect
Beitrag von: MarkusN am 12 November 2013, 15:53:14
Mist, da bist du mir ja zuvor gekommen :D

Habe quasi einen identischen Post geschrieben. Gut dass ich damit aktuell nicht alleine bin.
Titel: Antw:HM-LAN Disconnect
Beitrag von: bugster_de am 12 November 2013, 18:20:41
was mich wundert: momentan tauchen alle meine Probleme (siehe andere Posts) auch bei mehreren Usern auf.
Titel: Antw:Das leidige Thema - HMLAN disconnected
Beitrag von: bugster_de am 12 November 2013, 18:38:30
das war dann wohl ein doppel-Post. Ich habe das gleiche Problem auch gerade eingestellt.
Titel: Antw:HM-LAN Disconnect
Beitrag von: martinp876 am 13 November 2013, 08:31:57
hi,

das ist ja ein interessanter testfall (schade für dich... sorry)
kannst du mitloggen mit
attr global verbose 1
attr global mseclog 1
attr OG_HMLAN loglevel 1

danke
Martin

p.s. habe die Themen zusammengefasst. Bitte um die Logs.


Titel: Antw:HM-LAN Disconnect
Beitrag von: MarkusN am 13 November 2013, 08:51:16
Hallo Martin,

habe quasi das gleiche Problem (siehe anderer Thread von mir) und habe mir mal erlaubt deinen Vorschlag umzusetzen. Anbei ein Auszug der Logfile als der HMLAN sich mal wieder verabschiedet hat:


[...]
2013.11.13 08:48:26.840 1: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0707502 d:1E9CFB O:737BB2 t:32AD5945 IDcnt:0000
2013.11.13 08:48:26.112 1: HMLAN_Send:  hmlan I:K
2013.11.13 08:48:01.111 1: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0707502 d:1E9CFB O:737BB2 t:32ACF4C0 IDcnt:0000
2013.11.13 08:48:01.105 1: HMLAN_Send:  hmlan I:K
2013.11.13 08:47:53.723 1: HMLAN_Parse: hmlan R:E20DB0B   stat:0000 t:32ACD081 d:FF r:FFCF     m:F4 8670 20DB0B 000000 00AE3B
2013.11.13 08:47:36.103 1: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0707502 d:1E9CFB O:737BB2 t:32AC930D IDcnt:0000
2013.11.13 08:47:36.097 1: HMLAN_Send:  hmlan I:K
2013.11.13 08:47:11.098 1: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0707502 d:1E9CFB O:737BB2 t:32AC315B IDcnt:0000
2013.11.13 08:47:11.091 1: HMLAN_Send:  hmlan I:K
2013.11.13 08:46:47.914 1: HMLAN_Parse: hmlan new condition ok
2013.11.13 08:46:47.913 1: HMLAN_Parse: hmlan R:R506D4007 stat:0002 t:00000000 d:FF r:7FFF     m:99 8112 737BB2 000001
2013.11.13 08:46:47.910 1: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0707502 d:1E9CFB O:737BB2 t:32ABCF62 IDcnt:0000
2013.11.13 08:46:46.086 1: HMLAN_Send:  hmlan S:S506D4007 stat:  00 t:00000000 d:01 r:506D4007 m:99 8112 737BB2 000001
2013.11.13 08:46:46.031 1: HMLAN_Parse: hmlan new condition init
2013.11.13 08:46:46.030 1: HMLAN_Send:  hmlan I:T1A15DCD6,04,00,00000000
2013.11.13 08:46:46.028 1: HMLAN_Send:  hmlan I:Y03,00,
2013.11.13 08:46:46.026 1: HMLAN_Send:  hmlan I:Y02,00,
2013.11.13 08:46:46.025 1: HMLAN_Send:  hmlan I:Y01,00,
2013.11.13 08:46:46.023 1: HMLAN_Send:  hmlan I:C
2013.11.13 08:46:46.022 1: HMLAN_Send:  hmlan I:A737BB2
2013.11.13 08:46:46.014 1: hmlan:1000 reappeared (hmlan)
2013.11.13 08:45:44.648 1: HMLAN_Parse: hmlan new condition disconnected
2013.11.13 08:45:44.607 1: hmlan:1000 disconnected, waiting to reappear
2013.11.13 08:45:44.601 1: HMLAN_Send:  hmlan I:K
2013.11.13 08:45:12.693 1: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0707502 d:1E9CFB O:737BB2 t:32AA62C7 IDcnt:0000
2013.11.13 08:45:12.687 1: HMLAN_Send:  hmlan I:K
2013.11.13 08:45:01.166 1: HMLAN_Parse: hmlan R:E20DB0B   stat:0000 t:32AA26C2 d:FF r:FFCF     m:F3 8670 20DB0B 000000 00AF3C
2013.11.13 08:44:47.679 1: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0707502 d:1E9CFB O:737BB2 t:32AA010D IDcnt:0000
2013.11.13 08:44:47.673 1: HMLAN_Send:  hmlan I:K
2013.11.13 08:44:22.667 1: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0707502 d:1E9CFB O:737BB2 t:32A99F56 IDcnt:0000
2013.11.13 08:44:22.661 1: HMLAN_Send:  hmlan I:K
2013.11.13 08:43:57.661 1: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0707502 d:1E9CFB O:737BB2 t:32A93DA4 IDcnt:0000
2013.11.13 08:43:57.654 1: HMLAN_Send:  hmlan I:K
2013.11.13 08:43:31.326 1: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0707502 d:1E9CFB O:737BB2 t:32A8D6C0 IDcnt:0000
2013.11.13 08:43:31.318 1: HMLAN_Send:  hmlan I:K
2013.11.13 08:43:06.143 1: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0707502 d:1E9CFB O:737BB2 t:32A8745F IDcnt:0000
2013.11.13 08:43:06.137 1: HMLAN_Send:  hmlan I:K
[...]


Was mir sofort auffällt:

2013.11.13 08:46:46.014 1: hmlan:1000 reappeared (hmlan)
2013.11.13 08:45:44.648 1: HMLAN_Parse: hmlan new condition disconnected
2013.11.13 08:45:44.607 1: hmlan:1000 disconnected, waiting to reappear
2013.11.13 08:45:44.601 1: HMLAN_Send:  hmlan I:K


FHEM scheint nach dem Senden des K garnicht lange zu warten, sondern sagt direkt dass der HMLAN disconnected ist.
Titel: Antw:HM-LAN Disconnect
Beitrag von: martinp876 am 13 November 2013, 09:58:49
Hallo Markus,

das ist ein klarer keep-alive Verstoss.

Zitat08:45:44.648 Parse: hmlan new condition disconnected
08:45:44.607 1000 disconnected, waiting to reappear
08:45:44.601 Send:  hmlan I:K
*** 32  sec delay ***
08:45:12.693 Parse: hmlan V:03C1 sNo:JEQ0707502 d:1E9CFB O:737BB2 t:32AA62C7 IDcnt:0000
08:45:12.687 Send:  hmlan I:K
die 32sec sind zu lang. HMLAN mache einen autonomen disconnect. 00_HMLAN kann garnicht warten, der disconnect wird - korrekter weise - von IODev gemeldet, weil die TCP connection zusammengebrochen ist. Das ist von HMLAN beabsichtingt und hat soweit alles seine Richtigkeit.
Wir haben es in diesem Fall mit einem "einfachen" timeout zu tun.

Was ist zu tun
1) erkennen des Problems
in der neusten Version von FHEM solltest du bei HMLAN einen Parameter sehen
msgKeepAlive dlyMax:0.01 bufferMin:4

das sagt dir, dass das der keep-Alive trigger maximales  10ms später kam, als ich programmiert hatte (also quasi pünktlich). Ich hatte noch 4 sec Puffer bis zum voraussichtlichen HMLAN disconnect. Ich habe 25 sec Periode eingestellt, bei 30sec erwarte ich ein disconnect - ich runde nach Integer - also 4sec ist ok.
==> mein System hat im beobachteten Zeitraum kein Problem
??> wie sieht es bei dir aus?

2) Symptom beheben
Mit dem Attribut wdTimer kannst du den Timer von 25sec reduzieren und somit dem Puffer (jetzt 5 sec) vergrössern. Damit lassen sich delays deines systems ausgleichen.

3) Ursachen des Problems
die eigentliche Ursache für den Delay ist (noch bin ich überzeugt) nicht der HM-part von FHEM. Du hat voraussichtlich einen Prozess laufen, der länger als 5sec FHEM blockiert. Noch hat FHEM (leider) keine Überwachung und Auswertung, welcher Prozess wie lange braucht - und somit wie lange alles andere blockiert.

Gruss Martin
Titel: Antw:HM-LAN Disconnect
Beitrag von: MarkusN am 13 November 2013, 10:49:34
Hallo Martin,

danke für diese ausführliche Antwort. Ich habe auch bereits einen ersten Verdacht. Nachdem du erwähnt hast dass FHEM vermutlich zu lange blockiert wird ist mir eingefallen dass mein Nagios einige meiner Temperatursensoren über fhem.pl abfragt. Das habe ich jetzt mal deaktivert, ggf werde ich es so umbauen dass Nagios die Daten nicht über fhem.pl sondern via owserver abfragt. Bis jetzt gibt es jedenfalls seit über einer Stunde keinen Disconnect mehr.

msgKeepAlive sagt bei mir jedenfalls: "dlyMax:12.498 bufferMin:-7"

Ich hoffe dass ich mein Problem damit gefunden habe.
Titel: Antw:HM-LAN Disconnect
Beitrag von: martinp876 am 13 November 2013, 11:08:11
Hallo Markus,

zumindest eines, das ist sicher.
schön zu sehen, dass die delay-berechnung funktioniert :-)
Ich werden noch eine Beschreibung basteln um die Info verständlich zu machen.

Gruss Martin
Titel: Antw:HM-LAN Disconnect
Beitrag von: MarkusN am 14 November 2013, 13:24:29
Hallo Martin,

meine Nagios-Abfrage über fhem.pl scheint nicht alleiniger Auslöser für meine Probleme zu sein. Mein msgKeepAlive beträgt mittlerweile "dlyMax:8.107 bufferMin:6", also immer noch weit von optimalen Werten entfernt. Die Disconnects sind in etwa gleich häufig vorgekommen. Ich habe jetzt wdTimer auf 15 gesetzt und habe seit 3 Stunden Ruhe vor Disconnects.

Die Zahlen habe ich noch nicht wirklich verstanden. Das HMLAN-Modul sendet regelmäßig Pakete (das "K"?) an den HMLAN-Adapter, welcher daraufhin eine Art Ack schickt. Dieser Ack muss innerhalb einer bestimmten Zeit geschickt werden, ansonsten denkt FHEM der HMLAN ist nicht mehr erreichbar. Ist das so weit richtig? Meinst du mit Keep-Alive Trigger die Antwort des HMLAN-Adapters? Und warum ist bufferMin bei mir manchmal negativ? Fragen über Fragen. Und jetzt die wichtigste: Habe ich mir durch die Erhöhung des wdTimer eine mögliche Verzögerung bei der Befehlsausführung erkauft?

Danke und Grüße,

Markus
Titel: Antw:HM-LAN Disconnect
Beitrag von: martinp876 am 14 November 2013, 15:29:08
Hallo Markus,

an einer erweiterten Doku arbeite ich  noch...
dlyMax:8.107 bufferMin:6

Das keepalive kam maximal 8sec "verspätet", also spater als über dem timer eingestellt. Somit gibt es einen "Task" oder auch eine Gruppe von tasks die 8sec das abarbeiten des timers verhindern. Das kann jedem timer in FHEM so gehen. 8sec sind aus meiner sicht kritisch - und sollte es ein einzelner "task" sein eigentlich nicht hinnehmbar in einem "echtzeitsystem". Müsste man suchen gehen.
Du hattest seit der letzten Änderung des wdTimer mindestens 6 sec Puffer zwischen keep-alive message und erwartetem HMLAN disconnect.

Wenn du jetzt 15 eingestellt hast wird das keep-alive ("k") alle 15 sec gesendet. Es gab aber (s.o.) manchmal 8 sec delay, also trigger nach 23sec. Du hattest also <7sec puffer (entspricht "6" wen man "int" macht)
Die Berechnungen stimmen als. Keep-Alive-mässig bist du also im grünen Bereich.

Die Berechnung von bufferMin ist einfach:  30 - "zeit-zwische-2-keep-alive". Wenn die Zahl negativ ist kam der trigger zu spät. Bei 0 oder negativ ist damit zu rechnen, dass der HMLAN einen disconnect gemacht hat.

Du hat 2 Möglichkeiten, dem zu begegnen: schneller triggern (wdTimer runter setzen) oder den "langweiler" finden, der FHEM so lange blockiert.

Die Überwachung der keep-alive-Antwort hast du richtig erkannt. Diese führt aber nach den logs nicht zu einem Problem bei dir. Diese hat die Aufgabe zum einen das Protokol zu komplettieren, ggf ein keep-alive nachzusenden falls es verloren geganben ist und zum 2. einen schnelleren disconnect/reconnect durchzuführen sollte der HMLAN "verstorben" sein. Das kann u.U. manche message-sequence "retten". - wie gesagt, nicht bei dir aufgetreten.

Mit dem heruntersetzen des keepalive verzögerst du erst einmal nicht. Das ist nicht kritisch - und 15 ist sicher vertretbar. Du sendest jetzt doppelt so viele keep-alives  - aber das belastet das HMLAN auch nicht in seiner transmission performance.
Was mich stören würde sind die 8sec. Irgendwann - wie oft auch immer -ist ein task dran der ganz FHEM 8 sec blockiert (könnte auch eine sequenz sein...). Du kannst davon ausgehen, dass dann ganz FHEM steht. Es werden auch andere Timer auslaufen, messages werden wiederholt oder die Übertragung abgebrochen. Einfach alles, was über die Zentrale läuft.
Viele sehen das gelassen - mich stört es immens. Wenn das schule macht und es immer mehr dieser Kandidaten gibt werden sie sich akkumulieren. Aus meiner Sicht sollte ein einzelner task nach spätestens 1sec beendet sein - das ist schon lang.
Aktuell gibt es noch keine Möglichkeit (die mir bekannt ist) daß es ein User messen könnte. Evtl bastle ich einmal etwas.

Gruss Martin
Titel: Antw:HM-LAN Disconnect
Beitrag von: bugster_de am 18 November 2013, 17:25:00
Hi,

ich habe zwar den Task gestartet, aber da ja alles so geht wie es soll habe ich nicht mehr rein geschaut.

Das mit der Performance ist natürlich interessant. Ich beobachte seit geraumer Zeit dass meine FB7390 im Schnitt bei 80% CPU Load hängt. Somit kann es natürlich sein, dass irgendein Task die Ausfürhung der Rückmeldungsauswertung in HM-LAN blockiert.
Wie kann ich rausfinden, wer der Schuldige ist? Gibt es Performance Logging Tools für Perl?

-->Martinp876: im Prinzip ist das dann aber ein unglückliches Design für so ein "Echtzeitsystem". Wenn de eine "Task" den Buschstaben K sendet und dann in fester Zeit die Ausführung unr Rückmeldung geprüft werden muß, dann muss es eigentlich pre-emptive sein, sonst geht das mit Ansage schief. Ich weiß, da kannst Du nichts dafür, denn das ist halt in Perl / FHEM mal so.
Im Prinzip müsste man im Design einen Interrupt vorsehen. Der zugehörige Handler speichert dann nur die ein gegangen Antwort des HM-LAN inkl. Zeitstempel. Und sobald dein HM-LAN Modul nach Ablauf des InternalTimer wieder dran kommt wertet es den gespeicherten Zeitstempel aus.
Titel: Antw:HM-LAN Disconnect
Beitrag von: martinp876 am 19 November 2013, 19:12:38
wenn die FB auf 80% hängt solltest du erst einmal den Unix-level bemühen, nachsehen ob Perl/fhem das Problem ist (oder zu welchen Anteil) und was sonst so los ist.

Zitat-->Martinp876: im Prinzip ist das dann aber ein unglückliches Design für so ein "Echtzeitsystem"
ja.
Bitte an die Entwickler der Platform wenden. FHEM hat definitiv Grenzen!

ZitatWenn de eine "Task" den Buschstaben K sendet und dann in fester Zeit die Ausführung unr Rückmeldung geprüft werden muß, dann muss es eigentlich pre-emptive sein, sonst geht das mit Ansage schief.
nein.
Die Timer laufen in gleichen Threat und werden "symetrisch" mit verzögert. Das ist wiederum ein Vorteil des Designs.

ZitatIch weiß, da kannst Du nichts dafür, denn das ist halt in Perl / FHEM mal so.
Nicht Perl, aber FHEM

ZitatIm Prinzip müsste man im Design einen Interrupt vorsehen. Der zugehörige Handler speichert dann nur die ein gegangen Antwort des HM-LAN inkl. Zeitstempel. Und sobald dein HM-LAN Modul nach Ablauf des InternalTimer wieder dran kommt wertet es den gespeicherten Zeitstempel aus.
Ich denke du siehst ein Problem wo keins ist. Es gibt Probleme - aber die rechtzeitige Prüfung der Antwort ist eher keines.
Das rechtzeitige senden des "k" schon häufiger.

Gruss Martin
Titel: Antw:HM-LAN Disconnect
Beitrag von: Jojo11 am 28 Januar 2014, 19:19:50
Hallo,

auch ich habe schon seit längerem dieses Phänomen beobachtet und "HMLAN disconnected, waiting to reappear"-Einträge im log. Bislang war mir vollkommen unklar, woran es liegen könnte. Nun habe ich ein absolut reproduzierbares Szenario entdeckt. Ich habe eine Seite (einen Raum "Plots") mit 12 Temperaturplots. Wenn ich diese Seite im Browser aufrufe, dauert das so ca. 40 Sekunden. Während die Seite aufgebaut wird, disconnected der HMLAN. Ist es richtig, dass der Plot-Aufbau FHEM mehr oder weniger lahm legt, so dass die HMLAN-Lebenszeichen nicht mehr rechtzeitig empfangen werden können? Kann man das irgendwie umgehen oder z.B. den Seitenaufbau in der Priorität herabsetzen?

schöne Grüße
Jo
Titel: Antw:HM-LAN Disconnect
Beitrag von: Joachim am 28 Januar 2014, 19:52:38
ZitatIst es richtig, dass der Plot-Aufbau FHEM mehr oder weniger lahm legt,
Ja, eventuell ist plotfork für Dich die Lösung.

Gruß Joachim
Titel: Antw:HM-LAN Disconnect
Beitrag von: Jojo11 am 28 Januar 2014, 19:57:21
Danke, das kannte ich noch nicht. Werde ich mal ausprobieren.

schöne Grüße
Jo
Titel: Antw:HM-LAN Disconnect
Beitrag von: RainerW am 16 Februar 2014, 23:05:24
Hallo Zusammen!

Bei mir sieht's ähnlich aus:


2014.02.16 22:18:29 0: Server started with 28 defined entities (version $Id: fhem.pl 4905 2014-02-13 08:04:53Z rudolfkoenig $, os linux, user fhem, pid 28707)
2014.02.16 22:18:29 3: Device BadEG.Fensterkontakt added to ActionDetector with 028:00 time
2014.02.16 22:18:29 1: HMLAN_Parse: HMLAN1 new condition ok
2014.02.16 22:18:30 2: CUL_HM set FL.Tuerschloss statusRequest
2014.02.16 22:40:03 1: HMLAN_Parse: HMLAN1 new condition timeout
2014.02.16 22:40:03 1: 192.168.178.57:1000 disconnected, waiting to reappear
2014.02.16 22:40:03 1: HMLAN_Parse: HMLAN1 new condition disconnected
2014.02.16 22:40:11 1: 192.168.178.57:1000 reappeared (HMLAN1)
2014.02.16 22:40:11 1: HMLAN_Parse: HMLAN1 new condition init
2014.02.16 22:40:25 1: HMLAN_Parse: HMLAN1 new condition ok
2014.02.16 22:40:40 1: HMLAN_Parse: HMLAN1 new condition timeout
2014.02.16 22:40:40 1: 192.168.178.57:1000 disconnected, waiting to reappear
2014.02.16 22:40:40 1: HMLAN_Parse: HMLAN1 new condition disconnected
2014.02.16 22:41:48 1: 192.168.178.57:1000 reappeared (HMLAN1)
2014.02.16 22:41:48 1: HMLAN_Parse: HMLAN1 new condition init
2014.02.16 22:41:48 1: HMLAN_Parse: HMLAN1 new condition ok


Bisher habe ich beobachtet, dass es ca. alle 30min oder 1h auftaucht. Im Moment passiert es aber häufiger. Nur einen Fensterkontakt und Keymatic dran. PRESENCE Abfrage habe ich erstmal deaktiviert. Wollte sehen, ob das Problem dort liegt. Jedoch hat es nicht geholfen.

HM-LAN Modul und Rasp-Pi hängen an einem Switch direkt nebeneinander.

Mehr ist z.Z. noch nicht eingerichtet hat ihr eine Idee?

Gruß

Rainer
Titel: Antw:HM-LAN Disconnect
Beitrag von: martinp876 am 17 Februar 2014, 08:19:43
der disconnect kommt von einem timeout - die antwort auf das keepalive dauert laenger als 1sec
setze das Attribut
HMLAN_KeepAliveCheck

auf 5  und beobachte.

falls es klappt frage dich, warum dein System so langsam ist. Evtl nutze apptime
Titel: Antw:HM-LAN Disconnect
Beitrag von: hokascha am 17 Februar 2014, 19:46:02
Hallo,

ich habe hier das gleiche Problem:


(version $Id: fhem.pl 4935 2014-02-15 08:34:09Z rudolfkoenig $, os linux, user fhem, pid 32243)
2014.02.17 19:38:26 1: 192.168.178.36:1000 disconnected, waiting to reappear
2014.02.17 19:38:26 1: HMLAN_Parse: HMLAN1 new condition disconnected
2014.02.17 19:39:26 1: 192.168.178.36:1000 reappeared (HMLAN1)
2014.02.17 19:39:26 1: HMLAN_Parse: HMLAN1 new condition init
2014.02.17 19:39:27 1: HMLAN_Parse: HMLAN1 new condition ok
2014.02.17 19:40:11 1: 192.168.178.36:1000 disconnected, waiting to reappear
2014.02.17 19:40:11 1: HMLAN_Parse: HMLAN1 new condition disconnected
2014.02.17 19:41:11 1: 192.168.178.36:1000 reappeared (HMLAN1)
2014.02.17 19:41:11 1: HMLAN_Parse: HMLAN1 new condition init
2014.02.17 19:41:11 1: HMLAN_Parse: HMLAN1 new condition ok
2014.02.17 19:41:40 1: 192.168.178.36:1000 disconnected, waiting to reappear
2014.02.17 19:41:40 1: HMLAN_Parse: HMLAN1 new condition disconnected


msgKeepAlive        dlyMax:5.303 bufferMin:14

habe schon das wdTimer-Attribut des HMLAN auf 15 oder 5 gesetzt, bringt nichts.

Ein Attribut namens HMLAN_KeepAliveCheck kann ich nirgends finden...

Noch jemand eine Idee? Danke!

Grüße,

Kevin
Titel: Antw:HM-LAN Disconnect
Beitrag von: martinp876 am 18 Februar 2014, 08:12:45
Zitatich habe hier das gleiche Problem:
kann ich nicht erkennen. hast du auch timeout?
2014.02.16 22:40:40 1: HMLAN_Parse: HMLAN1 new condition timeout

msgKeepAlive        dlyMax:5.303 bufferMin:14
bedeuted nicht, dass HMLAN zu langsam gearbeitet hat sondern dass FHEM zu langsam war.
Aber immerhin hattest du  noch 14sec puffer in diesem Fall

Zitathabe schon das wdTimer-Attribut des HMLAN auf 15 oder 5 gesetzt, bringt nichts.
klar - war zu erwarten.

ZitatNoch jemand eine Idee? Danke!
mal mit apptime anfangen zu suchen, wer ein bummelkandidat in deinem System sein koennte.

Gruss Martin
Titel: Antw:HM-LAN Disconnect
Beitrag von: Jojo11 am 18 Februar 2014, 20:57:57
Hallo,

ich würde mir gerne immer dann eine email schicken lassen, wenn der HMLAN mal wieder disconnected ist (für die Fehlersuche).
Jetzt habe ich gedacht, ich könnte ja InternalVal("HMLAN1","STATE","0") abfragen (opened/disconnected).
Aber wie macht man das am elegantesten? Disconnected ist er ja meistens nur wenige Sekunden - das müßte man halt mitbekommen. Sowas wie "event-on-update-reading" kann man sicher nicht verwenden, oder?

schöne Grüße
Jo
Titel: Antw:HM-LAN Disconnect
Beitrag von: martinp876 am 19 Februar 2014, 07:12:05
hi Jo,
ueber ein notify.
evtl solltest du das Reading "cond" nutzen
Gruss Martin
Titel: Antw:HM-LAN Disconnect
Beitrag von: justme1968 am 19 Februar 2014, 08:32:37
schau mal ob dir plotfork hilft. dann werden die plots im hintergrund erzeugt.

gruss
  andre
Titel: Antw:HM-LAN Disconnect
Beitrag von: Jojo11 am 19 Februar 2014, 17:58:57
Zitat von: martinp876 am 19 Februar 2014, 07:12:05
hi Jo,
ueber ein notify.
evtl solltest du das Reading "cond" nutzen
Gruss Martin

Danke, werde ich mir mal genauer anschauen.
Danke auch justme1968, mit plotfork habe ich schon ein wenig experimentiert.

schöne Grüße
Jo
Titel: Antw:HM-LAN Disconnect
Beitrag von: MarkusN am 06 März 2014, 08:15:30
Hallo,

ich habe meine FHMLAN-Disconnects in den Griff bekommen in dem ich auf leistungsfähigere Hardware umgestiegen bin. Mein RaspberryPi hatte einfach mit anderen Sachen noch zu viel zu tun. Gelegentlich habe ich immer noch sehr wenige HMLAN-Disconnects, besonders wenn FHEM mehrere Tage gelaufen ist. Nach einem Neustart ist dann aber wieder einige Zeit ruhe.

Ich habe einen Blogeintrag geschrieben der euch unterstützen könnte die Gesamtperformance von FHEM in den Griff zu bekommen: http://blog.chanoa.de/fhem-performance

Grüße,

Markus
Titel: Antw:HM-LAN Disconnect
Beitrag von: JoeALLb am 06 März 2014, 08:55:54
Welche DB verwendest Du für DBLog? sqlite oder mysql?
Titel: Antw:HM-LAN Disconnect
Beitrag von: MarkusN am 06 März 2014, 08:58:24
Ich nutze MySQL.

Grüße,

Markus
Titel: Antw:HM-LAN Disconnect
Beitrag von: JoeALLb am 06 März 2014, 09:00:23
Dachte ich mir, wegen den 50% CPU auslastung am RPI.
Wenn du den DbLogType auf history stellst, geht alles viel schneller, da Mysql statt 3 aktionen pro Logeintrag nur eine Aktion machen muss.
Titel: Antw:HM-LAN Disconnect
Beitrag von: MarkusN am 06 März 2014, 09:04:43
Interessant. Danke für die Info, dieses Attribut scheint, zumindest in der Commandref, überhaupt nicht dokumentiert zu sein. Kannst du mehr Details zu dem Attribut geben? Werde meinen Blogpost dann gerne erweitern.

Die Auslastung des Pis hängt aber auch mit den vielen anderen Diensten zusammen die darauf liefen.

Grüße,

Markus
Titel: Antw:HM-LAN Disconnect
Beitrag von: JoeALLb am 06 März 2014, 09:09:15
Dieses Attribut definiert, in welche Tabelle auf dem SQL-Server geloggt werden soll.
Standard wird in beide Tabellen geloggt.

In History landen alle Logeinträge, in Current nur das jeweils aktuellste pro device pro reading.
Aus diesem Grund wird in Current immer ein insert versucht und wenn dieses scheitert, ein Update gemacht.
(--> das könnte besser gelöst werden).
Current wird aber bis auf wenige Ausnahmen mE nicht benötigt.

Die CPU-Auslastung sinkt dadurch deutlich!, ich denke nicht dass der Rest der Konfiguration daran "schuld" ist...