Modul 00_KNXIO.pm support

[erwin]

Hi Stefan,
ok danke fürs Feedback, ja das bestätigt meine Theorie!
ich hab jetzt 48 Stunden mit meinen fix getestet, sollte funtionieren.

wegen Log msg beim Start:
offensichtlich versucht irgendein notify/doif/at... unmittelbar nach global:initialized event, set od. get cmd's zu machen.
Das KNX-system ist aber noch nicht fertig initialisiert! - siehe die nachfolgende "initial-connect" message.
Falls diese set od. get cmd's im initial_nf sind, kannst du sie in ein notify KNXIO:INITIALIZED verschieben... Dieser event wird genau dafür ausgelöst.
l.g. erwin

[erwin]

Hi KNX_Community!
Neue Version ist am SVN, change-history (wie immer...) im 1.Beitrag in diesem Thread!
Die "frequent IO-write cmd - delayed" Log-msg's kommen jetzt ab LogLvl 4.

@stefan:
Dein problem sollte gefixt sein.
Es gibt jetzt ein Attribut "KNXIOdebug" wenn du das auf 1 setzt, kannst du im Log verfolgen, wie hoch die Anzahl der msg in der queue sind und wann sie abgearbeitet werden.
Mein Stresstest: 4 set und 1 get cmd unmittelbar hintereinander, mit 2 sekunden Wiederholung, ergibt folgendes Log:

Code Auswählen Erweitern

2023.12.21 21:12:02.280 1: myKNXIOTest [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0 # vom vorigen zyklus
2023.12.21 21:12:03.718 1: myKNXIOTest [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0 # 1stes set gesendet
2023.12.21 21:12:03.719 1: myKNXIOTest [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1        # kommt in die queue
2023.12.21 21:12:03.720 1: myKNXIOTest [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 2        # kommt in die queue
2023.12.21 21:12:03.722 1: myKNXIOTest [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 3        # kommt in die queue
2023.12.21 21:12:03.723 1: myKNXIOTest [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 4        # kommt in die queue
2023.12.21 21:12:04.068 1: myKNXIOTest [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 3 # 2tes set gesendet, noch 3 warten
2023.12.21 21:12:04.139 1: myKNXIOTest [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 2 # 3tes set gesendet
2023.12.21 21:12:04.209 1: myKNXIOTest [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 1 # 4tes set gesendet
2023.12.21 21:12:04.280 1: myKNXIOTest [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0 # get gesendet
2023.12.21 21:12:05.718 1: myKNXIOTest [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0 # nächster zyklusWichtig: es muss innerhalb von einigen Sekunden irgendwann ein remain=0 vorkommen. Falls nicht, überlastet du den KNX-Bus und es gehen msg's am Grünen-Kabel verloren ohne dass du es merkst! Das ist dzt. im Modul noch nicht abgefangen! Ich bin nicht sicher, wie ich das realisieren soll, jedenfalls müsste ich msg's aktiv verwerfen!
Ich hab jetzt in etlichen Foren recherchiert, andere Implementationen blockieren grundsätzlich nach jeder gesendeten msg für 50ms - so wollen wir das nicht, das würde FHEM blockieren.

l.g. erwin

[StefanG]

Hi Erwin,

super, danke! Schaut mal gut aus nach ein paar Minuten. Immer zur vollen Minute gibt es etwas mehr Traffic, aber das ist so gewollt und "remain=0" folgt. Langzeittest folgt noch.

Ist das Limit der Messages noch auf 10/Sekunde? Wenn ja, wäre da noch Reserve bis zu 40/Sekunde, sofern das IP-Interface das kann, oder? Das MDT-Interface dürfte da recht tolerant sein bzgl. der Geschwindigkeit.

Code Auswählen Erweitern

2023.12.21 22:03:56.511 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:03:56.512 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:03:56.652 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:03:58.519 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:03:58.523 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:03:58.660 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:00.006 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:00.017 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:00.017 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 2
2023.12.21 22:04:00.018 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 3
2023.12.21 22:04:00.018 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 4
2023.12.21 22:04:00.357 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 3
2023.12.21 22:04:00.428 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 2
2023.12.21 22:04:00.499 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 1
2023.12.21 22:04:00.570 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:02.023 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:02.025 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:02.164 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:04.742 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:04.745 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:04.883 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:07.844 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:07.846 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:07.985 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:09.853 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:09.857 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:09.993 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:11.863 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:11.866 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:12.003 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:13.873 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:13.875 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:14.013 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:15.882 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:15.886 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:16.023 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:19.011 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:19.013 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:19.152 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:21.019 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:21.022 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:21.159 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:23.028 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:23.030 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:23.168 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:25.036 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:25.039 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:25.177 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:27.045 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:27.047 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:27.186 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:30.182 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:30.184 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:30.322 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:32.191 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:32.194 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:32.331 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:34.201 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:34.203 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:34.342 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:36.208 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:36.211 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:36.349 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:38.217 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:38.220 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:38.358 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:41.344 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:41.347 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:41.485 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:43.354 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:43.358 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:43.494 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:45.363 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:45.366 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:45.504 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:47.374 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:47.377 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:47.514 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:49.384 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:49.387 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:49.525 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:52.514 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:52.516 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:52.655 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:54.523 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:54.527 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:54.664 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:56.533 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:56.536 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:56.674 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:58.540 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:04:58.543 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:04:58.681 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:00.435 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:00.441 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:05:00.442 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 2
2023.12.21 22:05:00.442 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 3
2023.12.21 22:05:00.443 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 4
2023.12.21 22:05:00.787 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 3
2023.12.21 22:05:00.857 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 2
2023.12.21 22:05:00.928 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 1
2023.12.21 22:05:00.998 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:02.451 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:02.454 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:05:03.680 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:04.460 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:04.463 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:05:04.745 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:06.470 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:06.473 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:05:06.610 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:08.479 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:08.482 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:05:08.620 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:11.584 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:11.586 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1
2023.12.21 22:05:11.725 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:13.593 1: KNXD [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0
2023.12.21 22:05:13.597 1: KNXD [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 1

Danke jedenfalls nochmals für den tollen Support!

LG
Stefan

[erwin]

Das Limit ist jetzt 14/sekunde, - oder anders formuliert alle 0,07 Sekunden wird eine msg gesendet.
Allerdings kann es ohne Probleme kurzzeitig (etliche Sekunden) überschritten weden, es sollte nur nicht permanent über 14/sek. sein, dann gibts die erwähnten Probleme..
Viel Reserve ist da nicht, 14 msg bedeuten 14 Antworten vom Bus, plus Handshake, und msg die direkt von einem KNX-Geber/Sensor zu einem KNX-Aktor gehen,...
Da IP-Interface wird nicht das Problem sein, der KNX-Bus kann am "Grünen Kabel" 9600 Bps... und nicht mehr. Speziell bei deinen 14Byte langen msg's, da kommen noch zumindest 12 Bytes Overhead/msg dazu...
Der dpt16 sendet IMMER 14 Byte user daten, auch wenn du nur ein einziges Zeichen senden willst!
Dein Log schaut gut aus! Da sollte es keine Probleme geben.
... wieder was gefixt...
l.g. erwin

[GammaTwin]

Super Feature!

Wildcards, ich komme

Ich habe mal "wild" ins System gefragt und über 400 Anfragen kreiert. Wurden sauber abgearbeitet.
Einzige Auffälligkeit. Zwischen der letzten Anfrage 08:07:50 und dem ersten Remain 08:08:19 liegen 29 Sekunden.

Nochmal, mega Feature.

Code Auswählen Erweitern

2023.12.22 08:07:50.813 1: KNX [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 406
2023.12.22 08:07:50.816 1: KNX [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 407
2023.12.22 08:07:50.819 1: KNX [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 408
2023.12.22 08:07:50.823 1: KNX [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 409
2023.12.22 08:07:50.826 1: KNX [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 410
2023.12.22 08:07:50.829 1: KNX [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 411
2023.12.22 08:07:50.832 1: KNX [KNXIO_Write2 628]: DEBUG1>>frequent IO-write - Nr.msg= 412
2023.12.22 08:08:19.682 1: KNX [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 411
2023.12.22 08:08:19.752 1: KNX [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 410
2023.12.22 08:08:19.823 1: KNX [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 409
2023.12.22 08:08:19.893 1: KNX [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 408
2023.12.22 08:08:19.963 1: KNX [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 407
...
2023.12.22 08:09:29.081 1: KNX [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 2
2023.12.22 08:09:29.151 1: KNX [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 1
2023.12.22 08:09:29.222 1: KNX [KNXIO_Write2 651]: DEBUG1>>IO-write processed- Nr.msg remain= 0

[erwin]

Einzige Auffälligkeit. Zwischen der letzten Anfrage 08:07:50 und dem ersten Remain 08:08:19 liegen 29 Sekunden.

Ja, stimmt: 400x0,07 ~ 28 sekunden...
sehr guter Stress-Test!

PS: jetzt deinen Log nochmal angeschaut: das erste remain nach 29 sek, das ist nicht ok, muss ich nochmal nachbessern!
l.g. erwin

[erwin]

Hi Gammatwin,

kannst du bitte in der 00_KNXIO.pm die Zeile 629

Code Auswählen Erweitern

InternalTimer($nextwrite + $adddelay, \&KNXIO_Write2,$hash);
#ändern in:
InternalTimer($nextwrite + 0.07, \&KNXIO_Write2,$hash);
und deinen Test wiederholen ?
ich weiß nicht mehr, warum ich diesen Unfug eingebaut hab. Vermutlich hab ich etliche Varianten ausprobiert.....
l.g.erwin

[GammaTwin]

Ich habe es mit der alten Variante nochmal nachgestellt und es gab wieder die Pause.

Mit der neuen Zeile, gibt es keine Pause.

[erwin]

ok, danke fürs testen, ich werde noch ein wenig optimieren und testen. Für morgen geht sich eine neue Version nicht mehr aus....
l.g. erwin

[StefanG]

Auch nochmals kurzes Feedback von mir:

* Auch nach drei Tagen ist die Laufschrift am Taster stabil, d.h. ja, der Fix hat funktioniert. Maximale Queue-Size ist üblicherweise 3-4, nach Freezes (z.B. von BOSEST) maximal 16.
* Wenn ich in Zeile 629 und 632 jeweils 0.07 durch 0.01 ersetze, läuft die Schrift nochmals schneller und bei mir ohne erkennbare negative Nebeneffekte.

Ich lasse das jetzt mal so weiterlaufen und beobachte ...

lg
Stefan

[erwin]

Hi Stefan & GammaTwin

danke nochmal fürs Feedback, ich werde das demnächst einchecken.

Wenn ich in Zeile 629 und 632 jeweils 0.07 durch 0.01 ersetze, läuft die Schrift nochmals schneller und ...

Ja, das glaube ich dir, weil vermutlich der KNX-Router auch noch puffert und du das "nur" jede Minute auslöst.
Die Limits sind in der neuen Version so: 14 msg/sekunde (gemittelt), können aber kurzeitig überschritten werden. Falls innerhalb von 30 Sekunden nicht mindestens EINMAL der "remain counter" (=Alle msg wurden gesendet) 0 ist, gibts eine Warning im Log - noch ohne Konsequenz...
Das ist auch etwas abhängig von der Performance des Systems.
Am Benchmark von GammaTwin würde ich schätzen zwischen 400-500 unmittelbar gesendete msgs.
l.g. erwin

[erwin]

Hi KNX community!
neue Version ist am SVN, change-history (wie immer...) im 1.Beitrag in diesem Thread!

siehe auch mein post v. 13:07
Es gibt eine neue Log-msg falls die write-queue nicht komplett abgearbeitet werden kann, innerhalb von 30 Sekunden!

Code Auswählen Erweitern

... number of write cmds exceed limits of KNX-Bus; Falls diese msg kommt, sollte man überlegen warum soviele set/get request passieren....
Dzt. noch ohne Konsequenz, mit dem Risiko das man damit FHEM lahmlegen kann. Konsequenz wäre, die write-queue zu löschen - msg gehen verloren!
l.g. erwin

[GammaTwin]

Am Benchmark von GammaTwin würde ich schätzen zwischen 400-500 unmittelbar gesendete msgs.

Es waren 438 get-Abfragen

[StefanG]

Hi Erwin,

Du hattest mir in einem früheren Post geschrieben, dass man beim FHEM-Start auf "KNXIO:INITIALIZED" warten soll, bevor man Infos auf den KNX-Bus schickt. Ich habe gesehen, dass vorher auch ein "KNXIO:CONNECTED" geschickt wird. Da kann aber noch nichts geschickt werden. Soweit verstanden.

Ich habe jetzt aber die Konstellation, dass beim FHEM-Start der KNX-IP-Router stellenweise noch nicht bereit ist und KNXD mehrmals neu startet, bis die Verbindung steht. Es wird dann beim FHEM-Start kein KNXIO:INITIALIZED geschickt, weil eben der KNXD noch nicht bereit. Sobald der KNX-IP-Router dann nach dem FHEM-Start zur Verfügung steht, KNXD läuft und die Verbindung steht, wird ein KNXIO:CONNECTED geschickt, aber es kommt kein KNXIO:INITIALIZED mehr.

D.h. KNXIO:INITIALIZED ist m.E. wertlos, weil es nur dann geschickt wird, wenn FHEM noch nicht fertig gestartet hat. Wenn KNXIO erst nach dem FHEM-Start connected, dann wird eben kein INITIALIZED mehr geschickt. Ich muss daher stattdessen auf KNXIO:CONNECTED abfragen, was aber dann beim FHEM-Start zu Fehlern im Log führt. Ich kann zu diesem Zeitpunkt m.E. aber nicht wissen, ob ich noch auf ein KNXIO:INITIALIZED warten muss (weil FHEM noch startet) oder nicht (weil FHEM schon läuft und nur KNXIO neu connected hat).

Evtl. habe ich hier etwas falsch verstanden, evtl. kann das auch ein Bug sein. Bitte gerne um Deine Rückmeldung dazu.

Vielen Dank vorab!

LG
Stefan

[erwin]

ok, zur Klärung:
Bei der ersten Verbindung mit einem KNX_Router wird KEIN KNXIO:connected geschickt, stattdessen nach Verzögerung- (wiel da auch noch Handshakes mit dem GW passieren) ein KNXIO:INITIALIZED.
Diese Logik ist dazu da, die FHEM-internen Strukturen nach FHEM-start und das Handshake mit dem Router fertig zu bekommen, bevor Dinge auf den Bus geschickt werden, aber NICHT um Verbindungsprobleme zu lösen.
Wenn wie in deinem Fall vermutet, unmittelbar nach FHEM start der knxd kurz erreichbar ist, aber dann sofort restarted, wird natürlich kein INITIALIZED ausgelöst, - FHEM versucht dann einen weiteren Verbindungsaufbauten und generiert, falls erfolgreich, ohne Verzögerung ein KNXIO:connected !
Du hast leider kein list (ich nehme an es geht um ein notify) geposted, daher kann ich nur raten...
Vorschlag:

Code Auswählen Erweitern

defmod knxio_nf notify <device>:INITIALIZED|<device>:connected {...} - also in deinem Fall beides berücksichtigen.
Details dazu in der cmd.ref!
Die Frage bleibt, warum der knxd mehrmals starten muss... Evtl. kann man ja auch an der startreihenfolge / Abhängigkeiten drehen...
l.g. erwin

Edit: Ich hab eine Idee, wie ich das lösen könnte....
Dazu brauche ich ein Log vom FHEM start - ab '<KNXIO-dev> opening mode=...' bis ca. 1 Minute nach 'FHEM global:INITIALIZED occured'