hmLanQlen - bekannte Probleme? Disconnects und Verzögerung

Begonnen von vbs, 14 Dezember 2014, 01:12:24

Vorheriges Thema - Nächstes Thema

vbs

Ich habe neulich das Attribut "hmLanQlen" entdeckt, mit dem dann mehrere Befehle parallel versendet werden können (also es muss nicht auf ACK gewartet werden). Ich finde das sehr interessant, da zum Beispiel drei Lampen wirklich subjektiv zeitgleich angehen und nicht kurz versetzt. Mir sind nun bei Nutzung jedoch zwei seltsame Effekte aufgefallen. Die Frage, die sich mir stellt ist, ob es generell nicht empfohlen wird, hmLanQlen mit einem Wert größer 1 zu verwenden? Sind das "known issues" oder müsste das eigentlich robust funktionieren?

Ich habe mit folgendem Szenario getestet:
Über einen Wandtaster HM-PB-2-WM55 wird ein fhem-Trigger ausgelöst, der letztendlich drei Lampen (per Dimmer HM-LC-Dim1L-Pl-2) ein- bzw. ausschaltet.
Als Device wird HMLAN verwendet. Ich habe das Gefühl, dass die Problem mit HMUSB nicht auftreten? Müsste ich aber nochmals testen...

Wenn hmLanQlen auf "1" steht, dann klappt das zuverlässig, jedoch ist eben ein kleiner Versatz beim Schalten der drei Lampen sichtbar.


Wenn hmLanQlen auf "3" steht, dann Schalten die Lampen zwar zeitgleich, jedoch habe ich dabei die folgenden zwei Probleme. Die Probleme treten nur auf, wenn ich wirklich mit dem Wandtaster teste. Wenn ich das gleiche Event, das der Wandtaster erzeugt, direkt als fhem-Kommando eingebe (zB. "trigger wz_wandTaster_Btn2 trigger:.Short.125"), dann klappt alles super. Also es passiert nur in Kombination mit dem echten Wandtaster.

Problem 1:
Es kommt häufig vor, dass zwei Lampen sofort schalten, aber die dritte dann erst nach einer Verzögerung von zwei bis drei Sekunden nachzieht. Das Log dazu sieht so aus:

2014.12.14 00:49:49.097 5: HMLAN/RAW: /E24F262,0000,0002A8F0,FF,FFB3,DAA44024F2621C062D01E7

2014.12.14 00:49:49.097 5: HMLAN_Parse: HMLAN0 R:E24F262   stat:0000 t:0002A8F0 d:FF r:FFB3     m:DA A440 24F262 1C062D 01E7
2014.12.14 00:49:49.098 5: HMLAN0 dispatch A0BDAA44024F2621C062D01E7::-77:HMLAN0
2014.12.14 00:49:49.187 5: HMLAN_Send:  HMLAN0 S:S460EE6F6 stat:  00 t:00000000 d:01 r:460EE6F6 m:DA 8002 1C062D 24F262 0107C800

<Kommentar von mir: hier ist nun scheinbar der Trigger vom Wandtaster eingegangen. Nun werden die drei Lampen geschaltet>

2014.12.14 00:49:49.197 3: SMARTLIGHTS: Toggling lights wz_lightCinema,wz_lightRed to value: 100
2014.12.14 00:49:49.198 3: SMARTLIGHTS: Executing: set wz_lightDesk:FILTER=pct!=100 100 0 1
2014.12.14 00:49:49.200 3: CUL_HM set wz_lightDesk 100 0 1
2014.12.14 00:49:49.201 5: HMLAN_Send:  HMLAN0 S:S460EE75B stat:  00 t:00000000 d:01 r:460EE75B m:B6 A011 F15544 22BA55 0201C80140FFFF
2014.12.14 00:49:49.203 3: SMARTLIGHTS: Executing: set wz_lightCrystal:FILTER=pct!=100 100 0 1
2014.12.14 00:49:49.212 3: CUL_HM set wz_lightCrystal 100 0 1
2014.12.14 00:49:49.213 5: HMLAN_Send:  HMLAN0 S:S460EE767 stat:  00 t:00000000 d:01 r:460EE767 m:B7 A011 F15544 22BAE7 0201C80140FFFF
2014.12.14 00:49:49.214 3: SMARTLIGHTS: Executing: set wz_lightRed:FILTER=pct!=100 100 0 1
2014.12.14 00:49:49.216 3: CUL_HM set wz_lightRed 100 0 1
2014.12.14 00:49:49.217 5: HMLAN_Send:  HMLAN0 S:S460EE76B stat:  00 t:00000000 d:01 r:460EE76B m:B8 A011 F15544 2072A5 0201C80140FFFF

<Ich denke, hier wurden nun alle drei Schaltkommandos gesendet. Das Schalten der letzten Lampe (wz_lightRed) passiert aber erst ca. 2 Sekunden nach den ersten beiden>

2014.12.14 00:49:49.221 5: HMLAN/RAW: /R460EE6F6,0002,00000000,FF,7FFF,DA80021C062D24F2620107C800

2014.12.14 00:49:49.222 5: HMLAN_Parse: HMLAN0 R:R460EE6F6 stat:0002 t:00000000 d:FF r:7FFF     m:DA 8002 1C062D 24F262 0107C800
2014.12.14 00:49:49.379 5: HMLAN/RAW: /R460EE75B,0001,0002AA0F,FF,FFB8,B6800222BA55F155440101011049

2014.12.14 00:49:49.380 5: HMLAN_Parse: HMLAN0 R:R460EE75B stat:0001 t:0002AA0F d:FF r:FFB8     m:B6 8002 22BA55 F15544 0101011049
2014.12.14 00:49:49.381 5: HMLAN0 dispatch A0EB6800222BA55F155440101011049::-72:HMLAN0
2014.12.14 00:49:49.850 5: HMLAN/RAW: /R460EE767,0008,00000000,FF,7FFF,B7A011F1554422BAE70201C80140FFFF

2014.12.14 00:49:49.851 5: HMLAN_Parse: HMLAN0 R:R460EE767 stat:0008 t:00000000 d:FF r:7FFF     m:B7 A011 F15544 22BAE7 0201C80140FFFF
2014.12.14 00:49:49.851 5: HMLAN_Parse: HMLAN0 no ACK from 22BAE7
2014.12.14 00:49:49.985 5: HMLAN/RAW: /R460EE76B,0008,00000000,FF,7FFF,B8A011F155442072A50201C80140FFFF

2014.12.14 00:49:49.986 5: HMLAN_Parse: HMLAN0 R:R460EE76B stat:0008 t:00000000 d:FF r:7FFF     m:B8 A011 F15544 2072A5 0201C80140FFFF
2014.12.14 00:49:49.987 5: HMLAN_Parse: HMLAN0 no ACK from 2072A5
2014.12.14 00:49:50.768 5: HMLAN_Send:  HMLAN0 S:S460EED7A stat:  00 t:00000000 d:01 r:460EED7A m:B8 A011 F15544 2072A5 0201C80140FFFF
2014.12.14 00:49:50.931 5: HMLAN/RAW: /R460EED7A,0001,0002B020,FF,FFB9,B880022072A5F155440101011042

2014.12.14 00:49:50.933 5: HMLAN_Parse: HMLAN0 R:R460EED7A stat:0001 t:0002B020 d:FF r:FFB9     m:B8 8002 2072A5 F15544 0101011042
2014.12.14 00:49:50.933 5: HMLAN0 dispatch A0EB880022072A5F155440101011042::-71:HMLAN0
2014.12.14 00:49:52.572 5: HMLAN/RAW: /E22BA55,0000,0002B684,FF,FFB8,B7A41022BA55F155440601C800

2014.12.14 00:49:52.573 5: HMLAN_Parse: HMLAN0 R:E22BA55   stat:0000 t:0002B684 d:FF r:FFB8     m:B7 A410 22BA55 F15544 0601C800
2014.12.14 00:49:52.573 5: HMLAN0 dispatch A0DB7A41022BA55F155440601C800::-72:HMLAN0
2014.12.14 00:49:52.574 5: HMLAN: Skip ACK
2014.12.14 00:49:53.212 5: HMLAN/RAW: /E22BAE7,0000,0002B904,FF,FFC5,B8A41022BAE7F155440601C800

2014.12.14 00:49:53.212 5: HMLAN_Parse: HMLAN0 R:E22BAE7   stat:0000 t:0002B904 d:FF r:FFC5     m:B8 A410 22BAE7 F15544 0601C800
2014.12.14 00:49:53.213 5: HMLAN0 dispatch A0DB8A41022BAE7F155440601C800::-59:HMLAN0
2014.12.14 00:49:53.214 5: HMLAN: Skip ACK
2014.12.14 00:49:53.366 5: HMLAN_Send:  HMLAN0 S:S460EF79F stat:  00 t:00000000 d:01 r:460EF79F m:B7 A011 F15544 22BAE7 0201C80140FFFF
2014.12.14 00:49:53.730 5: HMLAN/RAW: /R460EF79F,0001,0002BB0F,FF,FFC5,B7800222BAE7F155440101C8003B

2014.12.14 00:49:53.730 5: HMLAN_Parse: HMLAN0 R:R460EF79F stat:0001 t:0002BB0F d:FF r:FFC5     m:B7 8002 22BAE7 F15544 0101C8003B
2014.12.14 00:49:53.731 5: HMLAN0 dispatch A0EB7800222BAE7F155440101C8003B::-59:HMLAN0

Man sieht, dass das Versenden (HMLAN_Send) nicht verzögert wird. Die drei HMLAN_Sends passieren innerhalb von ca. 20 ms. Trotzdem schaltet die dritte Lampe verzögert verzögert :(

Problem 2:
Das andere Problem ist, dass es auch manchmal vorkommt, dass sich das HMLAN-Modul beim Schalten der drei Lampen komplett weghängt. D.h. es schaltet zB nur die erste Lampe und dann passiert nichts mehr. Nach kurzer Zeit kommt dann die Disconnect-Meldung. Das sieht im Log dann so aus:

2014.12.14 00:55:11.688 5: HMLAN/RAW: /E24F262,0000,00079542,FF,FFB3,DDA44024F2621C062D01EA

2014.12.14 00:55:11.689 5: HMLAN_Parse: HMLAN0 R:E24F262   stat:0000 t:00079542 d:FF r:FFB3     m:DD A440 24F262 1C062D 01EA
2014.12.14 00:55:11.690 5: HMLAN0 dispatch A0BDDA44024F2621C062D01EA::-77:HMLAN0
2014.12.14 00:55:11.780 5: HMLAN_Send:  HMLAN0 S:S4613D316 stat:  00 t:00000000 d:01 r:4613D316 m:DD 8002 1C062D 24F262 01070000
2014.12.14 00:55:11.789 3: SMARTLIGHTS: Toggling lights wz_lightCinema,wz_lightRed to value: 0
2014.12.14 00:55:11.790 3: SMARTLIGHTS: Executing: set wz_lightDesk:FILTER=pct!=0 0 0 1
2014.12.14 00:55:11.793 3: CUL_HM set wz_lightDesk 0 0 1
2014.12.14 00:55:11.794 5: HMLAN_Send:  HMLAN0 S:S4613D37B stat:  00 t:00000000 d:01 r:4613D37B m:BF A011 F15544 22BA55 0201000140FFFF
2014.12.14 00:55:11.795 3: SMARTLIGHTS: Executing: set wz_lightCrystal:FILTER=pct!=0 0 0 1
2014.12.14 00:55:11.803 3: CUL_HM set wz_lightCrystal 0 0 1
2014.12.14 00:55:11.804 5: HMLAN_Send:  HMLAN0 S:S4613D386 stat:  00 t:00000000 d:01 r:4613D386 m:C0 A011 F15544 22BAE7 0201000140FFFF
2014.12.14 00:55:11.805 3: SMARTLIGHTS: Executing: set wz_lightRed:FILTER=pct!=0 0 0 1
2014.12.14 00:55:11.807 3: CUL_HM set wz_lightRed 0 0 1
2014.12.14 00:55:11.808 5: HMLAN_Send:  HMLAN0 S:S4613D38A stat:  00 t:00000000 d:01 r:4613D38A m:C1 A011 F15544 2072A5 0201000140FFFF
2014.12.14 00:55:13.102 5: HMLAN_Delay: HMLAN0 22BA55
2014.12.14 00:55:13.576 5: HMLAN_Delay: HMLAN0 2072A5
2014.12.14 00:55:14.155 4: HMLAN_ack: timeout - clear queue
2014.12.14 00:55:15.992 5: HMLAN_Send:  HMLAN0 S:S4613E3E1 stat:  00 t:00000000 d:01 r:4613E3E1 m:C0 A011 F15544 22BAE7 0201000140FFFF
2014.12.14 00:55:17.845 5: HMLAN_Send:  HMLAN0 S:S4613EB1F stat:  00 t:00000000 d:01 r:4613EB1F m:BF A011 F15544 22BA55 0201000140FFFF
2014.12.14 00:55:18.016 5: HMLAN_Send:  HMLAN0 S:S4613EBCA stat:  00 t:00000000 d:01 r:4613EBCA m:C1 A011 F15544 2072A5 0201000140FFFF
2014.12.14 00:55:21.809 4: HMLAN_ack: timeout - clear queue
2014.12.14 00:55:21.919 5: HMLAN_Send:  HMLAN0 S:S4613FB08 stat:  00 t:00000000 d:01 r:4613FB08 m:C0 A011 F15544 22BAE7 0201000140FFFF
2014.12.14 00:55:23.024 5: HMLAN_Send:  HMLAN0 S:S4613FF5A stat:  00 t:00000000 d:01 r:4613FF5A m:C1 A011 F15544 2072A5 0201000140FFFF
2014.12.14 00:55:23.216 5: HMLAN_Send:  HMLAN0 S:S46140019 stat:  00 t:00000000 d:01 r:46140019 m:BF A011 F15544 22BA55 0201000140FFFF
2014.12.14 00:55:26.264 5: HMLAN_Send:  HMLAN0 I:K
2014.12.14 00:55:27.265 5: HMLAN_Send:  HMLAN0 I:K
2014.12.14 00:55:27.448 5: HMLAN_Send:  HMLAN0 S:S461410A2 stat:  00 t:00000000 d:01 r:461410A2 m:C0 A011 F15544 22BAE7 0201000140FFFF
2014.12.14 00:55:28.017 4: HMLAN_ack: timeout - clear queue
2014.12.14 00:55:28.267 5: HMLAN_Send:  HMLAN0 I:K
2014.12.14 00:55:29.269 5: HMLAN_Send:  HMLAN0 I:K
2014.12.14 00:55:30.270 1: HMLAN_Parse: HMLAN0 new condition timeout
2014.12.14 00:55:30.274 1: 192.168.2.31:1000 disconnected, waiting to reappear (HMLAN0)
2014.12.14 00:55:30.276 1: HMLAN_Parse: HMLAN0 new condition disconnected
2014.12.14 00:55:30.278 2: ENIGMA2 set dm7020hd msg attention
2014.12.14 00:55:30.295 3: onXbmcChange: wz_xbmc - msg "HMLAN0 changed status" "Event: HMLAN0:DISCONNECTED" 5
2014.12.14 00:55:30.303 3: nty_hm return value: -1
2014.12.14 00:55:33.311 1: Perfmon: possible freeze starting at 00:55:31, delay is 2.311
2014.12.14 00:55:33.312 4: HMLAN_ack: timeout - clear queue


Laut apptime hat Funktion "HMLAN_Ready" geklemmt:

                              name             function    max  count    total  average maxDly
                              HMLAN0          HMLAN_Ready   3007   2074    18471     8.91      0 HASH(HMLAN0)
                 tmr-Calendar_Wakeup      HASH(0xa81bf28)    713      2      718   359.00      7 HASH(calGoogle)
<usw.>

martinp876

ZitatSind das "known issues" oder müsste das eigentlich robust funktionieren?
die Probleme sind bekannt. wenn du eine Reihe von Kommandos direkt hintereinander absendest klappt es. Wenn es aber zu leichtem Versatz kommt und die ersten Devices schon wieder antworten kommt es zu Problemen. Generell werden die Probleme durch wiederholen abgefangen.
Zitatda zum Beispiel drei Lampen wirklich subjektiv zeitgleich angehen und nicht kurz versetzt
ich empfehle, einen virtuellen Button zu nutzen - das geht wirklich und problemlos gleichzeitig.  (noch gleichzeitiger also HMQLen schaffen kann)

ZitatDie Probleme treten nur auf, wenn ich wirklich mit dem Wandtaster teste.
klar - siehe oben. Hier wird noch etwas mit dem WM ausgetauscht und bereits mit dem Lampen kommuniziert. Daher die Probleme.


Cruiser79

#2
Zitat von: martinp876 am 14 Dezember 2014, 14:23:44
die Probleme sind bekannt. wenn du eine Reihe von Kommandos direkt hintereinander absendest klappt es. Wenn es aber zu leichtem Versatz kommt und die ersten Devices schon wieder antworten kommt es zu Problemen. Generell werden die Probleme durch wiederholen abgefangen. ich empfehle, einen virtuellen Button zu nutzen - das geht wirklich und problemlos gleichzeitig.  (noch gleichzeitiger also HMQLen schaffen kann)
klar - siehe oben. Hier wird noch etwas mit dem WM ausgetauscht und bereits mit dem Lampen kommuniziert. Daher die Probleme.

Da setze ich mich doch gleich mal mit ran, an das Thema, da ich ein ähnliches Problem habe und die hier vorgeschlagene Lösung nicht verstehe.
Ich habe ein Notify Heizung_Aus, das ich per Trigger steuere.
define Heizung_Aus notify Heizung_Aus set kind_Wandthermostat_Climate desired-temp 17.0;;set wz_Wandthermostat_Climate desired-temp 17.0;;set bz_Wandthermostat_Climate desired-temp 17.0
Auch bei mir kommt es ab und an vor, das nur ein Teil der 3 Wandthermostate schaltet, die anderen nicht.
Was kann ich hier am besten tun, damit auch wirklich immer alle 3 Thermostate schalten?
Was ist dieser virtuellen Button, mit dem es funktionieren soll?

Noch ein Nachtrag: Würde ein sleep in meinem Notify die gewünschte Änderung ergeben? Und vor allem, kein Blocken von FHEM verursachen?
Zitatdefine Heizung_Aus notify Heizung_Aus set kind_Wandthermostat_Climate desired-temp 17.0;;sleep 1;;set wz_Wandthermostat_Climate desired-temp 17.0;;sleep 1;set bz_Wandthermostat_Climate desired-temp 17.0
FHEM auf Raspberry Pi
HM-CFG-LAN mit HM-TC-IT-WM-W-EU, HM-CC-RT-DN, HM-WDS10-TH-O, HM-LC-SW1-FM, HM-LC-Bl1-FM
Signalduino mit Elro AB440, LOGILINK WS0002, IT CMR-1000

frank

ZitatWas ist dieser virtuellen Button, mit dem es funktionieren soll?
zb ein button (d)einer vccu.  ;)
FHEM: 6.0(SVN) => Pi3(buster)
IO: CUL433|CUL868|HMLAN|HMUSB2|HMUART
CUL_HM: CC-TC|CC-VD|SEC-SD|SEC-SC|SEC-RHS|Sw1PBU-FM|Sw1-FM|Dim1TPBU-FM|Dim1T-FM|ES-PMSw1-Pl
IT: ITZ500|ITT1500|ITR1500|GRR3500
WebUI [HMdeviceTools.js (hm.js)]: https://forum.fhem.de/index.php/topic,106959.0.html