Seltsames zeitliches Verhalten beim gleichzeitigen Schalten mehrerer HM-Schalter

[gandy]

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:

Code Auswählen Erweitern


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:

Code Auswählen Erweitern


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:

Code Auswählen Erweitern


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)


Code Auswählen Erweitern


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


Code Auswählen Erweitern


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:

Code Auswählen Erweitern


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.

[martinp876]

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

[gandy]

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

Code Auswählen Erweitern


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

Code Auswählen Erweitern


{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:

Code Auswählen Erweitern


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.

[martinp876]

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

[gandy]

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.

[martinp876]

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.

[gandy]

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.

[gandy]

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.

[gandy]

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:

Code Auswählen Erweitern


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 

Danke fürs Lesen und Deine Geduld,
Grüße,
Andy.

[gandy]

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.

[martinp876]

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.

Dazu 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.

[gandy]

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.

[martinp876]

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.