[geklärt] Verzögerung durch ActionDetector o.a. beim FHEM-Start?

Pfriemler · 21 Juni 2020, 15:01:57

Bedingt durch ein paar Neustarts der letzten Tage fiel mir auf, dass der Start von FHEM seit kurzer Zeit bedeutend länger dauert.
Exakt nach allen "Device ... added to ActionDetector ..." entstand seit längerem eine Pause vor der Initialisierung der ESPBridge. Also hatte ich diese in Verdacht und habe sie aus FHEM gelöscht (ein attr disable ignoriert sie übrigens komplett und initialisiert sich inkl. Funktion trotzdem). Nun entstand die Verzögerung vor dem nächsten Eintrag.
Das passte nicht. Also habe ich die Verzögerung einmal exemplarisch in Abhängigkeit von den ActionDetector-Devices untersucht.

edit: überarbeitete Version.

Code Auswählen

2019.11.12 08:17:19.200 3: Device BewMelder1 added to ActionDetector with 000:20 time
... (43 Geräte insgesamt)
2019.11.12 08:17:30.103 3: Device TDiffSens1 added to ActionDetector with 012:00 time
... Verzögerung 26.7s
2019.11.12 08:17:56.813 3: ESPEasy ESPBridge: Bridge v2.18 port [TCP:IPV4:8383] opened.

macht ziemlich genau 0,6209 s pro Gerät.

Code Auswählen

2020.05.24 18:23:04 3: Device BewMelder1 added to ActionDetector with 000:20 time
... (47)
2020.05.24 18:23:16 3: Device Wassermelder_1 added to ActionDetector with 028:00 time
... Verzögerung 29s
2020.05.24 18:23:45 3: ESPEasy ESPBridge: Bridge v2.18 port [TCP:IPV4:8383] opened.

da hier msec aus war, nicht genauer: 0,617s pro Gerät.

In den letzten Tagen hat in der Nachbarschaft jemand etwas über 30 Homematic-Geräte in Betrieb genommen. Ich habe sie spaßeshalber mitdefiniert.

Code Auswählen


2020.06.21 14:11:32 1: Including fhem.cfg
...
2020.06.21 14:12:07 3: Device BewMelder1 added to ActionDetector with 000:20 time
... (79 Geräte)
2020.06.21 14:12:23 3: Device Wassermelder_1 added to ActionDetector with 028:00 time
... Verzögerung 47 Sekunden
2020.06.21 14:13:10 3: ESPEasy ESPBridge: Bridge v2.18 port [TCP:IPV4:8383] opened.
...
2020.06.21 14:13:13 0: Server started with 1075 defined entities (fhem.pl:22172/2020-06-12 perl:5.024001 os:linux user:fhem pid:7985)

hier sind es also noch 0,594s pro ActionDetector-Gerät. Aber dennoch!

Das kann doch kein Zufall mehr sein!

Der gesamte Start von FHEM dauert also aktuell bei mir 101 Sekunden - davon entfallen 47 Sekunden auf diese ominöse Sache.

Vielleicht liegt es auch an etwas anderem, aber diese Korrelation ist doch extrem auffällig!

Was läuft hier schief? Kann das jemand mal in seinen Logs nachsehen ob es ähnliche Effekte gibt?

frank · 21 Juni 2020, 16:13:45

zu einem block von 24 devices am stück sagt mein log 2.146 sek.

mein AD hat aber trotzdem schon sehr lange ein problem, das martin mal beheben müsste:
https://forum.fhem.de/index.php/topic,101138.msg975930/topicseen.html#msg975930

LuckyDay · 21 Juni 2020, 17:24:07

Code Auswählen

2020.06.21 17:13:07.123 3: BEFEHL-EXTERN-MQTT-->: shutdown restart
2020.06.21 17:13:07.126 0: Server shutdown
2020.06.21 17:13:07 2: Perfmon: ready to watch out for delays greater than 1,5 second
2020.06.21 17:13:07.652 1: Including fhem3.cfg
2020.06.21 17:13:07.861 3: WEB: port 8093 opened
2020.06.21 17:13:07.905 1: Including cfgs/hm_io.cfg
2020.06.21 17:13:07.933 1: HMLAN_Parse: hmlan1 new condition disconnected
2020.06.21 17:13:07.934 3: Opening hmlan1 device 192.168.2.80:1000
2020.06.21 17:13:07.938 1: HMLAN_Parse: hmlan1 new condition init
2020.06.21 17:13:07.939 3: hmlan1 device opened
2020.06.21 17:13:07.941 1: HMLAN_Parse: hmlan2 new condition disconnected
2020.06.21 17:13:07.941 3: Opening hmlan2 device 192.168.2.81:1000
2020.06.21 17:13:07.945 1: HMLAN_Parse: hmlan2 new condition init
2020.06.21 17:13:07.946 3: hmlan2 device opened
2020.06.21 17:13:08.300 1: Including cfgs/hm_device.cfg
2020.06.21 17:13:08.686 1: Including /tmp/fhem3.save
2020.06.21 17:13:08.851 3: Device AussenTemp added to ActionDetector with 000:10 time
2020.06.21 17:13:08.870 3: Device eg_Halle added to ActionDetector with 000:10 time
2020.06.21 17:13:08.885 3: Device eg_Schlafzimmer added to ActionDetector with 000:10 time
2020.06.21 17:13:08.898 3: Device eg_ku_vd added to ActionDetector with 028:00 time
2020.06.21 17:13:08.902 3: Device eg_sz_vd added to ActionDetector with 028:00 time
2020.06.21 17:13:08.907 3: Device eg_wz_vd added to ActionDetector with 028:00 time
2020.06.21 17:13:08.916 3: Device og_Bad added to ActionDetector with 000:10 time
2020.06.21 17:13:08.924 3: Device og_Schlafzimmer added to ActionDetector with 000:10 time
2020.06.21 17:13:08.933 3: Device og_Wohnzimmer added to ActionDetector with 000:10 time
2020.06.21 17:13:08.938 3: Device og_bad_vd added to ActionDetector with 028:00 time
2020.06.21 17:13:08.943 3: Device og_sz_vd added to ActionDetector with 028:00 time
2020.06.21 17:13:09.288 3: Opening hmuart1 device 192.168.2.108:23
2020.06.21 17:13:09.293 0: Featurelevel: 6
2020.06.21 17:13:09.294 0: Server started with 90 defined entities (fhem.pl:22200/2020-06-19 perl:5.028001 os:linux user:fhem pid:21398)
2020.06.21 17:13:09.295 3: Opening mqttclient_localhost_HM device localhost:1883
2020.06.21 17:13:09.306 1: HMLAN_Parse: hmlan2 new condition ok
2020.06.21 17:13:09.313 1: HMLAN_Parse: hmlan1 new condition ok
2020.06.21 17:13:09.320 3: mqttclient_localhost_HM device opened
2020.06.21 17:13:09.397 3: hmuart1 device opened
2020.06.21 17:13:10.287 3: CUL_HM set Aussen_Licht_Strasse statusRequest
2020.06.21 17:13:11.293 3: CUL_HM set Aussen_Licht_Treppe statusRequest
2020.06.21 17:13:12.300 3: CUL_HM set hzpumpe_eg statusRequest
2020.06.21 17:13:13.306 3: CUL_HM set hzpumpe_og statusRequest
2020.06.21 17:13:14.318 3: CUL_HM set ww_zirk statusRequest
2020.06.21 17:13:15.334 3: CUL_HM set y_sw4 statusRequest
2020.06.21 17:13:16.348 3: CUL_HM set eg_Roll1 statusRequest
2020.06.21 17:13:17.359 3: CUL_HM set eg_Roll2 statusRequest
2020.06.21 17:13:18.365 3: CUL_HM set eg_Roll3 statusRequest
2020.06.21 17:13:19.371 3: CUL_HM set eg_Roll4 statusRequest
2020.06.21 17:13:20.378 3: CUL_HM set eg_eingang_Sw statusRequest
2020.06.21 17:13:21.384 3: CUL_HM set eg_eingang_Sw1_V_01 statusRequest
2020.06.21 17:13:22.390 3: CUL_HM set eg_eingang_Sw1_V_02 statusRequest
2020.06.21 17:13:23.401 3: CUL_HM set eg_klo statusRequest
2020.06.21 17:13:24.414 3: CUL_HM set eg_ku statusRequest
2020.06.21 17:13:25.420 3: CUL_HM set wz_Licht_1 statusRequest
2020.06.21 17:13:26.428 3: CUL_HM set wz_Roll1 statusRequest
2020.06.21 17:13:27.436 3: CUL_HM set wz_Roll2 statusRequest
2020.06.21 17:13:28.442 3: CUL_HM set wz_Roll3 statusRequest
2020.06.21 17:13:34.961 2: AttrTemplates: got 176 entries
2020.06.21 17:13:35.249 3: CUL_HM set og_Bad statusRequest
2020.06.21 17:13:42.801 3: CUL_HM set og_Schlafzimmer statusRequest
2020.06.21 17:14:33.571 3: CUL_HM set og_Wohnzimmer statusRequest
2020.06.21 17:15:02.990 3: CUL_HM set eg_Schlafzimmer statusRequest

Meine HM Instanz ist nach ein bisschen mehr wie 2-3 Sekunden wieder am Start, extra noch von Heute ein Update gemacht.

irgendwie hast du da ein Problem @ Pfriemler

Pfriemler · 21 Juni 2020, 18:55:07

Zitat von: frank am 21 Juni 2020, 16:13:45
zu einem block von 24 devices am stück sagt mein log 2.146 sek.

Und das genauso auf einem Pi3.

Zitat von: fhem-hm-knecht am 21 Juni 2020, 17:24:07
Meine HM Instanz ist nach ein bisschen mehr wie 2-3 Sekunden wieder am Start, extra noch von Heute ein Update gemacht.

Das hatte ich noch nie. Allerdings ist dein FHEM aber auch sehr schlank im Vergleich - 90 entities vs. >1000 bei mir.

Zitatirgendwie hast du da ein Problem @ Pfriemler

Achwas!

Ideen zum Weitersuchen? Könnte natürlich sein, dass die SD-Karte mal wieder kurz vor dem Abnippeln ist - allerdings habe ich sonst keine Probleme mit fehlenden Daten, langsamen oder fehlenden Aktionen... saveConfig ist (bei einer fhem.cfg von 560k) in <1s fertig.
defmods von größeren DOIF dauern auch schon mal 3s - sagt freezemon oder ähnliche Aktionen. Insgesamt fühlt sich alles dennoch ziemlich flüssig an, bzw. mich stört nix.

Nachtrag:

Was ich ja nicht kapiere: Die Abarbeitung der ActionDetector-Meldungen selbst dauert maximal 16 Sekunden (bei 79 Geräten). Erst danach entsteht ja dieses Warteloch.
So als würde jeder ActionDetector-Aufruf einen eigenen Thread lostreten, auf deren Ende erst gewartet wird.
Bei fhem-hm-knecht sind die 11 Geräte in 87ms zugefügt, danach entsteht ein Loch von 345ms
Das ist auch gut 4x länger als von der ersten bis zur letzten "added to" Meldung.
Geht halt alles viel schneller. Ist vermutlich auch kein RPi3?

Also wie gesagt: Jeder Hinweis zur Diagnose ist willkommen.

frank · 21 Juni 2020, 19:25:14

vielleicht mal verbose erhöhen beim ad?

Pfriemler · 21 Juni 2020, 19:42:51

Hatte ich schon probiert, war nicht erhellend.

Aber ich habe in global mal verbose=5 gesetzt, um zu sehen, was in der Pause da passiert.
Und siehe da: Es korreliert weniger mit dem ActionDetector - mehr mit der Anzahl meiner HM-Geräte überhaupt?

Code Auswählen

2020.06.21 19:17:22 3: Device Wassermelder_1 added to ActionDetector with 028:00 time
2020.06.21 19:17:22 5: Starting notify loop for Wassermelder_1, 1 event(s), first is Activity: alive
...
2020.06.21 19:17:24 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2E13E5
2020.06.21 19:17:24 5: HMUARTLGW HMUART HMUARTLGW_Write: init:529E82
2020.06.21 19:17:24 5: HMUARTLGW HMUART HMUARTLGW_Write: init:224A71
2020.06.21 19:17:25 5: HMUARTLGW HMUART HMUARTLGW_Write: init:312F44
2020.06.21 19:17:26 5: HMUARTLGW HMUART HMUARTLGW_Write: init:313194
2020.06.21 19:17:26 5: HMUARTLGW HMUART HMUARTLGW_Write: init:3D64C2
2020.06.21 19:17:27 5: HMUARTLGW HMUART HMUARTLGW_Write: init:518FB2
2020.06.21 19:17:27 5: HMUARTLGW HMUART HMUARTLGW_Write: init:23B2D0
2020.06.21 19:17:28 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2D8588
2020.06.21 19:17:28 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2D8579
2020.06.21 19:17:28 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2B62CC
2020.06.21 19:17:28 5: HMUARTLGW HMUART HMUARTLGW_Write: init:361500
2020.06.21 19:17:30 5: HMUARTLGW HMUART HMUARTLGW_Write: init:4D18E3
2020.06.21 19:17:31 5: HMUARTLGW HMUART HMUARTLGW_Write: init:24BB9F
2020.06.21 19:17:32 5: HMUARTLGW HMUART HMUARTLGW_Write: init:3BB24D
2020.06.21 19:17:32 5: HMUARTLGW HMUART HMUARTLGW_Write: init:3BB54D
2020.06.21 19:17:33 5: HMUARTLGW HMWLAN1 HMUARTLGW_Write: init:41676B
2020.06.21 19:17:33 5: HMUARTLGW HMUART HMUARTLGW_Write: init:283AEA
2020.06.21 19:17:34 5: HMUARTLGW HMUART HMUARTLGW_Write: init:3425BE
2020.06.21 19:17:35 5: HMUARTLGW HMWLAN1 HMUARTLGW_Write: init:3E59D3
2020.06.21 19:17:36 5: HMUARTLGW HMWLAN1 HMUARTLGW_Write: init:3E59B0
2020.06.21 19:17:37 5: HMUARTLGW HMUART HMUARTLGW_Write: init:242144
2020.06.21 19:17:38 5: HMUARTLGW HMUART HMUARTLGW_Write: init:239F63
2020.06.21 19:17:39 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2547B4
2020.06.21 19:17:39 5: HMUARTLGW HMUART HMUARTLGW_Write: init:5A2657
2020.06.21 19:17:40 5: HMUARTLGW HMUART HMUARTLGW_Write: init:37B755
2020.06.21 19:17:40 5: HMUARTLGW HMUART HMUARTLGW_Write: init:37BA9F
2020.06.21 19:17:40 5: HMUARTLGW HMUART HMUARTLGW_Write: init:31C4DB
2020.06.21 19:17:40 5: HMUARTLGW HMUART HMUARTLGW_Write: init:4E7558
2020.06.21 19:17:40 5: HMUARTLGW HMUART HMUARTLGW_Write: init:46694A
2020.06.21 19:17:40 5: HMUARTLGW HMUART HMUARTLGW_Write: init:696E6D
2020.06.21 19:17:40 5: HMUARTLGW HMUART HMUARTLGW_Write: init:37B939
2020.06.21 19:17:40 5: HMUARTLGW HMWLAN1 HMUARTLGW_Write: init:4E7559
2020.06.21 19:17:40 5: HMUARTLGW HMUART HMUARTLGW_Write: init:37BAC7
2020.06.21 19:17:40 5: HMUARTLGW HMUART HMUARTLGW_Write: init:366AEA
2020.06.21 19:17:40 5: HMUARTLGW HMUART HMUARTLGW_Write: init:366AF9
2020.06.21 19:17:41 5: HMUARTLGW HMUART HMUARTLGW_Write: init:5197F4
2020.06.21 19:17:41 5: HMUARTLGW HMUART HMUARTLGW_Write: init:23BDA6
2020.06.21 19:17:41 5: HMUARTLGW HMUART HMUARTLGW_Write: init:28B32B
	2020.06.21 19:17:42 4: [HKThermostat1_Weather moving average] Value = 25.3 Time = 2020-06-21 19:14:10
	...
	2020.06.21 19:17:42 4: [HKThermostat1_Weather moving average] calculated over 3 values is  25.3
2020.06.21 19:17:42 5: HMUARTLGW HMUART HMUARTLGW_Write: init:353FED
	2020.06.21 19:17:42 4: [HKThermostat2_Weather moving average] Value = 24.8 Time = 2020-06-21 19:15:03
	...
	2020.06.21 19:17:42 4: [HKThermostat2_Weather moving average] calculated over 3 values is  24.8
2020.06.21 19:17:43 5: HMUARTLGW HMUART HMUARTLGW_Write: init:3B097F
	2020.06.21 19:17:43 4: [HKThermostat3_Weather moving average] Value = 23.8 Time = 2020-06-21 19:15:50
	...
	2020.06.21 19:17:43 4: [HKThermostat3_Weather moving average] calculated over 4 values is  23.8
2020.06.21 19:17:43 5: HMUARTLGW HMUART HMUARTLGW_Write: init:41434D
2020.06.21 19:17:45 5: HMUARTLGW HMUART HMUARTLGW_Write: init:4F5BB9
2020.06.21 19:17:45 5: HMUARTLGW HMUART HMUARTLGW_Write: init:4D07DF
2020.06.21 19:17:45 5: HMUARTLGW HMUART HMUARTLGW_Write: init:190D0F
2020.06.21 19:17:45 5: HMUARTLGW HMWLAN1 HMUARTLGW_Write: init:1A95C9
2020.06.21 19:17:46 5: HMUARTLGW HMUART HMUARTLGW_Write: init:266A77
2020.06.21 19:17:46 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2E3EEE
2020.06.21 19:17:47 5: HMUARTLGW HMUART HMUARTLGW_Write: init:376BB2
2020.06.21 19:17:47 5: HMUARTLGW HMUART HMUARTLGW_Write: init:40AA91
2020.06.21 19:17:47 5: HMUARTLGW HMUART HMUARTLGW_Write: init:414004
2020.06.21 19:17:47 5: HMUARTLGW HMUART HMUARTLGW_Write: init:4213A0
2020.06.21 19:17:48 5: HMUARTLGW HMUART HMUARTLGW_Write: init:42A296
2020.06.21 19:17:48 5: HMUARTLGW HMUART HMUARTLGW_Write: init:49E7AB
2020.06.21 19:17:48 5: HMUARTLGW HMWLAN1 HMUARTLGW_Write: init:52C2C2
2020.06.21 19:17:48 5: HMUARTLGW HMUART HMUARTLGW_Write: init:3043A4
2020.06.21 19:17:50 5: HMUARTLGW HMUART HMUARTLGW_Write: init:47718D
2020.06.21 19:17:51 5: HMUARTLGW HMWLAN1 HMUARTLGW_Write: init:222002
2020.06.21 19:17:51 5: HMUARTLGW HMWLAN1 HMUARTLGW_Write: init:222001
2020.06.21 19:17:51 5: HMUARTLGW HMUART HMUARTLGW_Write: init:3B4558
2020.06.21 19:17:51 4: [HM_UWS1 moving average] Value = 26.9 Time = 2020-06-21 19:16:18
...
2020.06.21 19:17:51 4: [HM_UWS1 moving average] calculated over 4 values is  12.9
2020.06.21 19:17:51 5: HMUARTLGW HMUART HMUARTLGW_Write: init:D879E9
2020.06.21 19:17:51 5: HMUARTLGW HMUART HMUARTLGW_Write: init:63D5BF
2020.06.21 19:17:51 5: HMUARTLGW HMUART HMUARTLGW_Write: init:E6F85A
2020.06.21 19:17:51 5: HMUARTLGW HMUART HMUARTLGW_Write: init:3F8D03
2020.06.21 19:17:51 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2E34B8
2020.06.21 19:17:51 5: HMUARTLGW HMUART HMUARTLGW_Write: init:24E6BF
2020.06.21 19:17:51 5: HMUARTLGW HMUART HMUARTLGW_Write: init:258DF4
2020.06.21 19:17:52 5: HMUARTLGW HMWLAN1 HMUARTLGW_Write: init:68A129
2020.06.21 19:17:53 5: HMUARTLGW HMUART HMUARTLGW_Write: init:3E46A1
2020.06.21 19:17:53 5: HMUARTLGW HMUART HMUARTLGW_Write: init:361516
2020.06.21 19:17:53 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2B9616
2020.06.21 19:17:54 4: [KBThermostat_Weather moving average] Value = 23.8 Time = 2020-06-21 19:13:39
...
2020.06.21 19:17:54 4: [KBThermostat_Weather moving average] calculated over 4 values is  14.2
2020.06.21 19:17:54 5: HMUARTLGW HMUART HMUARTLGW_Write: init:388E07
2020.06.21 19:17:54 5: HMUARTLGW HMUART HMUARTLGW_Write: init:4EF263
2020.06.21 19:17:55 5: HMUARTLGW HMUART HMUARTLGW_Write: init:336CFB
2020.06.21 19:17:55 5: HMUARTLGW HMUART HMUARTLGW_Write: init:26FC58
2020.06.21 19:17:56 5: HMUARTLGW HMUART HMUARTLGW_Write: init:29765C
2020.06.21 19:17:56 5: HMUARTLGW HMUART HMUARTLGW_Write: init:297659
2020.06.21 19:17:56 5: HMUARTLGW HMUART HMUARTLGW_Write: init:378014
2020.06.21 19:17:57 5: HMUARTLGW HMWLAN1 HMUARTLGW_Write: init:1DF5B5
2020.06.21 19:17:57 5: HMUARTLGW HMUART HMUARTLGW_Write: init:272902
2020.06.21 19:17:57 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2C05AE
2020.06.21 19:18:01 5: HMUARTLGW HMUART HMUARTLGW_Write: init:3AC62C
2020.06.21 19:18:01 5: HMUARTLGW HMUART HMUARTLGW_Write: init:50EB6B
2020.06.21 19:18:01 5: HMUARTLGW HMUART HMUARTLGW_Write: init:22C9F7
2020.06.21 19:18:01 5: HMUARTLGW HMUART HMUARTLGW_Write: init:22C98D
2020.06.21 19:18:01 5: HMUARTLGW HMUART HMUARTLGW_Write: init:22C96E
2020.06.21 19:18:01 5: HMUARTLGW HMUART HMUARTLGW_Write: init:52B83A
2020.06.21 19:18:01 5: HMUARTLGW HMUART HMUARTLGW_Write: init:52B857
2020.06.21 19:18:01 5: HMUARTLGW HMUART HMUARTLGW_Write: init:52B814
2020.06.21 19:18:01 5: HMUARTLGW HMUART HMUARTLGW_Write: init:41D287
2020.06.21 19:18:02 5: HMUARTLGW HMUART HMUARTLGW_Write: init:22D1D0
2020.06.21 19:18:02 5: HMUARTLGW HMUART HMUARTLGW_Write: init:466984
2020.06.21 19:18:02 5: HMUARTLGW HMUART HMUARTLGW_Write: init:31C4DE
2020.06.21 19:18:02 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2446E4
2020.06.21 19:18:02 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2447B5
2020.06.21 19:18:03 5: HMUARTLGW HMUART HMUARTLGW_Write: init:29F2CA
2020.06.21 19:18:03 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2D9AAE
2020.06.21 19:18:04 5: HMUARTLGW HMUART HMUARTLGW_Write: init:374516
2020.06.21 19:18:04 4: [TDiffSens1_T1 moving average] Value = 48.6 Time = 2020-06-21 19:15:05
...
2020.06.21 19:18:04 4: [TDiffSens1_T2 moving average] calculated over 3 values is  40.7
2020.06.21 19:18:04 5: Starting notify loop for TeamRauchmelder, 1 event(s), first is off
2020.06.21 19:18:04 5: End notify loop for TeamRauchmelder
2020.06.21 19:18:05 5: HMUARTLGW HMUART HMUARTLGW_Write: init:4E0D8F
2020.06.21 19:18:05 5: HMUARTLGW HMUART HMUARTLGW_Write: init:5A369C
2020.06.21 19:18:05 5: HMUARTLGW HMUART HMUARTLGW_Write: init:1E4D08
2020.06.21 19:18:05 5: HMUARTLGW HMUART HMUARTLGW_Write: init:24F20D
2020.06.21 19:18:06 5: HMUARTLGW HMUART HMUARTLGW_Write: init:24BC41
2020.06.21 19:18:06 5: HMUARTLGW HMUART HMUARTLGW_Write: init:420C15
2020.06.21 19:18:08 5: Starting notify loop for vccu, 2 event(s), first is IOopen: 0
2020.06.21 19:18:08 5: End notify loop for vccu
2020.06.21 19:18:08 5: HMUARTLGW HMUART HMUARTLGW_Write: writeAesKey:HMUART
2020.06.21 19:18:08 5: HMUARTLGW HMWLAN1 HMUARTLGW_Write: writeAesKey:HMWLAN1
2020.06.21 19:18:10 5: Calendar Abfallkalender: FHEM initialization or rereadcfg triggered update, delay 10 seconds.
2020.06.21 19:18:10 4: Ignoring CUL_WS_1_Aussen
...
2020.06.21 19:18:10 4: Ignoring unknown_FFFFFF
2020.06.21 19:18:10 4: FB_CALLLIST (Anrufliste) ...
2020.06.21 19:18:10 4: ESPEasy ESPBridge: Available set cmds/maps (re)initialized.
2020.06.21 19:18:10 4: ESPEasy ESPBridge: Available attributes (re)initialized.
2020.06.21 19:18:10 5: Starting notify loop for ESPBridge, 1 event(s), first is Initialized
2020.06.21 19:18:10 5: End notify loop for ESPBridge
2020.06.21 19:18:10 3: ESPEasy ESPBridge: Bridge v2.18 port [TCP:IPV4:8383] opened.

In dieser Frist werden meine beiden aktiven HM-IOdev mit "init:<DEF>" beackert, und zwar exakt immer das Gerät was in der Definition des Gerätes im attr IODev eingetragen ist. Meines Wissens wird das bei mir ausschließlich von der VCCU verwaltet, ich habe da ewig nichts nachgetragen. IOgrp ist natürlich gesetzt.
Zwischendurch laufen etliche MovingAverage-Berechnungen und die Ignores, aber wie man sieht, fressen die nur marginal Rechenzeit.

Welchem Behufe dienen diese Inits? Und warum dauern sie so erschreckend lange? edit: Eintragung im IODev, auf welche Geräte sie direkt mit einem ACK antworten können - Liste der peers im Listing?

Nachtrag: Meine IO-Defs

Code Auswählen

Internals:
...
   DEF        uart://192.168.178.154:23
   NAME       HMWLAN1
   NOTIFYDEV  global
...
   TYPE       HMUARTLGW
   XmitOpen   1
   model      HM-MOD-UART
   msgLoadCurrent 4
   msgLoadHistory 0/0/2/0/2/-/-/-/-/-/-/-
   msgLoadHistoryAbs 4/4/4/2/2/0/-/-/-/-/-/-/-
   owner      1411AB
   owner_CCU  vccu
   .attraggr:
   .attrminint:
   .clientArray:
     CUL_HM
   Helper:
     CreditTimer 119
     FW         66561
     Initialized 1
     SendCnt    15
     AckPending:
       185:
         cmd        020000007280021411AB2D858801017000
         dst        1
         frame      FD001301B9020000007280021411AB2D8588010170005ECA
         time       1592761059.19984
       207:
         cmd        020000007380021411AB2D858801016C00
         dst        1
         frame      FD001301CF020000007380021411AB2D858801016C0057E5
         time       1592761380.3934
       231:
         cmd        020000007480021411AB2D858801017000
         dst        1
         frame      FD001301E7020000007480021411AB2D858801017000434F
         time       1592761672.26929
     LastSendLen:
       19
       3
     Log:
       IDs:
     PendingCMD:
     RoundTrip:
       Delay      0.0378291606903076
     loadLvl:
       lastHistory 1592761408.27457
   MatchList:
     1:CUL_HM   ^A......................
   Peers:
     1A95C9     +1A95C9,00,01,00
     1DF5B5     +1DF5B5,00,01,00
     222001     +222001,00,01,00
     222002     +222002,00,01,00
     26FC58     +26FC58,00,01,00
     29765C     +29765C,00,01,00
     2D8588     +2D8588,00,01,00
     3E59B0     +3E59B0,00,01,00
     3E59D3     +3E59D3,00,01,00
     41676B     +41676B,00,01,00
     4E0D8F     +4E0D8F,00,01,00
     4E7559     +4E7559,00,01,00
     5197F4     +5197F4,00,01,00
     52C2C2     +52C2C2,00,01,00
     5A369C     +5A369C,00,01,00
     68A129     +68A129,00,01,00
     D879E9     +D879E9,00,01,00
   READINGS:
...
     2020-06-21 19:18:26   D-firmware      1.4.1
...
     2020-06-21 19:16:33   D-type          HM-MOD-UART
     2020-06-21 19:18:28   cond            ok
     2020-06-21 19:33:31   load            4
     2020-06-21 19:18:28   loadLvl         low
     2020-06-21 19:18:22   state           opened
Attributes:
   group      Schnittstellen
   hmId       1411AB
   icon       hm_ccu
   room       System->Schnittstellen
   stateFormat [$name:state] (Stand: [$name:state:t])

und

Code Auswählen

Internals:
   AssignedPeerCnt 87
   CNT        66
   Clients    :CUL_HM:
   DEF        /dev/ttyAMA0
   DEVCNT     66
   DevState   99
   DevType    UART
   DeviceName /dev/ttyAMA0@115200
   FD         51
   FUUID      5c5c4989-f33f-d113-da49-e6265ad23705543d
   LastOpen   1592759890.98692
   NAME       HMUART
   NOTIFYDEV  global
   NR         29
   NTFY_ORDER 50-HMUART
   PARTIAL    
   RAWMSG     04022D
   RSSI       -54
   STATE      opened (Stand: 2020-06-21 19:18:10)
   TYPE       HMUARTLGW
   XmitOpen   1
   model      HM-MOD-UART
   msgLoadCurrent 23
   msgLoadHistory 1/0/1/0/1/20/-/-/-/-/-/-
   msgLoadHistoryAbs 23/22/22/21/21/20/0/-/-/-/-/-/-
   owner      1411AB
   owner_CCU  vccu
   .attraggr:
   .attrminint:
   .clientArray:
     CUL_HM
   Helper:
     CreditTimer 129
     FW         66561
     Initialized 1
     SendCnt    70
     AckPending:
       166:
         cmd        02000000F780021411AB36151601010800
         dst        1
         frame      FD001301A602000000F780021411AB36151601010800A13B
         time       1592759999.73408
       167:
         cmd        02000000F780021411AB36151601010800
         dst        1
         frame      FD001301A702000000F780021411AB36151601010800352C
         time       1592760000.0369
       168:
         cmd        02000000F780021411AB36151601010800
         dst        1
         frame      FD001301A802000000F780021411AB36151601010800F9E0
         time       1592760000.80004
       191:
         cmd        020000006F80021411AB2D858801017400
         dst        1
         frame      FD001301BF020000006F80021411AB2D8588010174003B2F
         time       1592760180.01784
       201:
         cmd        02000000F880021411AB36151601010800
         dst        1
         frame      FD001301C902000000F880021411AB3615160101080068E9
         time       1592760255.33759
       202:
         cmd        02000000F880021411AB36151601010800
         dst        1
         frame      FD001301CA02000000F880021411AB3615160101080054D5
         time       1592760256.89941
       21:
         cmd        02000000FB80021411AB36151601010A00
         dst        1
         frame      FD0013011502000000FB80021411AB36151601010A00DAFE
         time       1592761259.61223
       217:
         cmd        020000007080021411AB2D858801017000
         dst        1
         frame      FD001301D9020000007080021411AB2D8588010170002658
         time       1592760459.24737
       22:
         cmd        02000000FB80021411AB36151601010A00
         dst        1
         frame      FD0013011602000000FB80021411AB36151601010A00E6C2
         time       1592761260.13077
       229:
         cmd        02000000F980021411AB36151601010800
         dst        1
         frame      FD001301E502000000F980021411AB36151601010800E516
         time       1592760620.34822
       23:
         cmd        02000000FB80021411AB36151601010A00
         dst        1
         frame      FD0013011702000000FB80021411AB36151601010A0072D5
         time       1592761261.15453
       236:
         cmd        020000007180021411AB2D858801017000
         dst        1
         frame      FD001301EC020000007180021411AB2D8588010170005E55
         time       1592760709.13526
       254:
         cmd        02000000FA80021411AB36151601010800
         dst        1
         frame      FD001301FE02000000FA80021411AB36151601010800384F
         time       1592760955.41318
       43:
         cmd        02000000FC80021411AB36151601010A00
         dst        1
         frame      FD0013012B02000000FC80021411AB36151601010A003F69
         time       1592761527.77615
     LastSendLen:
       3
       3
     Log:
       IDs:
     PendingCMD:
     RoundTrip:
       Delay      0.010653018951416
     loadLvl:
       lastHistory 1592761708.23557
   MatchList:
     1:CUL_HM   ^A......................
   Peers:
     190D0F     +190D0F,00,01,00
     1E4D08     +1E4D08,00,01,00
     224A71     +224A71,00,01,00
     22C96E     +22C96E,00,01,00
     22C98D     +22C98D,00,01,00
     22C9F7     +22C9F7,00,01,00
     22D1D0     +22D1D0,00,01,00
     239F63     +239F63,00,01,00
     23B2D0     +23B2D0,00,01,00
     23BDA6     +23BDA6,00,01,00
     242144     +242144,00,01,00
     2446E4     +2446E4,00,01,00
     2447B5     +2447B5,00,01,00
     24BB9F     +24BB9F,00,01,00
     24BC41     +24BC41,00,01,00
     24E6BF     +24E6BF,00,01,00
     24F20D     +24F20D,00,01,00
     2547B4     +2547B4,00,01,00
     258DF4     +258DF4,00,01,00
     266A77     +266A77,00,01,00
     272902     +272902,00,01,00
     283AEA     +283AEA,00,01,00
     28B32B     +28B32B,00,01,00
     297659     +297659,00,01,00
     29F2CA     +29F2CA,00,01,00
     2B62CC     +2B62CC,00,01,00
     2B9616     +2B9616,00,01,00
     2C05AE     +2C05AE,00,01,00
     2D8579     +2D8579,00,01,00
     2D9AAE     +2D9AAE,00,01,00
     2E13E5     +2E13E5,00,01,00
     2E34B8     +2E34B8,00,01,00
     2E3EEE     +2E3EEE,00,01,00
     3043A4     +3043A4,00,01,00
     312F44     +312F44,00,01,00
     313194     +313194,00,01,00
     31C4DB     +31C4DB,00,01,00
     31C4DE     +31C4DE,00,01,00
     336CFB     +336CFB,00,01,00
     3425BE     +3425BE,00,01,00
     353FED     +353FED,00,01,00
     361500     +361500,00,01,00
     361516     +361516,00,01,00
     366AEA     +366AEA,00,01,00
     366AF9     +366AF9,00,01,00
     374516     +374516,00,01,00
     376BB2     +376BB2,00,01,00
     378014     +378014,00,01,00
     37B755     +37B755,00,01,00
     37B939     +37B939,00,01,00
     37BA9F     +37BA9F,00,01,00
     37BAC7     +37BAC7,00,01,00
     388E07     +388E07,00,01,00
     3AC62C     +3AC62C,00,01,00
     3B097F     +3B097F,00,01,00
     3B4558     +3B4558,00,01,00
     3BB24D     +3BB24D,00,01,00
     3BB54D     +3BB54D,00,01,00
     3D64C2     +3D64C2,00,01,00
     3E46A1     +3E46A1,00,01,00
     3F8D03     +3F8D03,00,01,00
     40AA91     +40AA91,00,01,00
     414004     +414004,00,01,00
     41434D     +41434D,00,01,00
     41D287     +41D287,00,01,00
     420C15     +420C15,00,01,00
     4213A0     +4213A0,00,01,00
     42A296     +42A296,00,01,00
     46694A     +46694A,00,01,00
     466984     +466984,00,01,00
     47718D     +47718D,00,01,00
     49E7AB     +49E7AB,00,01,00
     4D07DF     +4D07DF,00,01,00
     4D18E3     +4D18E3,00,01,00
     4E7558     +4E7558,00,01,00
     4EF263     +4EF263,00,01,00
     4F5BB9     +4F5BB9,00,01,00
     50EB6B     +50EB6B,00,01,00
     518FB2     +518FB2,00,01,00
     529E82     +529E82,00,01,00
     52B814     +52B814,00,01,00
     52B83A     +52B83A,00,01,00
     52B857     +52B857,00,01,00
     5A2657     +5A2657,00,01,00
     63D5BF     +63D5BF,00,01,00
     696E6D     +696E6D,00,01,00
     E6F85A     +E6F85A,00,01,00
   READINGS:
     2020-06-21 19:18:26   D-HMIdAssigned  1411AB
     2020-06-21 19:18:26   D-HMIdOriginal  4C3F76
     2020-06-21 19:18:26   D-firmware      1.4.1
     2020-06-21 19:18:28   D-serialNr      NEQ0605740
     2020-06-21 19:16:33   D-type          HM-MOD-UART
     2020-06-21 19:18:28   cond            ok
     2020-06-21 19:45:23   load            23
     2020-06-21 19:18:28   loadLvl         low
     2020-06-21 19:18:10   state           opened
   helper:
Attributes:
   group      Schnittstellen
   hmId       1411AB
   icon       cul
   room       System->Schnittstellen
   stateFormat [$name:state] (Stand: [$name:state:t])

frank · 21 Juni 2020, 20:32:14

wie sind die io an fhem angekoppelt?

fhem auf pi3?
auf dessen gpio hmuart?
(wenn das stimmt, finde ich das roundtrip delay von 10.6 ms ziehmlich viel. ist wheezy richtig? bei mir sind das ziehmlich konstant zwischen 3.5 und 4 ms)

pi3 über lan auf wlanAccessPoint?
von dort zum hmwlan1?

Zitatund zwar exakt immer das Gerät was in der Definition des Gerätes im attr IODev eingetragen ist.

und das ist meiner meinung nach buggy. siehe https://forum.fhem.de/index.php/topic,112117.0.html

Pfriemler · 21 Juni 2020, 21:32:58

Zitat von: frank am 21 Juni 2020, 20:32:14
fhem auf pi3?
auf dessen gpio hmuart?

Genau.

Zitat(wenn das stimmt, finde ich das roundtrip delay von 10.6 ms ziehmlich viel. ist wheezy richtig? bei mir sind das ziehmlich konstant zwischen 3.5 und 4 ms)

Muss ich mal checken.
Im Log habe ich heute viele Werte, die meisten um 4-5, seltener 14 etc.

Zitatpi3 über lan auf wlanAccessPoint?

über zwei Switches an der Fritte.

Zitatvon dort zum hmwlan1?

WLAN, hängt direkt neben der Fritte. Kein Repeater.

Zitatund das ist meiner meinung nach buggy. siehe https://forum.fhem.de/index.php/topic,112117.0.html

Mag sein, aber diese beiden IO sind eigentlich immer verfügbar und für die meisten Geräte auch eher gleichwertig.

Es gibt da noch eine seltsame Geschichte, die mir eben erst auffällt.
Die gesamten Inits werden im Log bis 19:18:10 gesendet.

Ich hatte nur bis zur geöffneten ESPBridge gesucht. Danach geht es aber noch weiter:

Code Auswählen

2020.06.21 19:18:10 3: ESPEasy ESPBridge: Bridge v2.18 port [TCP:IPV4:8383] opened.
...
2020.06.21 19:18:10 4: Ignoring CUL_WS_1_Aussen
...
2020.06.21 19:18:10 3: Opening HMUART device /dev/ttyAMA0
2020.06.21 19:18:10 3: Setting HMUART serial parameters to 115200,8,N,1
2020.06.21 19:18:10 3: HMUART device opened
2020.06.21 19:18:10 5: Starting notify loop for HMUART, 1 event(s), first is CONNECTED
2020.06.21 19:18:10 5: createNotifyHash
2020.06.21 19:18:11 5: End notify loop for HMUART
2020.06.21 19:18:11 3: Opening HMWLAN1 device 192.168.178.154:23
2020.06.21 19:18:11 5: HttpUtils url=http://192.168.178.154:23/
2020.06.21 19:18:11 4: IP: 192.168.178.154 -> 192.168.178.154
2020.06.21 19:18:11 3: Opening LCGW device 192.168.178.158:81
2020.06.21 19:18:11 5: HttpUtils url=http://192.168.178.158:81/
2020.06.21 19:18:11 4: IP: 192.168.178.158 -> 192.168.178.158

Moment: Die IOs werden geöffnet nach den Inits?
Wohin wurden die Inits denn dann zuvor gesendet?

Die Devices stehen in der fhem.cfg händisch an vorderster Stelle. Wieso werden sie erst so spät genöffnet?

LuckyDay · 21 Juni 2020, 23:59:06

ZitatGeht halt alles viel schneller. Ist vermutlich auch kein RPi3?

Das ist ein Odroid HC1 dümpelt zwischen 600mHz und 1,5GHz rum mit 2G Hauptspeicher ARM und hat einen direkten Anschluss für SSD
nicht wirklich schnell. im Vergleich zu x86

Ich hab nur mein Fhem in HM | INETdienste| Anzeige| Sonstiges - also in 4 eigenständige Fhems unterteilt und die plappern untereinander mit MQTT2.
Steuern und Bedienen tue ich es nur mit dem AnzeigeFhem und das läuft für mich supergut. ( Ich habe mehr wie -->90 defined entities )

martinp876 · 22 Juni 2020, 08:29:44

Beim Booten (pi3):

Code Auswählen

07:28.319 1: Including fhem.cfg
07:42.021 1: Including ./log/fhem.save                                                     => 16sec zum einlesen
07:42.021 1: Including ./log/fhem.save
07:45.106 1: Messages collected while initializing FHEM:SecurityCheck:   => 3sec zum einlesen der Readings
07:45.153 1: CUL_HM_updateConfig   start
07:52.437 1: CUL_HM_updateConfig basic                                                => 7sec prüfung aller Devices (60st) und dere Channels (incl Action detector)
08:15.788 1: CUL_HM_updateConfig  fin                                                   => 23sec zum prüfen und einstellen device-spezifischer Einstellungen (300 Entities)

=> kleiner 200ms je Entity zum Ordnen der Parameter/atribute/readings

Ich schaue einmal, ob man es verbessern kann. ActionDetector scheint nicht das Problem zu sein.

martinp876 · 22 Juni 2020, 10:00:26

so, jetzt sollte es etwas schneller booten.

Pfriemler · 22 Juni 2020, 11:16:31

10_CUL_HM.pm? ich check's mal.

Martin, zur Bootreihenfolge (Geräte-Initialisierung) und der Reihenfolge in der fhem.cfg habe ich bei den Anfängern schon gefragt (weil mir ja unklar ist was genau nun das Problem ist):
https://forum.fhem.de/index.php/topic,112310.0.html
und dabei erfahren, dass inzwischen eher die Modulautoren die Reihenfolge der Geräte und ihrer Initialisierung bestimmen.

Deswegen frage ich hier nochmal ganz explizit: Wieso wird ein (so ziemlich als letztes definiertes) HMLAN als erstes versucht zu initialisieren (Auszug aus dem meinem Startlog im o.g. Beitrag verlinkt) - noch dazu wo es regelmäßig disconnected ist, insofern schon ähnlich zu Franks Problem, gerade ein HMUART auf dem seriellen des PI als letztes? Das ist doch, mal vereinfacht gesagt, Unfug.

Kann der Anwender da was beeinflussen und wenn ja wie?

martinp876 · 22 Juni 2020, 15:02:08

Reihenfolge:
Die ios sind zuerst einmal anderen modulen zugehörig. Somit werden sie nicht modulintern synchronisiert.
Der kernal führt schlicht die kommandos aus dem config aus, in der dort aufgeführten reihenfolge. Danach werden die readings aus "save" gelesen und gesetzt.
In der reihenfolge der cmds im config ist wichtig, dass erst ein define kommt, dann die attribute. bei den attribute wiederum hatte ich das problem, dass diese Abhängigkeiten haben. Insbesondere die definition des model bspw. Wenn man versucht, etwas inteligenter attribute zu verwalten (peers nur bei Kanälen,...) Muss man den kontext kennen.
Auch kritisch der action detector oder die vccu.
Nach dem einlesen der readings ist der kernal fertig und setzt initdone, was auch als event kommt. Das nutze ich zweifach:
Culhm prüft nun alle(ALLE) entities, deren attribute und readings(register). Da passiert ggf. Einiges. Dort wurde die neue Verwaltung der modelid eingebaut, was einen fliegenden update der attributnutzung ermöglichte. auch wenn ein held das extert attribut im config editiert... Werden die readings jetzt korrigiert (sichtbar setzen).
Hminfo liest die gasicherten Register und templates.

Das 2.: Als Nutzer starte ich nun die "Korrektur" meiner Installation. Ich setze eventonchangereading .*, expert=12,autoreadreg, ..... Alles, was ich evtl experimentell verändere wird unabhängig vom configfile hier korrigiert. Weiter starte ich kommandos aus myutil
=> Das user.cfg nach initdone sollte jeder haben.

Evtl war das nicht der kern deiner Frage. Devices (oder entities, channels?) Werden also die im config instanziiert. Leben\starten.... was ist das? Es werden nach init die Status angefragt. Das passiert im batch(queue) und die Reihenfolge kann sich änder . Gestartet wird erst nach initdone. Es wird das verfügbare io genutzt. Gewartet wird nicht

Pfriemler · 23 Juni 2020, 13:17:13

Zitat von: martinp876 am 22 Juni 2020, 10:00:26
so, jetzt sollte es etwas schneller booten.

Was auch immer Du da wieder gezaubert hast:

Code Auswählen

2020.06.23 12:01:03 3: Device Wassermelder_1 added to ActionDetector with 028:00 time
2020.06.23 12:01:22 3: ESPEasy ESPBridge: Bridge v2.18 port [TCP:IPV4:8383] opened.
2020.06.23 12:01:22 3: Opening HMUART device /dev/ttyAMA0
2020.06.23 12:01:22 3: Setting HMUART serial parameters to 115200,8,N,1
2020.06.23 12:01:22 3: HMUART device opened

Pause von 47 auf 19 Sekunden geschrumpft. "Huch, dat läuft ja schon wieder!" (vorfreudeimkreisdurchszimmerhüpfend)

Soweit erst mal gut. Geht aber vielleicht noch besser, siehe unten.

Zur Reihenfolge:
Ich habe Mühe, Deinen Ausführungen zu folgen. Sie sind lehrreich, aber tragen dennoch nichts zur Erhellung bei, warum die HM-IOs auf so extrem unterschiedliche Weise unabhängig von ihrer Definition initialisiert werden.
Einzige Idee: HMLAN wird vom Modul CUL_HM verwaltet, HMWLAN/HMUART von HMUARTLGW. ?

Was mir hier gerade aufstößt ist:
- da ich den HMLAN aktuell nicht brauche, habe ich ihn auf "dummy" gesetzt. Trotzdem werden 3s verschwendet ihn zu erreichen. Warum?
- HMUART und HMWLAN werden also erst nach initdone aktiviert. Welchen Grund gibt es dafür?

Code Auswählen

2020.06.23 12:00:09 1: Including fhem.cfg
...
2020.06.23 12:00:13 3: additional HM config file loaded: ./FHEM/HMConfig_AskSinPPCustom.pm
2020.06.23 12:00:13 3: additional HM config file loaded: ./FHEM/HMConfig_HM_LC_Sw1PBU_FM_CustomFW.pm
2020.06.23 12:00:13 3: additional HM config file loaded: ./FHEM/HMConfig_SenTHPL.pm
...
2020.06.23 12:00:35 3: Opening HMLAN1 device 192.168.178.109:1000
2020.06.23 12:00:38 1: HMLAN1: Can't connect to 192.168.178.109:1000: Connection timed out
2020.06.23 12:00:39 3: [Freezemon] freezemon: Long running Command detected define HMLAN1 HMLAN 192.168.178.109:1000:N/A - 3.183384 seconds
2020.06.23 12:00:39 1: HMLAN_Parse: HMLAN1 new condition dummy
...
2020.06.23 12:00:40 1: Including ./log/fhem.save
...
2020.06.23 12:01:22 3: Opening HMUART device /dev/ttyAMA0
2020.06.23 12:01:22 3: Setting HMUART serial parameters to 115200,8,N,1
2020.06.23 12:01:22 3: HMUART device opened
2020.06.23 12:01:22 3: Opening HMWLAN1 device 192.168.178.154:23
...
2020.06.23 12:01:24 0: Server started with 1075 defined entities (fhem.pl:22200/2020-06-19 perl:5.024001 os:linux user:fhem pid:32242)
...
2020.06.23 12:01:27 3: HMWLAN1 device opened

Dann weiterhin:

die von mir erwähnten HMUARTLGW-Inits laufen aktuell (noch?) zweimal ab:

einmal direkt nach dem letzten Actiondetector-Eintrag, aber noch vor der Initialisierung von HMUART und HMWLAN1 (über insgesamt 13s hier),

Code Auswählen

2020.06.23 12:19:34 5: HMUARTLGW HMUART HMUARTLGW_Write: init:4D18E3
...
2020.06.23 12:20:44 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2E13E5
...
2020.06.23 12:20:45 5: HMUARTLGW HMUART HMUARTLGW_Write: init:361500
2020.06.23 12:20:46 5: HMUARTLGW HMUART HMUARTLGW_Write: init:4D18E3 # ein zweites Mal, siehe erste Zeile!
...
2020.06.23 12:20:57 5: HMUARTLGW HMUART HMUARTLGW_Write: init:24BC41
2020.06.23 12:20:57 5: HMUARTLGW HMUART HMUARTLGW_Write: init:420C15

insgesamt 105 (104+1 doppeltes) Write. Immerhin wie gesagt jetzt schon in hier 13 statt 47s

dann erst wird HMUART geöffnet:

Code Auswählen

2020.06.23 12:20:59 3: Opening HMUART device /dev/ttyAMA0
2020.06.23 12:20:59 3: Setting HMUART serial parameters to 115200,8,N,1
2020.06.23 12:20:59 3: HMUART device opened

dann HMWLAN1:

Code Auswählen

2020.06.23 12:20:59 3: Opening HMWLAN1 device 192.168.178.154:23
...

nun folgen die Inits allesamt noch einmal!?!? (ich habe beide Blocks mit einem Editor verglichen, exakt gleiche Reihenfolge, nur andere Zeiten)

Code Auswählen

2020.06.23 12:21:02 5: HMUARTLGW HMUART HMUARTLGW_Write: init:2E13E5
...
2020.06.23 12:21:02 5: HMUARTLGW HMUART HMUARTLGW_Write: init:24BC41
2020.06.23 12:21:02 5: HMUARTLGW HMUART HMUARTLGW_Write: init:420C15

insgesamt 104 - in nur einer Sekunde.

Erst danach kommen die Rückmeldung des geöffneten HMWLAN1 - und ein StartInit auf beide Geräte.

Code Auswählen


2020.06.23 12:21:04 3: HMWLAN1 device opened
2020.06.23 12:21:04 4: HMUARTLGW HMUART StartInit
...
2020.06.23 12:21:06 4: HMUARTLGW HMWLAN1 StartInit

Warum das ganze zweimal, warum dauert es beim ersten so lange, warum geht es beim zweiten viel schneller?

martinp876 · 23 Juni 2020, 21:50:28

Hmlan wird nicht von culhm verwaltet, nur genutzt.
Ios kommunizieren über unterschiedleche Wege und unterschiedliche stacks mit fhem ( oder besser umgekehrt). Eine nicht vorhandene cul hatte auf das timeout des ethernet für einige sekunden aktiv gewartet. Lege mich nicht auf die genauen zeiten fest.
Es ist also, insbesondere bei nicht antworten, gerne ein timeout problem der Treiber.
Es hat bei mir zu disconnects des hmian geführt, also habe ich das cul abgeschaltet.

Culhm startet kein einziges io. Es synchronisiert diese auch nicht. Hmlan sollte auch erst nach initdone starten, wäre sinnvoll. Leider hat meine vor 6 Monaten den dienst quittiert.

Zu den hmios: culhm meldet die Adressen der devices beim gewählten io an. Das ist bei einigen typen extrem wichtig.
Mir scheint, dass alle deine Devices bei einem io angemeldet werden.

Beim ersten init wird (unsichtbar) die gesamte config des device kontrolliert. Das natürlich nur einmal nach restart.
Das zuweisen des io geht schnell. Es kommt auch im betrieb vor, einzeln, wenn das io für ein device geändert werden muss.
Das abfabgen des 2. Durchlauf kann ich bei Gelegenheit suchen. Lohnt sich aber kaum.