CUNO timing varinazen

[martinp876]

Hi,

die CUNO2 hat nach vorliegenden Daten eine recht hohe timing Varianz. Da ich keine Besitze kann ich es nicht selbst prüfen.
Was der Grund ist (ethernet oder CUNO2 FW) kann ich nicht sagen.
Der Fehler tritt im HM mode auf.
HM lebt von einem genauen uns stabilen Timing - CUNO2 besitzer konnen aktuell wohl kein HM betreiben (jedenfalls kenne ich keinen)

Die Frage ist also
- wie gross ist der delay und die Varianz beim senden von iowrite bis es in der Luft ist?
- wie gross ist der delay und die Varianz beim Empfangen von der Luft bis zum Read?

Zum messen brauch man am sicher ein weiteres Device, das monitoren kann.

Eine CUL macht keine Probleme - das timing ist also eingermassen verlässlich.
Ein HMLAN liefert präzise Zeitstempel aus der Box - wäre auch eine Option zum Messen

Da ich keine CUNO habe (und aktuell auch keine brauche, somit keine kaufe) kann ich bei den Messungen leider nicht helfen. Aber ihr habt sicher das Equipment

Gruss Martin

[rudolfkoenig]

Aber ihr habt sicher das Equipment

Bin gespannt, wer sich angesprochen fuehlt.

[martinp876]

ist keiner für CUNO assigned? Schade. Wer hat es den gebaut? Ich kann leider nicht....

[rudolfkoenig]

Sei vorsichtig. "kann" ist evtl. das falsche Wort

[martinp876]

ist aber so. hätte ich eine CUNO wäre es erledigt - also zumindest das messen. Ist ja nicht wirklich schwer... ok, ein paar Messungen zur Kalibrierung, dann die Wert erfassen.
Da ich aber aktuell keine CUNO brauche kaufe ich auch keine - klar. Und ohne CUNO ist es echt problematisch.    

[rudolfkoenig]

Hallo Martin,

wenn deine Post-Adresse im letzten Jahr sich nicht geaendert hat, dann hast du demnaechst keine Ausrede mehr: busware schickt dir ein Geraet zu.

Gruss,
  Rudi

[martinp876]

danke - muss ich eben neue Ausreden suchen

[holzwurm83]

Hallo Martin,

konntest du schon test machen?

[martinp876]

sind in vorbereitung...

[martinp876]

Hi,

wen's interessiert, hier ein paar Messergebnisse:
Im Test
FB 7390, CUNO, CUL, HMLAN.
Gemessen wurde aktuell nur die Empfangsrichtung. Die Ethernet-packete sowie Zeitstempel mit FHEM wurden erfasst.
Die Zeitstempel der Ethernet Pakete scheinen verlässlich.

a) Delay zwischen Ethernet Paket und FHEM praser ist zwischen 2 und 135ms im Test
b) delay CUNO Ethernet bis Parser ist oft kürzer.
  Grund ist, dass die CUL als erste empfängt, die Pakete dispatched und verarbeitet werden. Das verzögert die Bearbeitung des IO Devices. CUNO hingegen ist durch die eigene Verzögerung so langsam, dass hier alles erledigt ist. Die Pakete werden sofort bearbeitet. HMLAN Pakete hätte die gleiche Geschwindigkeit
c) Messages der CUNO haben bereits am Ethernet einen Delay in der Größenordnung von 95 bis 245ms.
=> sowohl absoluter delay (min 100ms) als auch Varianz (-0 +150ms) sind nicht für präzises Timing nutzbar
d) HMLAN sendet einen Zeitstempel, der ein Rückrechnen zur Empfangszeit in der Luft erlaubt und einen Ausgleich aller folgenden Delays ermöglicht (Ethernet/FHEM/system). Das ermöglicht zumindest das zeitgerechte Senden der Massage von FHEM. Delays der Sendepakete durch Ethernet können nicht ausgeglichen werden (vielleicht doch?)

Eine CUNO ist daher aktuell nicht für timings nutzbar, die Reaktionszeiten kleiner 250ms benötigen. Unter Berücksichtigung vorhandener  Processing Zeiten in FHEM sollte man noch einmal 70ms addieren.
==> eine CUNO ist für HM aktuell nicht  präzise genug.

HM benötigt Reaktionen in max 100ms. Varianzen von 50ms können evtl tragbar sein (Annahme)
die Korrektur der Zeiten bei HMLAN scheint gut zu funktionieren.
CUL ist im Gegensatz zu CUNO weit schneller und präziser.

Legende
iocu1: CUL
iocn1: CUNO
iohl1: hmlan

Gruss Martin

Code Auswählen Erweitern


[font=courier]dly1: ethernet -> parser
dly2: air -> parser
FHEM time                                                                          Ethernet time    dly1  dly2
16:20:49.312  CUL_Parse:   iocu1           A 0B 2E A240 212291 1743BF 020B                         
16:20:49.433  HMLAN_Parse: iohl1 t:0A1A843E   m:2E A240 212291 1743BF 020B        .16:20:49.317535  116   
16:20:49.512  CUL_Parse:   iocn1           A 0B 2E A240 212291 1743BF 020B        .16:20:49.510040  2     195
16:20:49.562  CUL_Parse:   iocu1           A 0B 2F A240 212291 1743BF 020B                               
16:20:49.638  HMLAN_Parse: iohl1 t:0A1A8538   m:2F A240 212291 1743BF 020B        .16:20:49.567533  71   
16:20:49.761  CUL_Parse:   iocn1           A 0B 2F A240 212291 1743BF 020B        .16:20:49.758462  3     194
16:20:49.813  CUL_Parse:   iocu1           A 0B 30 A240 212291 1743BF 020B                               
16:20:49.884  HMLAN_Parse: iohl1 t:0A1A8633   m:30 A240 212291 1743BF 020B        .16:20:49.818489  66   
16:20:50.008  CUL_Parse:   iocn1           A 0B 30 A240 212291 1743BF 020B        .16:20:50.006772  2     190
16:20:51.786  HMLAN_Parse: iohl1 t:0A1A8D96   m:88 A258 172A85 150B94 000C        .16:20:51.709189  77   
16:20:51.807  CUL_Parse:   iocn1           A 0B 88 A258 172A85 150B94 000C        .16:20:51.744691  63    98
16:20:51.833  CUL_Parse:   iocu1           A 0E 88 8202 150B94 172A85 01010A0020                         
16:20:51.916  HMLAN_Parse: iohl1 t:0A1A8E17   m:88 8202 150B94 172A85 01010A0020  .16:20:51.838326  78   
16:20:51.996  CUL_Parse:   iocn1           A 0E 88 8202 150B94 172A85 01010A0020  .16:20:51.993130  3     158
16:20:54.233  CUL_Parse:   iocu1           A 0B 31 A240 212291 1743BF 0100                               
16:20:54.360  HMLAN_Parse: iohl1 t:0A1A9778   m:31 A240 212291 1743BF 0100        .16:20:54.238893  122   
16:20:54.482  CUL_Parse:   iocn1           A 0B 31 A240 212291 1743BF 0100        .16:20:54.475829  7     244
16:20:54.503  HMLAN_Parse: iohl1 t:0A1A9873   m:32 A240 212291 1743BF 0100        .16:20:54.489844  14   
16:20:54.625  CUL_Parse:   iocu1           A 0B 32 A240 212291 1743BF 0100                               
16:20:54.733  CUL_Parse:   iocn1           A 0B 32 A240 212291 1743BF 0100        .16:20:54.724219  9     244
16:20:54.751  HMLAN_Parse: iohl1 t:0A1A996E   m:33 A240 212291 1743BF 0100        .16:20:54.740779  11   
16:20:54.819  CUL_Parse:   iocu1           A 0B 33 A240 212291 1743BF 0100                               
16:20:54.985  CUL_Parse:   iocn1           A 0B 33 A240 212291 1743BF 0100        .16:20:54.972391  13    245
16:20:59.841  CUL_Parse:   iocu1           A 0B 34 A240 212291 1743BF 0300                               
16:20:59.981  HMLAN_Parse: iohl1 t:0A1AAD60   m:34 A240 212291 1743BF 0300        .16:20:59.846196  135   
16:20:59.984  HMLAN_corret      dly:144                                       calc 16:20:59.840           
16:21:00.008  CUL_Parse:   iocn1           A 0B 34 A240 212291 1743BF 0300        .16:20:59.938249  70    162
16:21:00.092  CUL_Parse:   iocu1           A 0B 35 A240 212291 1743BF 0300                               
16:21:00.170  HMLAN_Parse: iohl1 t:0A1AAE5B   m:35 A240 212291 1743BF 0300        .16:21:00.097131  73   
16:21:00.173  HMLAN_corret      dly:82                                        calc 16:21:00.091           
16:21:00.210  CUL_Parse:   iocn1           A 0B 35 A240 212291 1743BF 0300        .16:21:00.186520  24    113
16:21:00.342  CUL_Parse:   iocu1           A 0B 36 A240 212291 1743BF 0300                               
16:21:00.415  HMLAN_Parse: iohl1 t:0A1AAF56   m:36 A240 212291 1743BF 0300        .16:21:00.348101  67   
16:21:00.418  HMLAN_corret       dly:75                                       calc 16:21:00.342           
16:21:00.443  CUL_Parse:   iocn1           A 0B 36 A240 212291 1743BF 0300        .16:21:00.434859  9     95[/font]


[rene]

Ich mag mich zur Bekräftigung hier kurz anschließen. Es hat mir letzte Nacht den Schlaf geraubt, dass die Thermostate (HM-CC-RT-DN) sich partout nicht steuern lassen wollten, trotz korrektem Ack und empfangener Readings. Dank der Tipps hier, hab ich dann heute den CUNO2 via USB betrieben (was suboptimal ist, weil ich die IR_RX eigentlich an einer anderen Stelle benötige) und damit läuft es auch bei mir. Aber zum eigentlichen Threadinhalt. Hier meine Timings aus dem Log (device CUNO via USB, device CNET via Ethernet - selbes Gerät jeweils)

Code Auswählen Erweitern


2014.01.02 21:24:55.367 5: CUNO dispatch A0FB9861022262B0000000A245F100058::-46:CUNO
2014.01.02 21:24:55.445 5: CNET dispatch A0FB9861022262B0000000A245F100058::-46:CNET

2014.01.02 21:25:01.988 5: CUNO dispatch A0F1C86102322A20000000A24770F0066::-47:CUNO
2014.01.02 21:25:02.162 5: CNET dispatch A0F1C86102322A20000000A24770F0066::-47:CNET

2014.01.02 21:25:02.269 5: CUNO dispatch A0A0280022322A2F1123400::-47:CUNO
2014.01.02 21:25:02.422 5: CNET dispatch A0A0280022322A2F1123400::-47:CNET

2014.01.02 21:25:02.577 5: CUNO dispatch A1A03A0102322A2F11234020100020109010AF10B120C340E0A0F00::-47:CUNO
2014.01.02 21:25:02.660 5: CNET dispatch A1A03A0102322A2F11234020100020109010AF10B120C340E0A0F00::-47:CNET

2014.01.02 21:25:02.833 5: CUNO dispatch A180480102322A2F1123402110012151600180019001A000000::-47:CUNO
2014.01.02 21:25:02.909 5: CNET dispatch A180480102322A2F1123402110012151600180019001A000000::-47:CNET

2014.01.02 21:25:03.126 5: CUNO dispatch A0E0480102322A2F112340100000000::-47:CUNO
2014.01.02 21:25:03.157 5: CNET dispatch A0E0480102322A2F112340100000000::-47:CNET

2014.01.02 21:25:03.417 5: CUNO dispatch A0E0580102322A2F112340208000000::-47:CUNO
2014.01.02 21:25:03.655 5: CNET dispatch A0E0580102322A2F112340208000000::-47:CNET

2014.01.02 21:25:03.709 5: CUNO dispatch A0E0680102322A2F112340208000000::-47:CUNO
2014.01.02 21:25:03.904 5: CNET dispatch A0E0680102322A2F112340208000000::-47:CNET

2014.01.02 21:25:04.016 5: CUNO dispatch A1A07A0102322A2F1123403012A22093D18030016073000640F0500::-47:CUNO
2014.01.02 21:25:04.162 5: CNET dispatch A1A07A0102322A2F1123403012A22093D18030016073000640F0500::-47:CNET

2014.01.02 21:25:04.274 5: CUNO dispatch A1A08A0102322A2F1123403100000098E4448550845204520452045::-47:CUNO
2014.01.02 21:25:04.420 5: CNET dispatch A1A08A0102322A2F1123403100000098E4448550845204520452045::-47:CNET

2014.01.02 21:25:04.532 5: CUNO dispatch A1A09A0102322A2F11234031F204520452045204520452045204520::-47:CUNO
2014.01.02 21:25:04.677 5: CNET dispatch A1A09A0102322A2F11234031F204520452045204520452045204520::-47:CNET

2014.01.02 21:25:04.790 5: CUNO dispatch A1A0AA0102322A2F11234032E444855084520452045204520452045::-47:CUNO
2014.01.02 21:25:04.908 5: CNET dispatch A1A0AA0102322A2F11234032E444855084520452045204520452045::-47:CNET

2014.01.02 21:25:05.048 5: CUNO dispatch A1A0BA0102322A2F11234033D20452045204520452045204448546C::-47:CUNO
2014.01.02 21:25:05.148 5: CNET dispatch A1A0BA0102322A2F11234033D20452045204520452045204448546C::-47:CNET

2014.01.02 21:25:05.308 5: CUNO dispatch A1A0CA0102322A2F11234034C44CC55084520452045204520452045::-47:CUNO
2014.01.02 21:25:05.396 5: CNET dispatch A1A0CA0102322A2F11234034C44CC55084520452045204520452045::-47:CNET

2014.01.02 21:25:05.565 5: CUNO dispatch A1A0DA0102322A2F11234035B204520452045204448546C44CC5508::-47:CUNO
2014.01.02 21:25:05.645 5: CNET dispatch A1A0DA0102322A2F11234035B204520452045204448546C44CC5508::-47:CNET

2014.01.02 21:25:05.824 5: CUNO dispatch A1A0EA0102322A2F11234036A452045204520452045204520452045::-47:CUNO
2014.01.02 21:25:05.894 5: CNET dispatch A1A0EA0102322A2F11234036A452045204520452045204520452045::-47:CNET

2014.01.02 21:25:06.082 5: CUNO dispatch A1A0FA0102322A2F1123403792045204448546C44CC550845204520::-47:CUNO
2014.01.02 21:25:06.143 5: CNET dispatch A1A0FA0102322A2F1123403792045204448546C44CC550845204520::-47:CNET

2014.01.02 21:25:06.340 5: CUNO dispatch A1A10A0102322A2F112340388452045204520452045204520452044::-47:CUNO
2014.01.02 21:25:06.392 5: CNET dispatch A1A10A0102322A2F112340388452045204520452045204520452044::-47:CNET

2014.01.02 21:25:06.599 5: CUNO dispatch A1A11A0102322A2F11234039748546C44CC55084520452045204520::-47:CUNO
2014.01.02 21:25:06.640 5: CNET dispatch A1A11A0102322A2F11234039748546C44CC55084520452045204520::-47:CNET

2014.01.02 21:25:06.857 5: CUNO dispatch A1A12A0102322A2F1123403A6452045204520452045204448546C44::-47:CUNO
2014.01.02 21:25:06.889 5: CNET dispatch A1A12A0102322A2F1123403A6452045204520452045204448546C44::-47:CNET

2014.01.02 21:25:07.115 5: CUNO dispatch A1A13A0102322A2F1123403B5CC5508452045204520452045204520::-47:CUNO
2014.01.02 21:25:07.138 5: CNET dispatch A1A13A0102322A2F1123403B5CC5508452045204520452045204520::-47:CNET

2014.01.02 21:25:07.370 5: CUNO dispatch A1714A0102322A2F1123403C44520452045200F1E1E0F1E1E::-47:CUNO
2014.01.02 21:25:07.387 5: CNET dispatch A1714A0102322A2F1123403C44520452045200F1E1E0F1E1E::-47:CNET

2014.01.02 21:25:07.609 5: CUNO dispatch A0B1580102322A2F112340300::-47:CUNO
2014.01.02 21:25:07.640 5: CNET dispatch A0B1580102322A2F112340300::-47:CNET


Man sieht also auch hier durchschnittlich über 100ms Latenz auf dem LAN interface. Welches allerdings mit ICMP Laufzeiten von unter 5ms nicht am Netzwerk liegt.

Code Auswählen Erweitern


64 bytes from 192.168.2.102: icmp_seq=1 ttl=64 time=4.48 ms
64 bytes from 192.168.2.102: icmp_seq=2 ttl=64 time=4.55 ms
64 bytes from 192.168.2.102: icmp_seq=3 ttl=64 time=4.54 ms
64 bytes from 192.168.2.102: icmp_seq=4 ttl=64 time=4.55 ms
64 bytes from 192.168.2.102: icmp_seq=5 ttl=64 time=4.51 ms
64 bytes from 192.168.2.102: icmp_seq=6 ttl=64 time=4.41 ms
64 bytes from 192.168.2.102: icmp_seq=7 ttl=64 time=4.47 ms
64 bytes from 192.168.2.102: icmp_seq=8 ttl=64 time=4.60 ms
64 bytes from 192.168.2.102: icmp_seq=9 ttl=64 time=4.46 ms


Ich hab mich jetzt nicht durch den Code gewühlt, ob die Verarbeitung der CUNO messages den Empfang der CNET messages zeitlich beeinflusst. Sollte das der Fall sein, dann sind meine Logs natürlich unbrauchbar, getreu dem Motto "Wer misst, misst Mist".

Gleich nochmal nachgemessen, um nicht zuviel Mist zu messen:

Code Auswählen Erweitern


2014.01.03 09:00:51.502 5: CNET dispatch A1A20A0102224A7F11234036A452045204520452045204520452045::-66.5:CNET
T 2014/01/03 09:00:51.501287 192.168.2.102:2323 -> 192.168.2.106:50996 [AP]  A1A20A0102224A7F11234036A4520452045204520452045204520450F..                                                                           

2014.01.03 09:00:51.752 5: CNET dispatch A1A21A0102224A7F1123403792045204448546C44CC550845204520::-66:CNET
T 2014/01/03 09:00:51.750009 192.168.2.102:2323 -> 192.168.2.106:50996 [AP]  A1A21A0102224A7F1123403792045204448546C44CC55084520452010..                                                                           

2014.01.03 09:00:52.001 5: CNET dispatch A1A22A0102224A7F112340388452045204520452045204520452044::-66:CNET
T 2014/01/03 09:00:51.998840 192.168.2.102:2323 -> 192.168.2.106:50996 [AP]  A1A22A0102224A7F11234038845204520452045204520452045204410..                                                                           

2014.01.03 09:00:52.249 5: CNET dispatch A1A23A0102224A7F11234039748546C44CC55084520452045204520::-66.5:CNET
T 2014/01/03 09:00:52.247572 192.168.2.102:2323 -> 192.168.2.106:50996 [AP]  A1A23A0102224A7F11234039748546C44CC550845204520452045200F..                                                                           

2014.01.03 09:00:52.498 5: CNET dispatch A1A24A0102224A7F1123403A6452045204520452045204448546C44::-66.5:CNET
T 2014/01/03 09:00:52.496338 192.168.2.102:2323 -> 192.168.2.106:50996 [AP]  A1A24A0102224A7F1123403A6452045204520452045204448546C440F..                                                                           

2014.01.03 09:00:52.747 5: CNET dispatch A1A25A0102224A7F1123403B5CC5508452045204520452045204520::-66.5:CNET
T 2014/01/03 09:00:52.745104 192.168.2.102:2323 -> 192.168.2.106:50996 [AP]  A1A25A0102224A7F1123403B5CC55084520452045204520452045200F..                                                                           

2014.01.03 09:00:52.996 5: CNET dispatch A1726A0102224A7F1123403C44520452045200F1E1E0F1E1E::-66.5:CNET
T 2014/01/03 09:00:52.993871 192.168.2.102:2323 -> 192.168.2.106:50996 [AP]  A1726A0102224A7F1123403C44520452045200F1E1E0F1E1E0F..                                                                                 

2014.01.03 09:00:53.244 5: CNET dispatch A0B2780102224A7F112340300::-66:CNET
T 2014/01/03 09:00:53.241967 192.168.2.102:2323 -> 192.168.2.106:50996 [AP]  A0B2780102224A7F11234030010..                                                                                                         

2014.01.03 09:01:06.931 5: CNET dispatch A0FCC861022262B0000000A2457100058::-45.5:CNET
T 2014/01/03 09:01:06.924711 192.168.2.102:2323 -> 192.168.2.106:50996 [AP]  A0FCC861022262B0000000A245710005839..                                                                                                 


Zwischen Empfang auf der Netzwerkschicht und Dispatch liegen ca. 2-3ms. Also kann man die gemessenen Latenzen durchaus als valide betrachten.

Die wenigen Lichtblicke mit bis zu unter 30ms Latenz lassen mich hoffen, dass das Problem auf der Firmware Seite gelöst werden könnte. Vielleicht kann sich da ja Busware (tostmann?) dazu äußern.

[rudolfkoenig]

Vielleicht kann sich da ja Busware (tostmann?) dazu äußern.

Ich meine aber, dass er sich fuer das Firmware nicht zustaendig fuehlt.
Wie ich das schon geschrieben habe, es fehlt an einem CUNO Maintainer.

[rene]

Zuständigkeiten und Gewährleistungen hin und her, hoffe ich einfach darauf, dass tostmann als letzter und häufigster Committer des Codes (Maintainer?) zumindest ohne großen Zeitaufwand einschätzen können sollte, woher das Delay kommt, und ob es sich beheben lässt.

Am Ende baue ich darauf, dass der Anbieter der Hardware ähnlich hohes Engagement in die Maintenance investiert, wie wir Kunden ins Testen. Und solange CUNO2 nicht zum Auslaufmodell wird, dürfte ein Interesse an der Verbesserung der Firmware seitens busware/tostmann durchaus bestehen. Automobilhersteller forschen ja auch an der Verbesserung von Treibstoffen, obwohl sie dafür eigentlich nicht zuständig sind.

Ich schreib ihn aber auch gern als Käufer des CUNO2 nochmal direkt an, sollte das notwendig sein.

PS: was ihr Jungs hier an Zeit für Support und Produktpflege investiert ist beeindruckend und sicher nicht selbstverständlich.

[tostmann]

Der CUNO ist ca. 5 Jahre alt und kein Hochleistungsrechner. Der 8bit ATMEL bekommt es gerade so hin auch das Netzwerk ausreichend schnell zu bedienen. Zeitkritische ACK oä sollte man nicht erst über das Netzwerk schicken sondern, so wie bei MAX!, direkt im CUNO behandeln.
Leider kenn' ich mich NULL mit HM aus, kann daher auch keinen Weg zur Verbesserung aufzeigen. Clever ist in o.g. Zusammenhang besser einen Raspberry mit CUL/COC zu nutzen - das eröffnet weitere zusätzliche Möglichkeiten und krankt bestimmt nicht an Geschwindigkeit.

[rene]

Vielen Dank für die Rückmeldung.

Ich übersetz das mal in "Firmware-seitig eher schwierig zu lösen, ohne komplette Teile der Logik aus FHEM in die Firmware zu verlagern".

Das gibt zumindest schonmal Gewissheit auf schlechte Chancen.

So gesehen wäre es aber glaube ich angebracht, auf der Produktseite einen kleinen Hinweis zu den Nutzungseinschränkungen mit HomeMatic zu hinterlegen. Ich für meinen Teil werde ihn wohl eher dann künftig im USB Mode betreiben, da ich den IR_RX brauche und mir keine andere Komplettlösung bekannt ist. Ausserdem ist das Geld halt nun mal ausgegeben und irgendwie werde ich ihn schon auch mit USB Kabel in Sichtweite zu den IR Komponenten bringen.

Danke nochmal tostmann.

[holzwurm83]

Wie ich das schon geschrieben habe, es fehlt an einem CUNO Maintainer.

Das würde ich sehr gut finden!
Ich als Anfänger tuhe mir da echt schwer. Man weiß immer nicht ob es an einem selbst liegt oder daran das es generell ein Problem damit gibt. Jetzt nach zwei Wochen Hinschmalz muss ich mehr und mehr feststellen, dass die Entscheidung für einen CUNO eher eine Fehlentscheidung war, da HomeMatic und IR mit dem CUNO nicht wirklich sauber bis zum Teil gar nicht funktionieren und es zahlreiche Probleme gibt, die wohl nicht nur Softwareseitig gibt. Nur mit FS20 und CUNO hatte ich bisher keine Schwierigkeiten. Ich habe auch einige Probleme hier im Forum gepostet, aber bei den meisten bin ich wohl der einzige damit?

Versteht mich hier bitte nicht falsch? Die Leistung hier im Forum ist absolut beachtlich vor der ich auch großen Respekt habe!

[rudolfkoenig]

Der 8bit ATMEL bekommt es gerade so hin auch das Netzwerk ausreichend schnell zu bedienen

Ich glaube nicht an dieser Theorie. Wenn mit dem Interrupt-basierten Empfang von SlowRF keine Probleme gibt, dann sollte der Prozessor fuer HomeMatic/BidCos auch ausreichen, zumal in diesem Fall nur fertig empfangene und gepruefte Pakete von etwa 20 Byte laenge vom CC1101 zum enc28j60 kopiert werden muessen. Hoechstens ist letzteres nicht in der Lage, ein Paket innerhalb von 100ms wegzuschicken, was ich als unwahrscheinlich einstufe.

Fuer wahrscheinlicher halte ich, dass culfw auf diesem Hardware fehlerhaft ist, vermutlich beim Bedienen des Netzwerk Chips.

[rene]

Also ich denke, die Theorie von dem zu lahmen Prozessor können wir begraben. Das ist ein firmwareseitiges Problem.

Siehe folgende Timings:

Code Auswählen Erweitern


2014.04.08 10:41:35.694 5: CUNO dispatch A0F1F861022262B0000000A24B50F0058::-50:CUNO
2014.04.08 10:41:35.763 5: CNET dispatch A0F1F861022262B0000000A24B50F0058::-50:CNET
2014.04.08 10:41:53.876 5: CUNO dispatch A0F3D86102224A70000000A24B70F0058::-52.5:CUNO
2014.04.08 10:41:53.922 5: CNET dispatch A0F3D86102224A70000000A24B70F0058::-52.5:CNET
2014.04.08 10:42:15.315 5: CNET dispatch A0FEA86102322A20000000AB0E50E2F5D::-35.5:CNET
2014.04.08 10:42:15.325 5: CUNO dispatch A0FEA86102322A20000000AB0E50E2F5D::-35.5:CUNO
2014.04.08 10:43:40.365 5: CUNO dispatch A0F9A86102224B70000000AB0E30F2F55::-52:CUNO
2014.04.08 10:43:40.386 5: CNET dispatch A0F9A86102224B70000000AB0E30F2F55::-52:CNET
2014.04.08 10:43:58.945 5: CUNO dispatch A0F20861022262B0000000A24B50F0058::-51.5:CUNO
2014.04.08 10:43:59.043 5: CNET dispatch A0F20861022262B0000000A24B50F0058::-51.5:CNET
2014.04.08 10:44:38.825 5: CUNO dispatch A0FEB86102322A20000000AB0E60E2F5D::-35:CUNO
2014.04.08 10:44:38.849 5: CNET dispatch A0FEB86102322A20000000AB0E60E2F5D::-35:CNET


Wie man sieht hat um 2014.04.08 10:42:15.315 das Netzwerk Device den USB sogar überholt. Interessant ist, dass wenn es ihn überholt, stets maximal 12ms Zeit dazwischen liegen.

Code Auswählen Erweitern


2014.04.08 11:07:30.381 5: CNET dispatch A0F4786102224A70000000A24B70F0058::-48:CNET
2014.04.08 11:07:30.391 5: CUNO dispatch A0F4786102224A70000000A24B70F0058::-48:CUNO
...
2014.04.08 11:18:51.712 5: CNET dispatch A0F2E861022262B0000000A24B50F0058::-52:CNET
2014.04.08 11:18:51.722 5: CUNO dispatch A0F2E861022262B0000000A24B50F0058::-52:CUNO
..
2014.04.08 11:29:37.223 5: CNET dispatch A0F32861022262B0000000A24B50F0058::-52:CNET
2014.04.08 11:29:37.233 5: CUNO dispatch A0F32861022262B0000000A24B50F0058::-52:CUNO
...
2014.04.08 11:45:47.107 5: CNET dispatch A0F0386102322A20000000AB0F40E0A5D::-37:CNET
2014.04.08 11:45:47.117 5: CUNO dispatch A0F0386102322A20000000AB0F40E0A5D::-37:CUNO
...
2014.04.08 12:04:48.630 5: CNET dispatch A0FBA86102224B70000000AB0EF0F0D55::-47:CNET
2014.04.08 12:04:48.639 5: CUNO dispatch A0FBA86102224B70000000AB0EF0F0D55::-47:CUNO
...
2014.04.08 12:07:18.876 5: CNET dispatch A0FBB86102224B70000000AB0EF0F0D55::-48.5:CNET
2014.04.08 12:07:18.887 5: CUNO dispatch A0FBB86102224B70000000AB0EF0F0D55::-48.5:CUNO
...
2014.04.08 12:16:28.121 5: CNET dispatch A0F0F86102322A20000000AB0ED0E0E5D::-37:CNET
2014.04.08 12:16:28.127 5: CUNO dispatch A0F0F86102322A20000000AB0ED0E0E5D::-37:CUNO
...
2014.04.08 12:29:41.128 5: CNET dispatch A0FC486102224B70000000AB0EF0F1755::-50:CNET
2014.04.08 12:29:41.140 5: CUNO dispatch A0FC486102224B70000000AB0EF0F1755::-50:CUNO
...
2014.04.08 12:42:28.030 5: CNET dispatch A0F4F861022262B0000000A24B60F0058::-52:CNET
2014.04.08 12:42:28.035 5: CUNO dispatch A0F4F861022262B0000000A24B60F0058::-52:CUNO


Ich vermute also stark, dass das ein reines internes Timing ist. Vielleicht ja wirklich, um den Prozessor zu entlasten. Im Code bin ich bisher nicht fündig geworden, wo er da eine Pause einlegt. Vielleicht können da die Profis hier nochmal unterstützen.

Um Effekte durch IR Modul oder andere Module auszuschließen, hab ich alles deaktiviert, was nicht unbedingt gebraucht wird. Hat nicht geholfen, also sind es keine Seiteneffekte durch unnötigen Balast.

Code Auswählen Erweitern


2014.04.08 13:43:12.325 5: CUNO dispatch A0F67861022262B0000000A24B70F0058::-54:CUNO
2014.04.08 13:43:12.418 5: CNET dispatch A0F67861022262B0000000A24B70F0058::-54:CNET
2014.04.08 13:43:28.653 5: CUNO dispatch A0FE186102224B70000000AB0F50F0C55::-54:CUNO
2014.04.08 13:43:28.836 5: CNET dispatch A0FE186102224B70000000AB0F50F0C55::-54:CNET
2014.04.08 13:44:34.224 5: CUNO dispatch A0F8586102224A70000000A24B90F0058::-49:CUNO
2014.04.08 13:44:34.257 5: CNET dispatch A0F8586102224A70000000A24B90F0058::-49:CNET
2014.04.08 13:44:51.173 5: CNET dispatch A0F3286102322A20000000AB0F60E0A5D::-36:CNET
2014.04.08 13:44:51.180 5: CUNO dispatch A0F3286102322A20000000AB0F60E0A5D::-36:CUNO
2014.04.08 13:45:21.327 5: CUNO dispatch A0F68861022262B0000000A24B70F0058::-53.5:CUNO
2014.04.08 13:45:21.520 5: CNET dispatch A0F68861022262B0000000A24B70F0058::-53.5:CNET
2014.04.08 13:46:12.404 5: CUNO dispatch A0FE286102224B70000000AB0F50F0B55::-59.5:CUNO
2014.04.08 13:46:12.514 5: CNET dispatch A0FE286102224B70000000AB0F50F0B55::-59.5:CNET
2014.04.08 13:47:07.225 5: CUNO dispatch A0F8686102224A70000000A24BA0F0058::-49:CUNO
2014.04.08 13:47:07.240 5: CNET dispatch A0F8686102224A70000000A24BA0F0058::-49:CNET


[rudolfkoenig]

Kannst du bitte diese Zahlen erklaeren?

[rene]

Natürlich.

Ich habe den CUNO2 sowohl via USB (CUNO) als auch via Ethernet (CNET) verbunden und dann beide Devices in FHEM angelegt. Das Log auf Level 5 zeigt dann das Ankommen von CUNO Nachrichten der beiden Devices an. An dem Timestamp sieht man, wieviel Zeit zwischen den beiden Kommunikationswegen verloren geht:

Beispiel:

Code Auswählen Erweitern


2014.04.08 13:46:12.404 5: CUNO dispatch A0FE286102224B70000000AB0F50F0B55::-59.5:CUNO
2014.04.08 13:46:12.514 5: CNET dispatch A0FE286102224B70000000AB0F50F0B55::-59.5:CNET


Hier hat das USB-Device (CUNO) die Nachricht vom Thermostat um 13:46:12.404 erhalten, auf den Ethernet Channel (CNET) kam es aber erst um 13:46:12.514 an, also 110ms verzögert.

In einem älteren Post in diesem Thread hatte ich noch überprüft, inwieweit ggf. FHEM selbst aufgrund der beiden Devices das Empfangen zeitlich verzögert und hatte auf der Netzwerkschnittstelle des Server selbst nochmal die Timings gemessen und dann mit dem FHEM Log verglichen. Dabei kamen zwischen Netzwerkschnittstelle und FHEM nur 2-3ms Verzögerung zustande, also irrelevant.

[rudolfkoenig]

Nach etwas suche im culfw Code:
- Devices/CUNO2/CUNO2.c ruft regelmaessig Ethernet_Task auf
- Ethernet_Task (clib/ethernet.c) prueft mit timer_expired(&periodic_timer) ob sie Daten uebertragen soll
- periodic_timer wird mit CLOCK_SECOND/4 initialisiert (clib/ethernet.c)
- CLOCK_SECOND kommt aus CLOCK_CONF_SECOND und ist 125 (Devices/CUNO2/clock-arch.h)
- der Timer laeuft auf dem CUNO mit 125Hz.

D.h. Ethernet_Task will nur 4-mal die Sekunde die Daten loswerden, je nach Glueck liegt der Delay zwischen Funk-Empfang und Ethernet-Senden zw. 0 und 250ms. Ich vermute diese Pruefung wurde eingebaut, weil sonst der Netzwerk-Chip den Dienst einstellt, ich kann mich aber auch irren. Man koennte versuchen periodic_timer zu verkuerzen z.Bsp. auf CLOCK_SECOND/40, oder es ganz ausbauen.

[rene]

Hi Rudi,

das wollte ich auch schon anführen, aber dann ist mir aufgefallen, dass ethernet_process() was generell aufgerufen wird, auch ein network_send() absetzt, der periodic_timer also nur für irgendwelche Maintenance oder clearing tasks eingerichtet wurde.

Jetzt hab ich aber nochmal genauer hingesehen, und es kommt gar nicht die network.c aus dem enc28j60 Treiber zum Einsatz, sondern der ethersex und der scheint das nicht zu machen.

Ist einen Versuch wert. Ich werde das heute mal patchen und meine Ergebnisse posten.

Dank dir.

VG
René

[rene]

Bingo!

Code Auswählen Erweitern


2014.04.10 15:33:50.361 5: CUNO dispatch A0F05861022262B0000000A248E0F0058::-44.5:CUNO
2014.04.10 15:33:50.407 5: CNET dispatch A0F05861022262B0000000A248E0F0058::-44.5:CNET
2014.04.10 15:34:52.451 5: CNET dispatch A0F2486102224A70000000A24900F0058::-49.5:CNET
2014.04.10 15:34:52.457 5: CUNO dispatch A0F2486102224A70000000A24900F0058::-49.5:CUNO
2014.04.10 15:35:28.750 5: CUNO dispatch A0FCF86102322A20000000AB0ED0E0E5D::-35:CUNO
2014.04.10 15:35:28.768 5: CNET dispatch A0FCF86102322A20000000AB0ED0E0E5D::-35:CNET
2014.04.10 15:36:04.465 5: CUNO dispatch A0F7F86102224B70000000AB0EC0F1755::-54:CUNO
2014.04.10 15:36:04.483 5: CNET dispatch A0F7F86102224B70000000AB0EC0F1755::-54:CNET
2014.04.10 15:36:04.863 5: CUNO dispatch A0F06861022262B0000000A248E0F0058::-45.5:CUNO
2014.04.10 15:36:04.884 5: CNET dispatch A0F06861022262B0000000A248E0F0058::-45.5:CNET
2014.04.10 15:37:16.455 5: CUNO dispatch A0F2586102224A70000000A24900F0058::-50:CUNO
2014.04.10 15:37:16.474 5: CNET dispatch A0F2586102224A70000000A24900F0058::-50:CNET
2014.04.10 15:37:57.743 5: CNET dispatch A0FD086102322A20000000AB0ED0E185D::-35:CNET
2014.04.10 15:37:57.753 5: CUNO dispatch A0FD086102322A20000000AB0ED0E185D::-35:CUNO
2014.04.10 15:38:04.865 5: CUNO dispatch A0F07861022262B0000000A248D0F0058::-45.5:CUNO
2014.04.10 15:38:04.885 5: CNET dispatch A0F07861022262B0000000A248D0F0058::-45.5:CNET
2014.04.10 15:38:53.712 5: CNET dispatch A0F8086102224B70000000AB0EC0F1755::-52.5:CNET
2014.04.10 15:38:53.718 5: CUNO dispatch A0F8086102224B70000000AB0EC0F1755::-52.5:CUNO


Jetzt stöpsel ich mal USB ab und dann schauen wir, ob der CUNO nun auch mit den Thermostaten kann.

[rene]

Also. Seit gestern 16:00 läuft im 3minuten Takt eine Anforderung an ein Thermostat.

Code Auswählen Erweitern


*/3 * * * * /opt/fhem/fhem.pl 7072 'set HK_OFFICE_1 getRegRaw List0'


Bis jetzt gab es nur 2 Resend und die auch nur 1x, sprich beim 2. Versuch lief es dann jeweils durch.

Code Auswählen Erweitern


2014.04.10 20:44:42.582 4: CUL_HM_Resend: HK_OFFICE_1 nr 2
2014.04.11 08:55:58.107 4: CUL_HM_Resend: HK_OFFICE_1 nr 2


Ich denke, das Problem kann als "lösbar" betrachtet werden. Bleibt die Frage, wie sieht die Lösung aus, die auch ins Repo kommt? Ist das Herabsetzen des periodic_timers richtig (testweise 1/40s), oder sollte der ethernet_process() auch um einen network_send() Aufruf ergänzt werden (was 1/125s bedeuten würde)?

[rudolfkoenig]

Ich habe nicht wirklich eine Meinung dazu.
Wie hast Du es aktuell geloest?

[rene]

Entsprechend deines Vorschlags den Periodic_timer auf 1/40s gesetzt.

Patch:

Code Auswählen Erweitern


Index: trunk/culfw/clib/ethernet.c
===================================================================
--- trunk/culfw/clib/ethernet.c (revision 415)
+++ trunk/culfw/clib/ethernet.c (working copy)
@@ -52,7 +52,7 @@
   ntp_conn = 0;

   // setup two periodic timers
-  timer_set(&periodic_timer, CLOCK_SECOND / 4);
+  timer_set(&periodic_timer, CLOCK_SECOND / 40);
   timer_set(&arp_timer, CLOCK_SECOND * 10);

   if(erb(EE_USE_DHCP)) {


Es wäre schon praktisch, wenn dieser (oder ein besserer) Patch in den trunk wandern könnte. Ich war ja mit dem Problem nicht ganz alleine, wenn ich mich recht entsinne. Letztlich habt ihr Martin ja sogar extra einen CUNO2 geschickt, damit der Fehler gefunden wird.

[rudolfkoenig]

Letztlich habt ihr Martin ja sogar extra einen CUNO2 geschickt, damit der Fehler gefunden wird.

Stimmt. Kannst ihn bitten, mit geaenderten Timing zu testen, und seine Meinung dazu zu geben?
Bitte hier ein Link auf dem neuen Thread im HomeMatic Bereich geben, damit ich das mitverfolgen kann.

[rene]

Das hier ist doch Martin's Thread zu genau dem Thema.

Martin? Magst du mal den Patch anwenden und deine Tests mit unterschiedlichen Timings durchführen / das beste Timing herausfinden?

Allerdings glaube ich, dass sich durch die Verwendung des ethersex Codes hier schlicht ein Bug eingeschlichen hat, und im ethernet_process() das network_send() vergessen wurde, weshalb der periodic_timer, der wohl eher für Maintenance Tasks gedacht ist, zum unfreiwilligen Workaround wurde. Sucht man nach [ethernet "periodic_timer"] findet man dutzendweise nahezu identischen Code und überall arbeitet der periodic_timer network_send() zusätzlich zu einem main invocation network_send(). Nun scheint jedoch selbst der ethersex code nicht mehr ansatzweise dem Stand zu entsprechen, der in der culfw eingefügt wurde, weshalb ein Austausch wohl eher nicht mehr infrage kommt. Und da der Treiber nur beim CUNO und CUNO2 zum Einsatz zu kommen scheint, vermute ich mal infam (aufgrund tostmanns' Äußerung zum Alter), dass kaum Interesse besteht, es richtig zu lösen.

Der CUN benutzt noch die network.c aus dem enc28j60 Treiber. Rudi, hast du eine Idee, warum der nicht auch schlicht beim CUNO und CUNO2 zum Einsatz kommt? Bzw. nicht mehr, anfangs war das wohl laut History noch so. Der enc28j60 Treiber würde bei jedem Durchlauf versuchen, ethernet Packete abzusetzen. Ich glaube, ich werde das die Tage mal ausprobieren.

[rudolfkoenig]

Ich vermute Interesse besteht schon, auch wenn man das nicht mit "viel Aufwand reinstecken" gleichsetzen kann.

[rudolfkoenig]

Der CUN benutzt noch die network.c aus dem enc28j60 Treiber. Rudi, hast du eine Idee, warum der nicht auch schlicht beim CUNO und CUNO2 zum Einsatz kommt?

Ich habe culfw auf dem CUN zum Laufen gebracht, ich kann mich noch erinnern, dass ich massive Probleme mit dem Initialisieren der enc28j60 hatte. CUNO/CUNO2 habe ich nie gesehen, zu den Aenderungen kann ich nichts sagen.