CUNO timing varinazen

Begonnen von martinp876, 17 Dezember 2013, 15:18:21

Vorheriges Thema - Nächstes Thema

holzwurm83

Zitat von: rudolfkoenig am 02 Januar 2014, 22:31:47
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!
- Fhem auf einem MacMini Server
- CUL; HMLAN; CUNO2 für FS20; HM-Wired RS485 LAN Gateway
- HMW_Sen_SC_12_FM; HMW_LC_Sw2_DR; HMW_LC_Bl1_DR; HMW_IO_12_Sw7; HMW_IO_12_Sw14_DR; HMW_IO_12_FM; HBW_1W_T10
- HM-TC-IT-WM-W-EU; HM-CC-RT-DN

rudolfkoenig

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


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.


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.


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:

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!


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.


*/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.


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:

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

ZitatLetztlich 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

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