Hallo,
in meiner Installation sind 15 HM-LC-Bl1PBU-FM für Rollos, einige HM-LC-Dim1L-Pl-2, HM-LC-Dim1T-Pl-2 und HM-LC-Dim1TPBU-FM. Gruppen davon sind in verschiedenen structures (zB "RolloSchalterAll" für alle Rollos) und LightScenes zusammengefasst:
define RolloSchalterAll structure room RolloSchalter01 RolloSchalter02 RolloSchalter03 RolloSchalter04 RolloSchalter05 RolloSchalter06 RolloSchalter07 RolloSchalter08 RolloSchalter09 RolloSchalter10 RolloSchalter11 RolloSchalter12 RolloSchalter13 RolloSchalter14 RolloSchalter15
define RolloSchalterOst structure room RolloSchalter01 RolloSchalter02 RolloSchalter03 RolloSchalter04
define RolloSchalterSud structure room RolloSchalter05 RolloSchalter06 RolloSchalter07 RolloSchalter08
define RolloSchalterLog structure room RolloSchalter09 RolloSchalter10 RolloSchalter11
define RolloSchalterWest structure room RolloSchalter12 RolloSchalter13 RolloSchalter14 RolloSchalter15
define wohnlicht LightScene ThekenlichtKueche StandleuchtenWohnzimmer TischlampeWohnzimmer DekoleuchteEsszimmer RolloSchalter03 RolloSchalter04 RolloSchalter05 RolloSchalter06 RolloSchalter07 RolloSchalter08 RolloSchalter09 RolloSchalter10
Um mehrere Rollos zu steuern, habe ich also verschiedene Möglichkeiten:
set RolloSchalter.. up 50
set RolloSchalterAll up 50
set wohnlicht scene all_off
Früher konnte man nach Absetzen dieser Befehle höhren, wie die Rollos der Reihe nach anfingen zu schalten, im Abstand von etwa 200ms.
Seit einiger Zeit aber zeigt sich ein davon abweichendes Verhalten:
Je nachdem, auf welchem Wert hmLanQlen steht, schalten zunächst entsprechend viele der ersten Aktoren in der structure/LightScene mit dem gewohnten zeitlichen Verhalten. Dann folgt eine Pause von 1-3 Sekunden, danach schalten die restlichen Aktoren mit ebenfalls konstanter, aber merklich längerer Pause. Gerade wenn Beleuchtungsaktoren beteiligt sind, kann das sehr schnell unbefriedigend werden, egal in welcher Reihenfolge.
Nach umfangreicher Suche mit Google und der Forums-eigenen Suchfunktion, habe ich bei den üblichen Verdächtigen angesetzt: FileLog Instanzen auf das notwendigste reduziert, notifies gekeult, alle FHEMWEB clients getrennt, am Ende habe ich sogar ein fhem.cfg aufgesetzt, das nur noch die HM-Komponenten und structures/LightScenes beinhaltet. Selbst das hat zwar quantitativ die Pausen leicht verkürzt (klar, weniger Event-Behandlung), aber qualitativ war auch hier die deutlich längere Pause nach den ersten hmLanQlen Aktoren vorhanden (diesmal gut eine Sekunde, was aber nicht wirklich hilft, weil in dieser Konfiguration wesentliche Bestandteile meiner Installation fehlen).
Mit der vollständigen Konfig zeigt mir Apptime Folgendes:
apptime clear
set RolloSchalter01 down 20
apptime
name function max count total average maxDly
RolloSchalter01 CUL_HM_Set 677 53 729 13.75 0 HASH(RolloSchalter01); RolloSchalter01; down; 20
tmr-SYSMON_Update HASH(0x2f34450) 640 1 640 640.00 1 HASH(sysmon_hal)
HMLAN1 HMLAN_Read 400 3 860 286.67 0 HASH(HMLAN1)
fhem_themaxx FHEM2FHEM_Read 216 62 3901 62.92 0 HASH(fhem_themaxx)
fhem_laantena FHEM2FHEM_Read 195 25 2008 80.32 0 HASH(fhem_laantena)
RolloSchalterAll structure_Notify 165 333 650 1.95 0 HASH(RolloSchalterAll); HASH(RolloSchalter01)
voice_cmd_hist readingsHistory_Notify 96 333 325 0.98 0 HASH(voice_cmd_hist); HASH(sysmon_hal)
RolloSchalterOst structure_Notify 72 333 282 0.85 0 HASH(RolloSchalterOst); HASH(RolloSchalter01)
fhem_tardis FHEM2FHEM_Read 71 18 481 26.72 0 HASH(fhem_tardis)
RolloSchalterGast structure_Notify 60 333 237 0.71 0 HASH(RolloSchalterGast); HASH(RolloSchalter01)
tmr-sunpos_GetUpdate HASH(0x2fecb18) 41 1 41 41.00 46 HASH(Sonnenposition)
tmr-at_Exec HASH(0x30191e0) 36 15 523 34.87 542 HASH(at_datetime)
FHEMWEB:192.168.1.20:56249 FW_Notify 32 333 122 0.37 0 HASH(FHEMWEB:192.168.1.20:56249); HASH(RolloSchalterAll)
FHEMWEB:192.168.1.21:54076 FW_Notify 31 333 197 0.59 0 HASH(FHEMWEB:192.168.1.21:54076); HASH(RolloSchalterAll)
FHEMWEB:192.168.1.20:56277 FW_Notify 30 333 234 0.70 0 HASH(FHEMWEB:192.168.1.20:56277); HASH(RolloSchalterAll)
FHEMWEB:192.168.1.38:39455 FW_Notify 30 333 228 0.68 0 HASH(FHEMWEB:192.168.1.38:39455); HASH(RolloSchalterAll)
RolloSchalterAll structure_Set 29 16 438 27.38 0 HASH(RolloSchalterAll); RolloSchalterAll; ?
PowerMeterMM cloneDummy_Notify 28 34 113 3.32 0 HASH(PowerMeterMM); HASH(EC3kMM)
PowerMeter01 cloneDummy_Notify 27 29 81 2.79 0 HASH(PowerMeter01); HASH(EC3k01)
PowerMeterKS cloneDummy_Notify 27 33 88 2.67 0 HASH(PowerMeterKS); HASH(EC3kKS)
PowerMeterMW cloneDummy_Notify 27 33 89 2.70 0 HASH(PowerMeterMW); HASH(EC3kMW)
apptime maxDly
name function max count total average maxDly
tmr-at_Exec HASH(0x30191e0) 53 91 3225 35.44 542 HASH(at_datetime)
tmr-perfmon_ProcessTimer HASH(0x19cb8c0) 0 91 0 0.00 377
tmr-HMLAN_KeepAliveCheck keepAliveCk:HMLAN1 0 3 0 0.00 143
tmr-HMLAN_KeepAliveCheck keepAliveCk:HMLAN2 0 3 0 0.00 143
tmr-at_Exec HASH(0x30cace8) 99 1 99 99.00 142 HASH(rollo_gast_golight_upd)
tmr-at_Exec HASH(0x28ec248) 63 1 63 63.00 134 HASH(rollo_gast_godark2_upd)
tmr-FW_closeOldClients 2 2 4 2.00 116
tmr-at_Exec HASH(0x30b7738) 68 1 68 68.00 76 HASH(rollo_gast_godark_upd)
tmr-sunpos_GetUpdate HASH(0x2fecb18) 41 1 41 41.00 46 HASH(Sonnenposition)
tmr-HMLAN_UpdtMsgCnt UpdtMsg:HMLAN1 0 2 0 0.00 4
tmr-HMLAN_UpdtMsgCnt UpdtMsg:HMLAN2 0 2 0 0.00 4
tmr-at_Exec HASH(0x28c9870) 66 1 66 66.00 4 HASH(rollo_auf_upd)
tmr-ROOMMATE_DurationTimer HASH(0x2441540) 1 1 1 1.00 2 HASH(rr_A_DurationTimer)
tmr-ROOMMATE_DurationTimer HASH(0x2779458) 1 1 1 1.00 2 HASH(rr_M_DurationTimer)
tmr-ROOMMATE_DurationTimer HASH(0x2a47a70) 1 1 1 1.00 2 HASH(rr_M_DurationTimer)
tmr-ROOMMATE_DurationTimer HASH(0x32d4c98) 1 1 1 1.00 2 HASH(rr_A_DurationTimer)
tmr-CUL_HM_ActCheck ActionDetector 12 1 12 12.00 1 ActionDetector
tmr-HMLAN_KeepAlive keepAlive:HMLAN1 0 3 0 0.00 1
tmr-HMLAN_KeepAlive keepAlive:HMLAN2 0 3 0 0.00 1
tmr-SYSMON_Update HASH(0x2f34450) 640 2 1273 636.50 1 HASH(sysmon_hal)
tmr-Twilight_sunpos HASH(0x333ee68) 55 1 55 55.00 1 HASH(twilight_sunpos)
apptime clear
set RolloSchalter.. down 20
apptime
name function max count total average maxDly
telnet:127.0.0.1:42604 telnet_Read 12741 2 12741 6370.50 0 HASH(telnet:127.0.0.1:42604)
HMLAN1 HMLAN_Read 3061 26 20761 798.50 0 HASH(HMLAN1)
RolloSchalter06 CUL_HM_Set 1052 424 1475 3.48 0 HASH(RolloSchalter06); RolloSchalter06; down; 20
RolloSchalter07 CUL_HM_Set 1050 420 1469 3.50 0 HASH(RolloSchalter07); RolloSchalter07; down; 20
RolloSchalter08 CUL_HM_Set 1050 420 1469 3.50 0 HASH(RolloSchalter08); RolloSchalter08; down; 20
RolloSchalter09 CUL_HM_Set 1040 404 1444 3.57 0 HASH(RolloSchalter09); RolloSchalter09; down; 20
RolloSchalter10 CUL_HM_Set 1037 404 1440 3.56 0 HASH(RolloSchalter10); RolloSchalter10; down; 20
FHEMWEB:192.168.1.38:39459 FW_Read 1009 1 1009 1009.00 0 HASH(FHEMWEB:192.168.1.38:39459)
RolloSchalter04 CUL_HM_Set 883 345 1227 3.56 0 HASH(RolloSchalter04); RolloSchalter04; down; 20
RolloSchalter03 CUL_HM_Set 882 349 1230 3.52 0 HASH(RolloSchalter03); RolloSchalter03; down; 20
RolloSchalter05 CUL_HM_Set 882 354 1235 3.49 0 HASH(RolloSchalter05); RolloSchalter05; down; 20
FHEMWEB:192.168.1.20:56402 FW_Read 868 1 868 868.00 0 HASH(FHEMWEB:192.168.1.20:56402)
tmr-SYSMON_Update HASH(0x2f34450) 724 1 724 724.00 1991 HASH(sysmon_hal)
RolloSchalter14 CUL_HM_Set 703 312 1014 3.25 0 HASH(RolloSchalter14); RolloSchalter14; down; 20
RolloSchalter15 CUL_HM_Set 703 312 1014 3.25 0 HASH(RolloSchalter15); RolloSchalter15; down; 20
RolloSchalter13 CUL_HM_Set 702 312 1014 3.25 0 HASH(RolloSchalter13); RolloSchalter13; down; 20
RolloSchalter12 CUL_HM_Set 700 312 1011 3.24 0 HASH(RolloSchalter12); RolloSchalter12; down; 20
RolloSchalter11 CUL_HM_Set 689 298 986 3.31 0 HASH(RolloSchalter11); RolloSchalter11; down; 20
RolloSchalter02 CUL_HM_Set 672 280 951 3.40 0 HASH(RolloSchalter02); RolloSchalter02; down; 20
RolloSchalter01 CUL_HM_Set 671 276 947 3.43 0 HASH(RolloSchalter01); RolloSchalter01; down; 20
fhem_laantena FHEM2FHEM_Read 246 122 12133 99.45 0 HASH(fhem_laantena)
apptime maxDly
name function max count total average maxDly
tmr-at_Exec HASH(0x30191e0) 45 129 4796 37.18 26484 HASH(at_datetime)
tmr-perfmon_ProcessTimer HASH(0x19cb8c0) 0 101 0 0.00 12800
tmr-CUL_HM_respPendTout respPend:1AB510 2 1 2 2.00 8400 respPend:1AB510
tmr-CUL_HM_respPendTout respPend:1AF52B 2 1 2 2.00 7610 respPend:1AF52B
tmr-CUL_HM_sndIfOpen sndIfOpen:HMLAN1 3 12 30 2.50 7590 sndIfOpen:HMLAN1
tmr-CUL_HM_respPendTout respPend:2908FD 1 1 1 1.00 7251 respPend:2908FD
tmr-CUL_HM_respPendTout respPend:1AB518 1 1 1 1.00 6616 respPend:1AB518
tmr-CUL_HM_respPendTout respPend:1B711B 1 1 1 1.00 3935 respPend:1B711B
tmr-Twilight_sunpos HASH(0x3348b58) 54 1 54 54.00 2813 HASH(twilight_sunpos)
tmr-HMLAN_UpdtMsgCnt UpdtMsg:HMLAN1 0 2 0 0.00 2792
tmr-HMLAN_UpdtMsgCnt UpdtMsg:HMLAN2 0 2 0 0.00 2792
tmr-FW_closeOldClients 4 2 6 3.00 2478
tmr-HMLAN_clearQ hmClearQ:HMLAN1 0 6 0 0.00 2077
tmr-SYSMON_Update HASH(0x2f34450) 735 2 1459 729.50 1991 HASH(sysmon_hal)
tmr-HMLAN_KeepAliveCheck keepAliveCk:HMLAN2 0 6 0 0.00 1953
tmr-HMLAN_KeepAliveCheck keepAliveCk:HMLAN1 0 6 0 0.00 1952
tmr-at_Exec HASH(0x30cace8) 104 2 208 104.00 1597 HASH(rollo_gast_golight_upd)
tmr-at_Exec HASH(0x30b7738) 71 2 141 70.50 1528 HASH(rollo_gast_godark_upd)
tmr-at_Exec HASH(0x28ec248) 72 2 138 69.00 1380 HASH(rollo_gast_godark2_upd)
tmr-CUL_HM_ActCheck ActionDetector 11 1 11 11.00 1256 ActionDetector
tmr-CUL_HM_respPendTout respPend:2908FB 2 1 2 2.00 1191 respPend:2908FB
apptime clear
set RolloSchalterAll down 20
apptime
name function max count total average maxDly
telnet:127.0.0.1:42604 telnet_Read 7847 2 7847 3923.50 0 HASH(telnet:127.0.0.1:42604)
RolloSchalterAll structure_Set 7700 103 10453 101.49 0 HASH(RolloSchalterAll); RolloSchalterAll; down; 20
HMLAN1 HMLAN_Read 2302 15 17053 1136.87 0 HASH(HMLAN1)
FHEMWEB:192.168.1.38:39457 FW_Read 908 1 908 908.00 0 HASH(FHEMWEB:192.168.1.38:39457)
FHEMWEB:192.168.1.20:56345 FW_Read 897 1 897 897.00 0 HASH(FHEMWEB:192.168.1.20:56345)
tmr-SYSMON_Update HASH(0x2f34450) 730 2 1363 681.50 186 HASH(sysmon_hal)
RolloSchalter06 CUL_HM_Set 699 316 1014 3.21 0 HASH(RolloSchalter06); RolloSchalter06; down; 20
RolloSchalter08 CUL_HM_Set 699 316 1014 3.21 0 HASH(RolloSchalter08); RolloSchalter08; down; 20
RolloSchalter07 CUL_HM_Set 698 316 1013 3.21 0 HASH(RolloSchalter07); RolloSchalter07; down; 20
RolloSchalter10 CUL_HM_Set 687 308 994 3.23 0 HASH(RolloSchalter10); RolloSchalter10; down; 20
RolloSchalter09 CUL_HM_Set 685 308 992 3.22 0 HASH(RolloSchalter09); RolloSchalter09; down; 20
RolloSchalter03 CUL_HM_Set 546 249 794 3.19 0 HASH(RolloSchalter03); RolloSchalter03; down; 20
RolloSchalter04 CUL_HM_Set 546 249 794 3.19 0 HASH(RolloSchalter04); RolloSchalter04; down; 20
RolloSchalter05 CUL_HM_Set 546 250 795 3.18 0 HASH(RolloSchalter05); RolloSchalter05; down; 20
RolloSchalter13 CUL_HM_Set 378 235 612 2.60 0 HASH(RolloSchalter13); RolloSchalter13; down; 20
RolloSchalter15 CUL_HM_Set 378 235 612 2.60 0 HASH(RolloSchalter15); RolloSchalter15; down; 20
RolloSchalter14 CUL_HM_Set 377 235 611 2.60 0 HASH(RolloSchalter14); RolloSchalter14; down; 20
RolloSchalter12 CUL_HM_Set 376 238 613 2.58 0 HASH(RolloSchalter12); RolloSchalter12; down; 20
RolloSchalter11 CUL_HM_Set 366 220 585 2.66 0 HASH(RolloSchalter11); RolloSchalter11; down; 20
RolloSchalter01 CUL_HM_Set 355 189 543 2.87 0 HASH(RolloSchalter01); RolloSchalter01; down; 20
RolloSchalter02 CUL_HM_Set 347 190 536 2.82 0 HASH(RolloSchalter02); RolloSchalter02; down; 20
apptime maxDly
name function max count total average maxDly
tmr-at_Exec HASH(0x30191e0) 61 108 4036 37.37 19309 HASH(at_datetime)
tmr-perfmon_ProcessTimer HASH(0x19cb8c0) 0 89 0 0.00 7329
tmr-CUL_HM_respPendTout respPend:1AB518 2 1 2 2.00 4753 respPend:1AB518
tmr-CUL_HM_sndIfOpen sndIfOpen:HMLAN1 3 13 30 2.31 4639 sndIfOpen:HMLAN1
tmr-CUL_HM_respPendTout respPend:1AF52B 1 1 1 1.00 4601 respPend:1AF52B
tmr-HMLAN_KeepAlive keepAlive:HMLAN1 1 4 1 0.25 4488 keepAlive:HMLAN1
tmr-HMLAN_KeepAlive keepAlive:HMLAN2 1 4 1 0.25 4488 keepAlive:HMLAN2
tmr-CUL_HM_respPendTout respPend:2908FD 1 1 1 1.00 3970 respPend:2908FD
tmr-CUL_HM_respPendTout respPend:1AB510 1 1 1 1.00 3669 respPend:1AB510
tmr-CUL_HM_respPendTout respPend:1B711B 1 1 1 1.00 2835 respPend:1B711B
tmr-HMLAN_clearQ hmClearQ:HMLAN1 0 6 0 0.00 2661
tmr-HMLAN_KeepAliveCheck keepAliveCk:HMLAN1 0 5 0 0.00 1819
tmr-HMLAN_UpdtMsgCnt UpdtMsg:HMLAN1 0 2 0 0.00 1116
tmr-HMLAN_UpdtMsgCnt UpdtMsg:HMLAN2 0 2 0 0.00 1116
tmr-ROOMMATE_DurationTimer HASH(0x2648708) 1 1 1 1.00 1036 HASH(rr_A_DurationTimer)
tmr-ROOMMATE_DurationTimer HASH(0x32cc2a0) 0 1 0 0.00 1035
tmr-HMLAN_KeepAliveCheck keepAliveCk:HMLAN2 0 3 0 0.00 300
tmr-at_Exec HASH(0x28c9870) 62 1 62 62.00 299 HASH(rollo_auf_upd)
tmr-SYSMON_Update HASH(0x2f34450) 730 2 1363 681.50 186 HASH(sysmon_hal)
tmr-at_Exec HASH(0x30cace8) 104 1 104 104.00 96 HASH(rollo_gast_golight_upd)
tmr-at_Exec HASH(0x28ec248) 65 1 65 65.00 78 HASH(rollo_gast_godark2_upd)
Obige Meldungen kommen aus der aktuellen FHEM Version:
version
# $Id: fhem.pl 6913 2014-11-08 10:32:44Z rudolfkoenig $
# $Id: 10_CUL_HM.pm 6863 2014-11-02 09:04:57Z martinp876 $
# $Id: 93_FHEM2FHEM.pm 6203 2014-07-06 12:31:20Z rudolfkoenig $
# $Id: 01_FHEMWEB.pm 6884 2014-11-04 22:03:52Z rudolfkoenig $
# $Id: 95_FLOORPLAN.pm 6174 2014-06-29 05:51:28Z ulimaass $
# $Id: 92_FileLog.pm 6769 2014-10-15 17:03:30Z rudolfkoenig $
# $Id: 00_HMLAN.pm 6471 2014-08-27 12:32:38Z martinp876 $
# $Id: 98_HMinfo.pm 6794 2014-10-19 16:48:14Z martinp876 $
# $Id: 31_LightScene.pm 6704 2014-10-07 17:03:35Z justme1968 $
# $Id: 75_MSG.pm 2012-06-20 18:29:00 rbente
# $Id: 76_MSGFile.pm 2012-06-20 18:29:00 rbente
# $Id: 02_RSS.pm 6543 2014-09-12 15:13:15Z borisneubert $
# $Id: 99_SUNRISE_EL.pm 6765 2014-10-14 18:24:29Z rudolfkoenig $
# $Id: 98_SVG.pm 6756 2014-10-12 13:13:26Z rudolfkoenig $
# $Id: 42_SYSMON.pm 6970 2014-11-14 20:01:35Z hexenmeister $
# $Id: 59_Twilight.pm 6953 2014-11-11 23:04:30Z mrp666 $
# $Id: 99_Utils.pm 6660 2014-10-03 06:35:43Z rudolfkoenig $
# $Id: 99_XmlList.pm 1528 2012-05-03 06:35:53Z rudolfkoenig $
# $Id: 98_apptime.pm 6126 2014-06-17 05:44:54Z martinp876 $
# $Id: 90_at.pm 6797 2014-10-21 12:32:19Z rudolfkoenig $
# $Id: 98_autocreate.pm 6505 2014-09-06 12:24:48Z rudolfkoenig $
# $Id: 98_cloneDummy.pm 5919 2014-05-21 05:03:48Z joachim09876 $
# $Id: 98_cmdalias.pm 6195 2014-07-04 11:53:51Z rudolfkoenig $
# $Id: 98_dewpoint.pm 6757 2014-10-12 18:58:57Z joachim09876 $
# $Id: 98_dummy.pm 4934 2014-02-15 08:23:12Z rudolfkoenig $
# $Id: 95_holiday.pm 5956 2014-05-24 13:04:04Z rudolfkoenig $
# $Id: 98_mydewpoint.pm 5099 2014-03-02 16:29:34Z betateilchen $
# $Id: 91_notify.pm 6371 2014-08-07 05:33:37Z rudolfkoenig $
# $Id: 33_readingsGroup.pm 6262 2014-07-16 07:46:03Z justme1968 $
# $Id: 33_readingsHistory.pm 6788 2014-10-18 19:28:13Z justme1968 $
# $Id: 33_readingsProxy.pm 5750 2014-05-05 09:26:45Z justme1968 $
# $Id: 98_structure.pm 6936 2014-11-09 21:11:40Z rudolfkoenig $
# $Id: 98_telnet.pm 6611 2014-09-24 07:48:32Z rudolfkoenig $
# $Id: 91_watchdog.pm 5622 2014-04-24 08:04:29Z rudolfkoenig $
/opt/fhem/FHEM/95_webViewControl.pm: No such file or directory
# $Id: 98_weblink.pm 5608 2014-04-23 10:57:16Z rudolfkoenig $
Das System läuft auf einem CubieTruck mit SSD, auf dem kein weiterer Dienst läuft, der Resourcen beanspruchen könnte. Zwischen CT und HMLAN sind zwei Switches, die ich auch schon getauscht habe, ohne Änderung. Auch der Nameserver funktioniert stabil ohne nennenswerte Delays.
Bevor ich meine Installation noch mehr zerlege: Könnte das Verhalten an CUL_HM / HMLAN liegen? Oder das Wie kann ich das weiter optimieren/debuggen?
Danke schonmal für weitere Ideen,
Andy.
Wie du beschrieben hast spielt hmqlen zumindest eine rolle. 1 ist der empfohlene wert. Es wird ein kommando an einen aktor gesendet, der antwortet mit ack, dann der naechste.
Ist der wert groesser werden mehr kommandos gesendet, dann auf die acks gewartet. Geht schneller - kommt aber regelmaessig zu kollisionen und wiederholungen. Insbesondere wenn es ueber langsame aktionen wie struktur gestartet wird. Kannst du in den hminfo statistiken verfolgen.
Parallel und sparsam geht es ueber peerings.ist aber weit weniger flexibel.
Setze die qlen besser auf 1 und teste. Was dann noch probleme macht kann ich mir ansehen. Mit
statistiken und logs der msg
Hallo Martin,
danke für Deine Antwort und das Angebot, genauer draufzuschauen. Bis vor Kurzem hatte ich hmLanQlen in der Tat auf 1, das war mit sign=on bei den RolloSchaltern dringend nötig, mit 2 ging es halbwegs gut, mit 3 war es schon recht mühsam. Aber auch bei 1 war das zeitliche Verhalten mit Signierung irgendwann einfach gefühlt viel zu langsam, weswegen ich das Signieren erstmal aufgegeben habe. Dann kam vor einigen Wochen der lange Delay nach dem ersten Aktor ins Spiel, was ich vor einigen Tagen dann mit einem aggressiveren hmLanQlen=5 versuchte, zu entspannen. Aber ich sehe, dass das nur zu anderen Problemen führt, wie Du auch schreibst.
Ich habe jetzt nochmal folgendes gemacht: Sichergestellt, dass wirklich alle FHEMWEB clients abgemeldet sind, dann jeweils die Kommandos
- set RolloSchalter.. down 15 (->Logfiles "xrollo-1.*")
- set RolloSchalterAll up 15 (->Logfiles "xrollo-2.*")
abgesetzt. Danach 5 FHEMWEB-Clients aufgemacht (entspricht meiner typischen Nutzung), und die beiden Kommandos für xrollo-3.* und xrollo-4.* wiederholt, zum Vergleich.
Vor jedem Befehl habe ich per script
attr global verbose 1
attr global mseclog 1
attr HMLAN. logIDs all,sys
list TYPE=CUL_HM DEF
list HMLAN1
list HMLAN2
set hm clear msgStat
set hm clear Protocol
attr global logfile /var/log/fhem/xrollo-X.log
{Log 0,"TimeCmd start: xrollo-X"}
apptime clear
abgesetzt (der Output der list Befehle geht jeweils in eine Datei) und nach jedem Befehl
{Log 0,"TimeCmd stop: xrollo-X"}
apptime max all
apptime maxDly all
Das Logfile läuft danach jweils nach dem Befehl noch 45 Sekunden weiter, um die Rückmeldungen der Schalter mit zu erfassen, danach werden noch Dateien mit dem Output folgender Befehle erzeugt:
attr global logfile /opt/fhem/log/fhem-%Y-%m.log
set hm update
set hm msgStat
set hm protoEvents
set hm rssi
Das angefügte Archiv enthält für die 4 Tests jeweils die FHEM-Logdatei (.log) und die verschiedenen anderen Dateien.
Sollte ich noch was übersehen haben (oder zuviel/unbrauchbare Info dabei ist), kann ich das gern ins Script einbauen und das Ganze ggfls wiederholen.
Danke und beste Grüße,
Andy.
Hallo Andy,
habe gerade das xrollo-1 start angsehensind immerhin 15 Rollos - alle korrekt gefahren. alle auf "AA".
dauert über 20 sec. Das senden dauert über 10 sec - das ist wohl notwendig, bei den vielen Aktoren.
Gruß Martin
Hallo Martin,
kann ich bestätigen, Zuverlässigkeit ist auch nicht das Problem. Was ich seltsam finde ist, dass der erste Aktor gleich losfährt, dann 1-3 Sekunden Pause ist und dann die anderen Aktoren anfangen zu fahren, dann aber mit jeweils 1/3-1/2 Sekunde Pause zwischen zweien. Diese lange Pause nach dem Ersten war früher nie da.
Wenn der Schaltvorgang nicht vom at kommt, sondern auf Tastendruck oder über Floorplan-Icon, ist meistens der erste Aktor nicht einsehbar, drum ist man gerne mal verleitet, die Aktion mehrmals auszulösen, weil augenscheinlich jegliche Reaktion auf den ersten Versuch ausbleibt. Das macht die Situation natürlich nicht besser.
Siehst Du eine mögliche Ursache für dieses verlängerte Delay zwischem erstem und zweiten Aktor?
Grüße,
Andy.
liegt an der Verzögerung des ersten aktors Der Befehl wird wiederholt, erst dann antwortet der Aktor. Das 2. senden erfolgt nach 3 sec, das ist der delay.
das senden ist "alleinstehend" - hat also nichts mit der "masse" der Rollos zu tun.
Wenn der Rollo erst späer in der Liste auftauchen würden wäre der delay voraussichtlich irgendwann zwischen drin.
Kann ich so leider nicht bestätigen - wenn ich aus der Gruppe die ersten beiden RolloSchalter rausnehme, und das Schalten mit RolloSchalter03 beginnt, kommt die lange Pause zwischen RolloSchalter04 und RolloSchalter04. Wenn ich statt RolloSchalterAll eine LightScene schalte (Reihefolge: Schalter1, Dimmer1, RolloSchalter03..10, Dimmer2) kommt die Pause nach Schalter1. Die lange Pause ist also nicht an einen bestimmten HM-Aktor gebinden sondern kommt immer nach dem ersten Aktor einer Gruppe.
Da fällt mir ein - hast Du ausser xrollo-1 auch xrollo-2 angesehen? Ersteres schaltet ja nicht über die structure sondern wählt alle Aktoren über regexp aus ("set RolloSchalter.. down 15"). Das sieht in der Tat zeitlich anders aus als das Schalten über structure wie in xrollo-2 dokumentiert.
Hi Martin,
sorry, ich muss dich nochmal mit dem Thema belästigen, ich komm nicht recht weiter :-\
Folgendes habe ich auf Deine Vermutung hin versucht:
- Eine structure "RolloSchalterTest" erzeugt, die Alle RolloSchalter01..15 enthält
- Mit dieser einen Fahrbefehl ausgeführt "set RolloSchalterTest 75" und dabei Daten aufgezeichnet
- Das selbe wiederholt für 15 Permutationen aus den Rolloschaltern, also
- 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15
- 02 03 04 05 06 07 08 09 10 11 12 13 14 15 01
- 03 04 05 06 07 08 09 10 11 12 13 14 15 01 02
- ...
- 15 01 02 03 04 05 06 07 08 09 10 11 12 13 14
Dabei konnte ich folgendes Schema für alle 15 Permutationen verifizieren: Unabhängig davon, welcher der RolloSchalter als erster angesteuert wird, folgt dem ersten Logeintrag mit HMLAN_Send nach etwa 11 Sekunden ein Eintrag von Perfmon, gefolgt von weitern HMLAN_Send, HMLAN_Parse:
2014.11.17 10:07:01.646 0: TimeCmd start: xrollo-per10
2014.11.17 10:07:02.161 0: HMLAN_Send: HMLAN1 S:SBD0158DA stat: 00 t:00000000 d:01 r:BD0158DA m:B0 A011 139AF8 1AB510 020196
2014.11.17 10:07:13.597 1: Perfmon: possible freeze starting at 10:07:02, delay is 11.597
2014.11.17 10:07:13.599 0: HMLAN_Send: HMLAN1 S:SBD018588 stat: 00 t:00000000 d:01 r:BD018588 m:B0 A011 139AF8 1AB510 020196
2014.11.17 10:07:13.602 0: HMLAN_Parse: HMLAN2 R:E1F4B18 stat:0000 t:0901C2A2 d:FF r:FFDE m:45 8670 1F4B18 000000 00983A
2014.11.17 10:07:13.930 0: HMLAN_Parse: HMLAN1 R:RBD0158DA stat:0001 t:088E2273 d:FF r:FFC7 m:B0 8002 1AB510 139AF8 0101B42039
Im weiteren Verlauf treten weitere Perfmon-Einträge mit 1-2 Sek auf, insgesamt zwischen 9 und 12 je Versuch.
Allerdings muss ich mich korrigieren, wenn in einer LightScene zuerst ein Lichtschalter geschaltet wird, ist das Delay direkt danach nicht so lang (gefühlt, messen muss ich das noch).
Deshalb und im Versuch, was dazuzulernen habe ich mir in der Funktion CUL_HM_Set() die Unterschiede zwischen einem "set pct" und "set on" angesehen und bei ersterem ein zusätzliches
CUL_HM_UpdtReadSingle($hash,"level",$state,1); gesehen (Zeile 3700 in Version 6863).
Wenn ich das auskommentiere, reduziert sich das anfängliche Delay auf 6-7 Sekunden, die nachfolgenden Perfmon-Einträge bleiben bei 1-2 Sekunden. Sehe ich das richtig, dass diese eine Zeile lediglich ein Event postet mit "set_..." und das zusätliche Delay in den diversen notifies, FileLogs etc entsteht? Kann ich das mit apptime weiter eingrenzen (wenn ja wie)?
Das selbe passiert ja aber auch wenn die weiteren Schalter der structure angesteuert werden und trotzdem sind die delays dann deutlich kürzer.
Dazu kommt die bereits geschilderte Beobachtung, das das lange Delay dann kommt, wenn Zahl der zuerst angesteuerten Schalter der Einstellung von hmLanQlen entspricht.
Lass mich nochmal ein paar wesentliche Punkte zusammenfassen wie ich sie verstanden habe und korrigiere mich bitte wenn es anders ist:
- structure ruft der Reihe nach für jeden der enthaltenen Schalter set auf. Hier wird jeweils ein Befehl in die Warteschlange gestellt und alles gesendet, was laut hmLanQlen raus darf. Hier werden bereits verschiedene Events ausgelöst
- Bei 15 Schaltern in der strucutre dauert der Vorgang ca 11 Sekunden, in der Zeit ist FHEM blockiert (was Perfmon belegt). Danach ist der set-Befehl der structure abgearbeitet.
- Per Timer werden später die restlichen Kommandos in der Warteschlange abgearbeitet, auch Keelalive wird wieder gesendet
- Auch hierbei werden Events ausgelöst, was z.T. in Delays von 1-2 Sekunden resultiert
Früher war es auch so, dass der per telnet abgesetzte Befehl (gefühlt) sofort zurückkam, jetzt dauert das mit 11 Sekunden spürbar länger. Damals konnt man im Webfrontend sehen, wie mit dem höhrbaren "durchklackern" der Rolloschalter die Stati jweils gleichzeitig auf "set_xy" gingen. Jetzt hängt das einfach für 11 Sekunden, danach gehts zäh weiter. Leider kann ich den Zeitpunkt/die Version ab der sich das Verhalten geändert hat, nicht festmachen.
Vielleicht liegt es auch gar nicht an HMLAN/CUL_HM sondern am FHEM-core oder den structures/LightScenes aber das ist für mich noch weniger greifbar.
Vielleicht hast Du ja noch weitere Ideen, wie ich das weiter eingrenzen kann. Ich füge auch gern weitere Messungen an wenns hilft ;D
Danke fürs Lesen und Deine Geduld,
Grüße,
Andy.
Kurzes Update:
Augenscheinlich ist das geschilderte Verhalten im Zusammenspiel zwischen FHEMWEB und mehreren structures begründet, die jeweils überlappende Teilmengen der Rolloschalter beinhalten.
Zumindest habe ich eine Spur, die ich verfolgen kann und Ansätze zum Debugging. Wenn sich das bewahrheitet, soll der thread dann umziehen?
Grüße,
Andy.
Hallo Andy,
mal sehen, was ich beantworten kann:
structure ist "FHEM-atomar" aber nicht HM-atomar. Es werden also einzelne Kommandos an jeden der beteiligten Aktoren gesendet.
Wenn du die Aktoren mit einen Sender (hier wohl ein virtueller) peerst kannst du HM-atomar arbeiten. Ist aber ein komplett anderes vorgehen und weniger flexibel.
Das setzen des Readings in CUL_HM löst ein notify aus - je nach dem, wer angeschlossen ist, kann dies zu delays führen. Notifyes sind quasi immer gefährlich bezüglich echtzeit. Wenn auch noch web -services betroffen sind (fhemweb) ist fast schon von vorne herein jede Echtzeit dahin.
ZitatDazu kommt die bereits geschilderte Beobachtung, das das lange Delay dann kommt, wenn Zahl der zuerst angesteuerten Schalter der Einstellung von hmLanQlen entspricht.
wenn die gleich sind werden alle Kommandos hintereinander gesendet ohne auf Acks zu warten. Die werden danach empfangen. Solltest du andere Szenarien haben, also die Kommandos kleine Verzögerungen haben, zwischendurch schon acks einlaufen... dann kommt es quasi immer zu kollisionen. Für den allgemeinen Betrieb ist es daher sicherer, die Q auf 1 zu stellen.
Deine Darstellung ist soweit korrekt. keepalive wird immer gesendet. Was zu beachten ist, sind die acks der Devices, die unkoordiniert dazwischen kommen können. Das macht es vom timing her nicht mehr vorhersehbar.
Das ganze wäre kein Problem, wäre die Zentrale endlos schnell. Perl in sich ist schon vom Prinzip her nicht performant, geht aber schon. Das ganze wird problematisch bei Fileaktionen (logen,...) geht aber erstaunlich gut. Wirklich schlecht wird es, wenn aktionen wir web.interfaces dazu kommen. das kann endlos dauern.
Das Abarbeiten von Events in FHEM erfolgt zeitlich gestaffelt. Prios gibt es keine. von Echtzeitfähigkeit will Rudi nichts wissen.
=> es wird also nach best-effort probiert, das timng aufrecht zu erhalten. Eine Grantie kann strukturell nicht gegeben werden. Es gibt aber wiederhol-mechanismen und ggf status-nachfragen um aufgetretene Probleme abzufangen.
Um zu klären, wer hier evtl bummelt kannst du apptime probieren (vor jedem Versuch rücksetzen) und auch logs ziehen. dann kann man sehen, wer wann dran kommt und wie lange es von log zu log dauert.
Hallo Martin,
danke für deine detaillierten Ausführungen. Der Vorschlag, Aktoren (oder Gruppen davon) mit virtuellen Sender zu peeren, klingt interessant. Ich nehme an die VCCU-Buttons sind dazu perfekt geeignet :-) Gibts beim peering was zu besonderes zu beachten oder mache ich das nach Schema F nacheinander für die einzelnen Aktoren?
Inzwischen habe ich tatsächlich eine Verbesserung der Situation erreichen können, siehe hierzu auch http://forum.fhem.de/index.php/topic,28623.msg221222.html#msg221222
Apptime ist ein wertvolles Tool, hat aber meine Vorstellung zu sehr darauf versteift, es mit einem Problem in CUL_HM zu tun zu haben, während die Ursache tatsächlich deutlich kopmplexer war. Auch ein global verbose 5 hat diesen Eindruck nicht entkräften können*. Erst nachdem ich für meine Tests für alle Entities verbose auf 5 gesetzt hatte (und damit auch für die structures), konnte ich sehen, dass die langen Delays aus einer ungünstigen Kombination aus vielen Aktoren in sich überlappenden structures, vielen neuen Events und daraus resultierende Aktionen von FHEMWEB resultierten. Letztere haben über die structures bei jedem Event alle möglichen Schalter zeitaufwändig mit "set ?" abgefragt, was Rudi inzwischen abgestellt hat.
Im Moment teste ich gerade eine Modifikation für structures, die ein set auf der structure optional nicht "HM-atomar" ausführt, sondern alle Aktionen in eine Queue stellt und diese per Timer einzeln abarbeitet. Im Augenblick sieht es so aus, als würde der Ansatz ganz gut aufgehen, es kommt vereinzelt zu Delays von maximal 1.3 Sekunden, die Werte in apptime sehen entsprechend gut aus.
Nachdem sich herausgestellt hat, dass das Thema vorwiegend structure-bezogen ist, können wir diesen Thread gerne als gelöst betrachten. Gerne kann ich ihn auch schließen, würde aber noch deine Antwort zum Thema "peering mit virtuellem Sender" abwarten.
Beste Grüße und nochmals vielen Dank für Deine Hilfe und Ausführungen,
Andy.
(*) Was eines Erachtens für die zielführende Fehlersuche fehlt, ist ein guter Wikiartikel mit best-practices, der auch etwas mehr in die Tiefe geht; die vielen Beiträge im Forum zum Thema mögen das in der Summe vielleicht abdecken, sind aber zu verteilt und mittels Forum-Suche nicht einfach zu finden. Auch das ist aber ein eher übergreifendes Thema und gehört nicht hierher.
Bei virtuellen aktoren ist nicht viel zu beachten - hoffe ich. Nun na
1) besonders effektiv sind sie. Bei hmlan oder usb. Da sendet das io die acks. Bei cul ist ein kanal der vccu genauso effektiv wie jeder andere.
2) nach dem peeren darf man save nicht vergessen. Die vccu speichert peers natuerlich in attributen - wo sonst.
3) das virtuelle druecken von tastern sollte eine wirkliche gleichzeitigkeit garantieren, was ins esondere bei lichtern wichtig sein kann. Das kann man von der zentrale aus nicht erreichen
Wenn du fragen dazu hast macht ein neuer thraet sicher sinn.
Zum debuggen kannst du gerne etwas schreiben. Mir fehlt hier die phantasie. Die probleme sind zu unteeschiedlich oder werden von anfaengern nicht erfasst. Z.b. das lesen von rohmessages.
Sicher kann man auf die auswertetool hinweisen
Rohmessages, hminfo statistiken, apptime sind quasi alles, was ich brauche (fast ). Ein status ueber laufende timer ist auch ganz nett, aber das mache ich aktuell manuell.