MISSING ACK bei Übermittlung von Templisten (HM-TC-IT-WM-W-EU)

Begonnen von Wondermusic, 04 August 2021, 14:13:51

Vorheriges Thema - Nächstes Thema

noansi

Hallo Zusammen,

roundtrip delay wird nicht nur von der Qualität und Geschwindigkeit der Anbindung beeinflusst, sondern auch von Aktionen, die durch Timer oder andere über die verschiedenen IO Wege eintreffende Anforderungen oder Daten ausgelöst werden.

Der HMUARTLGW schickt eine credits Anforderung raus, merkt sich die Zeit, setzt seinen Status auf Wartend auf die Antwort und lässt dann die normale FHEM Loop weiter laufen. Bis zum Eintreffen des Ergebnis kann also noch viel anderes dazwischen funken und ggf. mit viel Rechenzeit stören, was keinen Rückschluss auf allein die Verbindungsqualität liefert.

Eintreffende Daten lösen beim setzen zugehöriger Readings in den meisten Fällen Events aus. Sind es viele Readings und wird nichts eingeschränkt, dann dauert es entsprechend, bis sie alle vom System abgearbeitet sind.

Gruß, Ansgar.

frank

hallo richy,

1. notify definieren
das notify sucht in fhem.log nach dem roundtrip muster und setzt im device "VCCU" (deine vccu) ggf entsprechende readings. in deinem fall sollten 2 readings auftauchen => rt_Pi_HmUART und rt_Pi_HmUART_ug.
damit jeder eintrag gelogt wird, müssen diese readings bei jedem update ein event erzeugen => also die event attribute in der vccu kontrollieren.

2. für die readings ein filelog device anlegen, oder in ein bestehendes integrieren.
3. ein svg device erstellen.


notify (raw definition):
defmod n_roundtrip notify n_roundtrip:.*roundtrip.delay.* {\
  my @rt;;\
  @rt = ($1,$2) if($EVENT=~'\s([^\s]+)\sroundtrip\sdelay:\s(.*)$');;\
  fhem("setreading VCCU rt_".$rt[0]." ".$rt[1]);;\
}
attr n_roundtrip disable 0
attr n_roundtrip readLog 1


svg (raw definition):
defmod SVG_FileLog_Technik_IO_4 SVG FileLog_Technik_IO:SVG_FileLog_Technik_IO_4:CURRENT
attr SVG_FileLog_Technik_IO_4 captionPos left
attr SVG_FileLog_Technik_IO_4 endPlotNow 1
attr SVG_FileLog_Technik_IO_4 title "delay: min [$data{min1}] - avg [$data{avg1}] - max [$data{max1}] - last [$data{currval1}] ----- [".localtime()."]"


gplot file:
# Created by FHEM/98_SVG.pm, 2021-08-06 09:10:49
set terminal png transparent size <SIZE> crop
set output '<OUT>.png'
set xdata time
set timefmt "%Y-%m-%d_%H:%M:%S"
set xlabel " "
set title '<TL>'
set ytics nomirror
set y2tics
set grid y2tics
set ylabel ""
set y2label "delay [ms]"
set y2range [0:]

#FileLog_Technik_IO 4:VCCU.rt_hmuart1\x3a::$fld[3]*1000

plot "<IN>" using 1:2 axes x1y2 title 'roundtrip_delay' ls l2 lw 2 with points
FHEM: 6.0(SVN) => Pi3(buster)
IO: CUL433|CUL868|HMLAN|HMUSB2|HMUART
CUL_HM: CC-TC|CC-VD|SEC-SD|SEC-SC|SEC-RHS|Sw1PBU-FM|Sw1-FM|Dim1TPBU-FM|Dim1T-FM|ES-PMSw1-Pl
IT: ITZ500|ITT1500|ITR1500|GRR3500
WebUI [HMdeviceTools.js (hm.js)]: https://forum.fhem.de/index.php/topic,106959.0.html

Wondermusic

Hallo zusammen,

wollte nur kurz Bescheid geben - nicht das es heißt ich würde mich drücken...  ;)
Bin gerade in meinen Urlaubsvorbereitungen und aufgrund der aktuell immer noch anhaltenden Situation habe ich ein wenig mehr Rennerei als manch andere.
Werde also vor meinem Urlaub nicht mehr dazu kommen noch viel zu machen, melde mich aber nach meinen Trip sobald ich kann mit weiteren Ergebnissen zurück.

Vielen Dank schon mal an Euch für die Unterstützung bis hierher - Ihr seid Spitze!!!

Beste Grüße,
Richy
RPi 3B+ FHEM-Server mit HM-MOD-RPI-PCB
RPi2 mit HM-MOD-RPI-PCB
HM-CFG-LAN
RPi 4 mit ioBroker
>100 HM Sensoren & Aktoren, div. ESP8266 via mqtt, ems-esp

martinp876

Ich schrebe noch einmal quer rein hier: Das Timing sehe ich als Kathastrophe - weiss allerding nicht, was der Grund ist.
Das Schreiben von Registern kann man register für register machen - geht auch garnicht ander. Allerdings sind es min 3 Kommandos - ein Timing ist also unabdingbar. Min die 3 müssen passen - plus ein Burst Aktivaltor beim IT.

06:17:02.459 HMUARTLGW Pi_HmUART send: 01 02 00 00 01                           msg: 01 B001 2BAD4A 3C7084 00050000000009
=> der sender ist Pi_HmUART
06:17:02.854 HMUARTLGW Pi_HmUART_ug recv: 01 05 00 00 4C                        msg: 01 B001 2BAD4A 3C7084 00050000000009
06:17:02.859 HMLAN_Parse: HMLAN01 R:E2BAD4A   stat:0000 t:0058B6C6 d:FF r:FFBB     m:01 B001 2BAD4A 3C7084 00050000000009
=> die beiden anderen IOs haben das Senden gesehen - irrelevant. Allerdings wird das erste erst nach 400ms gesehen. Vermutlich hat es 400ms gedauert bis das Kommando final aus dem Pi_HmUART in die Luft ging

06:17:02.974 HMUARTLGW Pi_HmUART_ug recv: 01 05 00 00 4F                        msg: 01 8002 3C7084 2BAD4A 00
=> erster Empfang. 150ms nach dem vermuteten Senden - würden gut passen
06:17:03.354 HMUARTLGW Pi_HmUART recv: 01 04 03 00 46                           msg: 01 8002 3C7084 2BAD4A 00
06:17:03.357 HMLAN_Parse: HMLAN01 R:E3C7084   stat:0000 t:0058B741 d:FF r:FFCD     m:01 8002 3C7084 2BAD4A 00
=> beiden anderen IOs sind 400ms später. Unerklärlich. Definitiv hat das Device einmal gesendet. Ich vermute, dass hier FHEM die Zeit verbummelt hat - nur wo?

06:17:03.449 HMUARTLGW Pi_HmUART send: 01 02 00 00 00                           msg: 02 A001 2BAD4A 3C7084 0008483049844A35
=> Pi_HmUART sendet wir angefordert. Allerdings sollt das um 06:17:03.100 passieren. +- . Das Timing stimmt nicht. Das ist klar ein Problem von FHEM
06:17:03.486 HMUARTLGW Pi_HmUART_ug recv: 01 05 00 00 4D                        msg: 02 A001 2BAD4A 3C7084 0008483049844A35
06:17:03.493 HMLAN_Parse: HMLAN01 R:E2BAD4A   stat:0000 t:0058B940 d:FF r:FFBB     m:02 A001 2BAD4A 3C7084 0008483049844A35
06:17:03.804 HMUARTLGW Pi_HmUART_ug recv: 01 05 00 00 4C                        msg: 02 A001 2BAD4A 3C7084 0008483049844A35
06:17:03.809 HMLAN_Parse: HMLAN01 R:E2BAD4A   stat:0000 t:0058BA7D d:FF r:FFBB     m:02 A001 2BAD4A 3C7084 0008483049844A35
06:17:04.105 HMUARTLGW Pi_HmUART_ug recv: 01 05 00 00 4C                        msg: 02 A001 2BAD4A 3C7084 0008483049844A35
06:17:04.112 HMLAN_Parse: HMLAN01 R:E2BAD4A   stat:0000 t:0058BBAA d:FF r:FFBA     m:02 A001 2BAD4A 3C7084 0008483049844A35
=> die beiden IO-Freunde sehen die Message. 3-mal. Weil ein Homematic IO immer 3-mal wiederholt wenn ein ACK gefordert ist aber nicht kommt. Schön zu sehen die Wiederholzeit von 250-300ms.  Klar, dass keine Antwort des Device mehr kommt, da das Senden um 06:17:03.449 etwa 300ms zu spät ist. Das Device hat sich schon lange wieder schlafen gelegt.


Was also ist zu tun, um es stabil zu bekommen
1) alle IOs hängen am LAN. Hier könnten Delays auftreten. Sah am Anfang so aus, allerdings sind die späteren Meldungen absolut im gültigen Bereich.  => Im Auge behalten, nicht prio1
2) wir sehen major delay beim Senden sowie beim Empfangen. Es könnte also etwas mit den Processing der messages oder abhängiger Aktionen zu tun haben.
2a) Direkte Abhängigkeiten in FHEM sehe ich als unwahrscheinlich - zumindest für die gesamt-länge der Verzögerung
2b) indirekte Aktionen in FHEM werden erzeugt durch das Setzen von Readings (Primär) und deren angeschlossenen Aktionen. Das können viele sein: Update von Web-interfaces, notifies,..... Hierzu "Echtzeit" weiter untern
2c) die Performance der Platform. Ich nutze aktuelle eine PI3. Die Fritzbox vorher oder der PI2 - oder auch meine NAS sind nicht so performant.

Für 2b) spricht, dass immer die erste Message einen Delay erzeugt. Senden wie empfangen. 2a) ist auch nicht komplett raus.

Wir kommen hierbei also zu einem Grundlegenden Problem von FHEM: Es gibt keinen Echtzeit-kernel.
a) Die meisten Aktionen und Funktionen in FHEM sind "user-Echtzeit". Es soll halt so schnell gehen wir möglich. Ich will nach Sekunden einenUpdate - automatisch
b) Maschinen-Echtzeit (erwarte ich...) wird nur von wenigen Module wirklich gefordert. Homematik selbst braucht es -aber auch nur manchmal. Alle "Ein-Message-Kommandos" brauchen keine Maschienen-Echtzeit. Manchmal nice-to-have um Performance zu sparen,... aber.... Allerdings ist das Schreiben und lesen von Configuration (Register) auf Echtzeit angewiesen. Auch das Keep-Alive eines IO.

Als Konsequenz bedeutet es, dass durch notifies und Frontends die Maschinen-Echtzeit gestört werden kann. Das ist eigentlich "echt miess" da die Zusammenhänge komplex und kaum stabilisierbar sind.

Es zu Lösen wäre eine (unmögliche) restrukturierung von FHEM. Rudi müsste eine Prozess-priorisierung einführen, alle müssten sich daran halten. Puh. 
Zweite Lösung (schöner) ist ein 2. OS-Prozess. Also ein gespawnter Job auf OS Level. Das ist eigentlich der Königs-Weg - aber bedarf einer guten Architektur. Es wiederspricht den FHEM Ansatz von "all-flat" und "almost-no-Architecture" und "no-Dokumentation-of-IPC/No-Interface-Docu written".

Zusammenfassend: Das Problem finde ich interessant und würde es gerne untersuchen. Mal sehen, wann ich Zeit finde. Die Lösung wird nicht Trivial. Die Lösung ist aber eigentlich Elementar und notwendig- Die notwendigkeit könnte CUL_HM-eigen sein da bei HMCCU das Timing von der CCU gemacht wird - und damit ist der Prozess auf einen anderen Prozessor ausgelagert. Homematic hat sicher einen wirklichen "Maschienen-Echtzeit-Prozess" in jeder der CCUs am Laufen


Was braucht man zum Debuggen. Mal sehen. Man müsste sehen, wer alles getriggert wird zwischen 2 Ereignissen, also vom Send bis Ack, vom Ack bis zum next-send

Viel Grundlagen....

noansi

#19
Hallo Martin,

ZitatEs zu Lösen wäre eine (unmögliche) restrukturierung von FHEM. Rudi müsste eine Prozess-priorisierung einführen, alle müssten sich daran halten. Puh.
Ich praktiziere schon lange (möglichst) eine 1 Event pro device Struktur, meistens ist der der Status, der schon die interessanten Infos enthält.
Es interessiert eigentlich nur die Änderung und der Empfänger kann sich dann über ReadingsVal abholen, was ihn interessiert. Das spart schon mal eine Menge Event Last.

Außerdem in Code Readings Aktualisierung via Timer. Erst das spannende main Reading und dann die anderen nochmal verzögert.
Das lässt mehr Luft für andere dazwischen zu Funken.

Gruß, Ansgar.

martinp876

Hallo Ansgar,

das kann man machen - und hört sich sinnvoll an.
FHEM ist aber nicht nur für Bastler. Mein Anspruch wäre, ein sicheres, kein lustiges System zu bauen.
In deinem Ansatz kannst du die Gesamt-performance reduzieren - und die nicht unerheblichen Suchaktionen durch Strukturen reduzieren. Sicher erheblich. Damit tritt ein entsprechendes Problem (deutlich) seltener auf. Abhängig von den Anwendungen kann es allerdings immer noch zu Latenzen kommen.
Man kann es nur mit "priority" Processing (schwache Implemntierung) oder mit einem parallelen OS-Prozess lösen.
Der Parallele Prozess sollte natürlich nicht frisch gespawnt werden - das haben schon andere unterschätzt.
=> man kann es mit aufwand verbessern aber nicht lösen.
=> der Aufwand ist nicht von FHEM unterstützt

Gruß Martin

Wondermusic

Zitat von: frank am 06 August 2021, 09:42:45
hallo richy,

1. notify definieren
das notify sucht in fhem.log nach dem roundtrip muster und setzt im device "VCCU" (deine vccu) ggf entsprechende readings. in deinem fall sollten 2 readings auftauchen => rt_Pi_HmUART und rt_Pi_HmUART_ug.
damit jeder eintrag gelogt wird, müssen diese readings bei jedem update ein event erzeugen => also die event attribute in der vccu kontrollieren.

2. für die readings ein filelog device anlegen, oder in ein bestehendes integrieren.
3. ein svg device erstellen.

Hi frank,

melde mich aus meinem Urlaub zurück..! :)
Ich habe das jetzt gemacht und läuft im Hintergrund.

Ich lass den jetzt erst mal einen Tag im Normalzustand laufen, und morgen stresse ich Ihn dann mal mit Templisten. Ist das so OK?
Hat man einen schönen Vergleich der Zustände.

Gruß,
Richy
RPi 3B+ FHEM-Server mit HM-MOD-RPI-PCB
RPi2 mit HM-MOD-RPI-PCB
HM-CFG-LAN
RPi 4 mit ioBroker
>100 HM Sensoren & Aktoren, div. ESP8266 via mqtt, ems-esp

Wondermusic

Hallo zusammen,

ich habe dann eben mal ein Templisten geändert und siehe da - keine Ahnung warum - von ca. 20 Änderungen hatte ich gerade mal 1 MISSING ACK und 1 ERROR.
Die Graphen hab ich mal mit angehängt. Einmal von gestern Abend und einmal vom Zeitraum der Änderungen von gerade.
RPi 3B+ FHEM-Server mit HM-MOD-RPI-PCB
RPi2 mit HM-MOD-RPI-PCB
HM-CFG-LAN
RPi 4 mit ioBroker
>100 HM Sensoren & Aktoren, div. ESP8266 via mqtt, ems-esp