Firmware zu CUL, CUNX und Co. mit Timestamp Option ASKSIN tsculfw V0.43

Begonnen von noansi, 09 Juni 2014, 19:16:01

Vorheriges Thema - Nächstes Thema

noansi

#45
Hallo Rudolf,

in ringbuffer ist mir aufgefallen, dass rb_reset nicht Interrupt fest gemacht wurde, wie die get und put routine.
Edit: nun hängt auch die Datei an.

Die restlichen Änderungen dienen der Speicheroptimierung.

Edit: Anhang gelöscht, da update siehe unten.

Gruß, Ansgar.

PS: Und bitte die Änderungen auf der vorhergenden Seite 3 nicht übersehen.

noansi

#46
Hallo Rudolf,

der nächste Änderungswunsch betrifft LUFA.

Neben Speicheroptimierung habe ich es fest gegen Aufruf im Interrupt gemacht.

Da darin USB_USBTask in CDC_Task jeweils direkt vor dem Zugriff auf den IN bzw. OUT EndPoint aufgerufen wird, kann (sollte) der Aufruf aus der Hauptschleife entfernt werden.

Bei mir läuft es besser.

Haupt Übeltäter bei meinen RasPi - CUL USB Problemen war jedoch plotfork. Seit ich das aus habe, läuft USB sehr stabil (mit Aufbau von Seiten mit vielen Protokoll-Graphen konnte ich zuvor USB-Probleme gut provozieren). Außerdem habe ich an meinen Zehnfach USB Hub 2.0 die beiden CULs und meinen USB-WDE1 jeweils so gesteckt, dass für jedes der USB1.1 Geräte ein eigener Transaction-Translator zur Verfügung steht und damit die USB-Verzögerungen minimiert.

Edit: Anhang gelöscht, da update siehe unten.

Gruß, Ansgar.

PS: auf die seriell und USB Optimierungen lege ich wert, damit nicht ASKSIN TimeStamp Probleme gemeldet/beklagt werden, die eigentlich versteckte Kommunikationsprobleme sind.

rudolfkoenig

ZitatAls erstes ein Änderungswunsch in clock.c

Ich habe die beabsichtigten Aenderungen eingecheckt, den Patch aber nicht direkt uebernommen.

ZitatKonkret in ASKSIN passiert so was...
Dann ist im ASKSIN was schlecht geloest. Eine Umbenennung der Variable waere dafuer aber nicht notwendig, nicht mal die Zaehlrichtung muss man aendern, falls man bereit ist mit busy-loops unter eine Sekunde auszukommen. Nach 2 Sekunden kommt eh der Watchdog.

ZitatBei CUL_V2 würde es wohl (derzeit) zu Speicherproblemen führen.
Deswegen, und wegen den vielen IFDEFs habe ich versucht den Code kleiner zu krieger, was schliesslich mit avr-gcc 4.8.1 in ausreichenden Masse (3.5%) gelang. Das musste ich aber eine Weile selbst testen, bevor ich es auf die Allgemeinheit loslasse. Das ist hiermit passiert, und um es besser verfolgen zu koennen, habe ich die Version auf 1.62 geaendert.

Das Einarbeiten des Patches hat etwas laenger gedauert, weil ich etwa 4 Stunden Zeit dafuer investieren musste.

noansi

#48
Hallo Rudolf,

ZitatIch habe die beabsichtigten Aenderungen eingecheckt, den Patch aber nicht direkt uebernommen.

Danke für die Mühe, die Du Dir damit gemacht hast!

Deine Variante ist auch gut. Der Timerinterruptzeit tut's in jedem Fall gut.
Und etwas mehr mögliche Credits Verluste -> näher an der Norm. ;-)
Mit der Variablenänderung hätte mir der Compiler gesagt, wenn dieser Zähler bereits irgendwo anders genutzt worden wäre.

ZitatDann ist im ASKSIN was schlecht geloest.

Es wird halt auf den freien Kanal gewartet. In ursprünglicher Variante sogar, bis der watchdog zuschlägt. Wenn TimeStamp mal volltändig drin ist, wäre es über das Feedback auch möglich, dass fhem einen diesbezüglichen Misserfolg nach timeout mitbekommt und es nochmal versuchen kann.
Im CUL wäre es mit großem Aufwand denkbar, mit einer Statemaschine zu arbeiten, um länger warten zu können. Aber ich denke, das willst Du nicht wirklich.
Bei mir läuft der Watchdog auf 8s eben um das Problem weitgehend zu umgehen.

Ich habe für clock.c noch ein paar Kleinigkeiten und für DH8 möchte ich nochmal werben, da das später bei TimeStamp auch noch genutzt wird und sich dann erst der Progammspeicher Vorteil ergibt.
Daher habe ich display.c nochmal etwas umgebaut. Mit einem #define CUL_SAVE_PROGMEM werden darin die erweiterten Funktionen abgeschaltet, d.h. vermutlich nur für CUL_V2 wäre dieser define dann überhaupt nötig.
In stringfunc war ich auch schon aktiv. Für eine spätere Korrektur von ks_send müssen auch ungerade Anzahlen von Nibbles von Hex gewandelt werden können. daher habe ich fromhex dahingehend schon vorbereitet. Ich hoffe, das passt Speichertechnisch noch. In der Wandlung sollte es etwas schneller sein, denke ich.

Edit: Anhang gelöscht, da update siehe unten.

Gruß, Ansgar.


noansi

#49
Hallo Testwillige,

im Anhang eine ergänzte Version von Firmware und 00_CUL.pm für ASKSIN/HM Timestamp.

Ich habe in der Firmware aus den Sendequittungen die Länge der kopierten Nachrichten entfernt, da überflüssig und es die Lesbarkeit von Rohdaten Logs erleichtert.
EDIT: Den Timeout für ASKSIN für die Umschaltung auf Senden habe ich reduziert. Nun sollte CUL max. 2s versuchen auf Senden zu schalten und dann Misserfolg zurück melden. Mit der letzten Firmwareversion war der Timeout zu lang und der Watchdog konnte zuschlagen und FHEM hat zwar den disconnect bemerkt, aber mit dem reconnect hat es nicht immer geklappt.

Außerdem habe ich in 00_CUL.pm die Rohdatenausgabe um eine Ausgabe der Timestamp in ms dezimal ergänzt. Damit ist es bezüglich Timingproblemen besser lesbar.
EDIT: Die Timestamp Log Ausgabe habe ich geändert. Die Timestamp kommt nur einmal vor und hat 8 Stellen und wird per default in hex in ms ausgegeben. Mit dem Attribut hmtsLogFormat kann man auf dec = dezimal umstellen. In Hex Ausgabe sind es 32bit und in dezimal 12bit, die ausgegeben werden.

Beispiel hex:
2015.01.03 14:53:01 4: CUL_Parse: CUL_HM868  A FF81 0023D428 0E 11 A010 17832D F11034 0212003006 -66
2015.01.03 14:53:01 4: CUL_send:  CUL_HM868               As 0A 11 8002 F11034 17832D 00
2015.01.03 14:53:02 4: CUL_Parse: CUL_HM868  A FF83 0023D4C0 0A 11 8002 F11034 17832D 00 -138
2015.01.03 14:53:02 4: CUL_Parse: CUL_HM868  A FF81 0023D540 0C 12 A010 17832D F11034 030000 -66.5


Beispiel dezimal:
2015.01.03 14:24:24 4: CUL_Parse: CUL_HM868  A FF51 00631344 0E 08 A010 17832D F11034 0212003006 -67
2015.01.03 14:24:24 4: CUL_send:  CUL_HM868               As 0A 08 8002 F11034 17832D 00
2015.01.03 14:24:24 4: CUL_Parse: CUL_HM868  A FF53 00631520 0A 08 8002 F11034 17832D 00 -138
2015.01.03 14:24:24 4: CUL_Parse: CUL_HM868  A FF51 00631648 0C 09 A010 17832D F11034 030000 -66.5


Edit: Anhang gelöscht, da update siehe unten.

Gruß

Ansgar.

noansi

#50
Hallo Testwillige, hallo Martin,

ich habe in dieser Testversion die 00_CUL.pm dahingehend geändert, das die Sendverzögerung mit der TimeStamp Firmware automatisch hinsichtlich einer Zielverögerung von 120 - 124ms angepasst wird.

Bei mir auf RasPi scheint's zu klappen.

Gruß, Ansgar,
EDIT: geändert wegen ping bug

Edit: Anhang gelöscht, da update siehe unten.

noansi

#51
Hallo Testwillige, hallo Martin,

eine neue Version für 00_CUL.pm steckt im Anhang. Darin habe ich mal zusätzlich den credits Stand genutzt, um bei zu geringem credits Stand die weitere Abarbeitung der HM Sende Warteschlange zu verzögern. Hilft zum Teil, da die Antwort zum Sendebefehl verzögert abgearbeitet wird.
Mit ping (Ap) wird dann der grobe credits Stand aktualisiert. Die Verzögerung unterscheidet auch zwischen Burst und Non Burst messages und verzögert entsprechend lange.

Außerdem ist ein dusseliger Bug bei der Ping Auswertung raus.

Edit: Anhang gelöscht, da update siehe unten.

Gruß, Ansgar.
EDIT: Log ist jetzt auf dauerhaft dezimal für die Timestamps

noansi

#52
Hallo Testwillige, hallo Martin,

eine neue Version für Firmware und 00_CUL.pm steckt im Anhang.

Die Firmware kennt nun den neuen Befehl Aw für verzögertes Senden.
Das Sende Format ist dann Aw 0d ll x*. Die 0 ist Reserve, d (Hex Nibble) die Verzögerungszeit bis zum Senden in 8ms Einheiten. ll die Anzahl der Bytes die gesendet werden sollen und x* die eigentliche Nachricht, also ab 0d das gleiche, wie bisher bei As.
Mit dieser Funktion kann man also um bis zu 15*8ms=120ms das Senden verzögern. Während der Wartezeit wird auch weiter empfangen, so etwas reinkommt, nur Befehle über die Schnittstelle werden nicht angenommen/bearbeitet.

In der zugehörigen 00_CUL.pm ist das dann genutzt, um die Sendeverzögerungen für Ack Nachrichten auf 120ms zu optimieren. Dabei wartet dann nicht mehr FHEM, wie in den vorherigen Versionen, sondern CUL, um das Senden entsprechend zu verzögern.
Wenn nicht gewartet werden muss, soll oder kann, dann wird As benutzt, ansonsten wird der Sendestring auf die passende Aw Nachricht umgesetzt.

Außerdem ist der AP für die PLL Log Ausgaben für cc1101 Problemmeldungen geändert. AP1 schaltet diese ein und AP0 schaltet sie aus. Per Default sind sie nun aus und können also per AP Befehl aktiviert werden.

Edit: Anhang gelöscht, da update siehe unten.

Gruß, Ansgar.

noansi

#53
Hallo Testwillige, hallo Martin,

eine neue Version für 00_CUL.pm steckt im Anhang.

EDIT: Verwerfen erst mal verworfen wegen buggy HM Devices, die bei fehlendem Ack zu schnell Wiederholen.
Ergänzt zur vorherigen Version habe ich das Verwerfen einer zu sendenden Antwort, wenn FHEM zu langsam auf die vorherige Nachricht reagiert und somit keine Chance für einen rechtzeitigen Versand besteht. Bei einer Systemverzögerung von mehr als 180ms wird keine Antwort an das device gesendet, sondern die Antwort verworfen. Die 180ms kann man ggf. noch optimieren.
Das sollte Credits sparen und bei der nächsten Nachricht vom Device die Chance auf den Empfang und die dann hoffentlich rechtzeitige Antwort erhöhen.


Anhand von dhmSt (Antwortzeit von CUL auf Device Nachricht) im Log ist zu sehen, wie hmSysACKwait nach und nach auf die optimale Antworteit zum device von 120ms optimiert wird. Startwert für hmSysACKwait ist 0.1s und das wird bei meinem System auf etwa 0.09s optimiert.
Die 120ms beobachte ich auch bei Antworten von Geräten zu denen CUL sendet, so dass ich die mal als guten Wert annehme.
Sdly ist die Systemverzögerung, die leider zwischendurch mal hoch wird, so dass eine Antwort keinen Sinn macht.

Edit: Anhang gelöscht, da update siehe unten.

Gruß, Ansgar.

tpm88

Hallo Ansgar,

super Arbeit! Bei mir ist es diese Woche etwas eng - sobald ich dazukomme, werde ich aber testen und Feedback geben.

Gruß
Tobias
Test FHEM Server on RPi, CUL_HM
Prod FHEM Server on Odroid HC1, HM-USB, JeeLink
Devices: diverse HM, IT1500, 1wire, LaCrosse, MQTT

tpm88


Hallo Ansgar,

habe die letzte Kombi heute mal getestet. Funktioniert im Großen und Ganzen - aber nicht ganz so reibungslos wie mit der Version von Mitte November (siehe weiter vorne im Thread). Speziell sehe ich deutlich mehr "Resends".


fhem> set hm protoEvents

protoEvents done:
    name          :State           |CmdPend   |Snd       |Resnd     #CmdDel    |ResndFail |Nack      |IOerr
    az_Thermostat : done           | -        |47:       |1:        # -        | -        | -        | -
    az_podP6026   : done           | -        |10:       | -        # -        | -        | -        | -
    bd_Thermostat : done           | -        |33:       |1:        # -        | -        | -        | -
    dg_Thermostat : done           | -        |33:       |1:        # -        | -        | -        | -
    hm_PowerMeter : done           | -        |35:       | -        # -        | -        | -        | -
    hm_RC4_Tobi   : done           | -        |1:        | -        # -        | -        | -        | -
    ke_Pumpe      : done           | -        |21:       |3:        # -        | -        | -        | -
    ke_Switch4    : done           | -        |64:       |7:        # -        | -        | -        | -
    ku_Rollo      : done           | -        |12:       | -        # -        | -        | -        | -
    ku_Switch1    : done           | -        |8:        | -        # -        | -        | -        | -
    te_Markise    : done           | -        |13:       | -        # -        | -        | -        | -
    te_Sensor     : done           | -        |283:      | -        # -        | -        | -        | -
    tim_Rollo     : done           | -        |16:       | -        # -        | -        | -        | -
    vccu          :  -             | -        | -        | -        # -        | -        | -        | -
    wz_Sensor     : done           | -        |137:      | -        # -        | -        | -        | -
    wz_Thermostat : done           | -        |45:       |1:        # -        | -        | -        | -
    wz_vT         :  -             | -        | -        | -        # -        | -        | -        | -
================================================================================================================
    sum           0                |0         |758       |14        #0         |0         |0         |0


Zitat von: noansi am 07 Januar 2015, 01:09:43
Anhand von dhmSt (Antwortzeit von CUL auf Device Nachricht) im Log ist zu sehen, wie hmSysACKwait nach und nach auf die optimale Antworteit zum device von 120ms optimiert wird. Startwert für hmSysACKwait ist 0.1s und das wird bei meinem System auf etwa 0.09s optimiert.
Die 120ms beobachte ich auch bei Antworten von Geräten zu denen CUL sendet, so dass ich die mal als guten Wert annehme.
Sdly ist die Systemverzögerung, die leider zwischendurch mal hoch wird, so dass eine Antwort keinen Sinn macht.

hmSysACKwait pendelt bei mir ebenfalls um 0.09s.

root@raspbmc:/opt/fhem/log# grep hmSysACKwait fhem-2015-01.log
2015.01.08 19:58:25 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 19:58:25 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 19:58:27 4: CUL_parse: myCULv3  dhmSt:136 hmSysACKwait:0.092
2015.01.08 19:58:27 4: CUL_parse: myCULv3  dhmSt:1360 hmSysACKwait:0.092
2015.01.08 19:58:28 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 19:58:28 4: CUL_parse: myCULv3  dhmSt:176 hmSysACKwait:0.092
2015.01.08 19:58:53 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 19:59:01 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 19:59:02 4: CUL_parse: myCULv3  dhmSt:176 hmSysACKwait:0.092
2015.01.08 19:59:02 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 19:59:02 4: CUL_parse: myCULv3  dhmSt:168 hmSysACKwait:0.092
2015.01.08 19:59:03 4: CUL_parse: myCULv3  dhmSt:184 hmSysACKwait:0.092
2015.01.08 19:59:03 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 19:59:03 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 19:59:04 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 19:59:12 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 19:59:25 4: CUL_parse: myCULv3  dhmSt:248 hmSysACKwait:0.092
2015.01.08 19:59:26 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 19:59:28 4: CUL_parse: myCULv3  dhmSt:136 hmSysACKwait:0.09
2015.01.08 19:59:28 4: CUL_parse: myCULv3  dhmSt:1696 hmSysACKwait:0.09
2015.01.08 19:59:29 4: CUL_parse: myCULv3  dhmSt:328 hmSysACKwait:0.09
2015.01.08 19:59:29 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 19:59:29 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 19:59:29 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 19:59:30 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 19:59:30 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 19:59:30 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 19:59:30 4: CUL_parse: myCULv3  dhmSt:112 hmSysACKwait:0.094
2015.01.08 19:59:33 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.092
2015.01.08 19:59:33 4: CUL_parse: myCULv3  dhmSt:232 hmSysACKwait:0.092
2015.01.08 19:59:37 4: CUL_parse: myCULv3  dhmSt:80 hmSysACKwait:0.092
2015.01.08 19:59:39 4: CUL_parse: myCULv3  dhmSt:40 hmSysACKwait:0.092
2015.01.08 19:59:41 4: CUL_parse: myCULv3  dhmSt:2848 hmSysACKwait:0.092
2015.01.08 20:00:17 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:00:24 4: CUL_parse: myCULv3  dhmSt:1936 hmSysACKwait:0.092
2015.01.08 20:01:04 4: CUL_parse: myCULv3  dhmSt:112 hmSysACKwait:0.096
2015.01.08 20:01:04 4: CUL_parse: myCULv3  dhmSt:312 hmSysACKwait:0.096
2015.01.08 20:01:07 4: CUL_parse: myCULv3  dhmSt:136 hmSysACKwait:0.094
2015.01.08 20:01:07 4: CUL_parse: myCULv3  dhmSt:192 hmSysACKwait:0.094
2015.01.08 20:01:09 4: CUL_parse: myCULv3  dhmSt:48 hmSysACKwait:0.094
2015.01.08 20:01:09 4: CUL_parse: myCULv3  dhmSt:24 hmSysACKwait:0.094
2015.01.08 20:01:09 4: CUL_parse: myCULv3  dhmSt:328 hmSysACKwait:0.094
2015.01.08 20:01:09 4: CUL_parse: myCULv3  dhmSt:224 hmSysACKwait:0.094
2015.01.08 20:01:10 4: CUL_parse: myCULv3  dhmSt:280 hmSysACKwait:0.094
2015.01.08 20:01:10 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.094
2015.01.08 20:01:10 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.092
2015.01.08 20:01:48 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.09
2015.01.08 20:02:38 4: CUL_parse: myCULv3  dhmSt:112 hmSysACKwait:0.094
2015.01.08 20:02:38 4: CUL_parse: myCULv3  dhmSt:336 hmSysACKwait:0.094
2015.01.08 20:02:38 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.094
2015.01.08 20:02:38 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.092
2015.01.08 20:02:39 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:02:39 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:02:39 4: CUL_parse: myCULv3  dhmSt:112 hmSysACKwait:0.096
2015.01.08 20:02:39 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.096
2015.01.08 20:02:40 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.094
2015.01.08 20:02:40 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.094
2015.01.08 20:02:40 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.094
2015.01.08 20:02:40 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.094
2015.01.08 20:02:41 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.092
2015.01.08 20:02:42 4: CUL_parse: myCULv3  dhmSt:88 hmSysACKwait:0.092
2015.01.08 20:02:43 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.09
2015.01.08 20:02:46 4: CUL_parse: myCULv3  dhmSt:136 hmSysACKwait:0.09
2015.01.08 20:02:48 4: CUL_parse: myCULv3  dhmSt:56 hmSysACKwait:0.09
2015.01.08 20:02:49 4: CUL_parse: myCULv3  dhmSt:3368 hmSysACKwait:0.09
2015.01.08 20:03:01 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.09
2015.01.08 20:03:01 4: CUL_parse: myCULv3  dhmSt:544 hmSysACKwait:0.09
2015.01.08 20:03:02 4: CUL_parse: myCULv3  dhmSt:136 hmSysACKwait:0.088
2015.01.08 20:03:02 4: CUL_parse: myCULv3  dhmSt:1048 hmSysACKwait:0.088
2015.01.08 20:03:03 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.088
2015.01.08 20:03:03 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.088
2015.01.08 20:03:03 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.088
2015.01.08 20:03:03 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.088
2015.01.08 20:03:04 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.088
2015.01.08 20:03:04 4: CUL_parse: myCULv3  dhmSt:112 hmSysACKwait:0.092
2015.01.08 20:03:04 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:03:04 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:03:07 4: CUL_parse: myCULv3  dhmSt:136 hmSysACKwait:0.09
2015.01.08 20:03:08 4: CUL_parse: myCULv3  dhmSt:280 hmSysACKwait:0.09
2015.01.08 20:03:08 4: CUL_parse: myCULv3  dhmSt:96 hmSysACKwait:0.09
2015.01.08 20:03:08 4: CUL_parse: myCULv3  dhmSt:32 hmSysACKwait:0.09
2015.01.08 20:03:11 4: CUL_parse: myCULv3  dhmSt:40 hmSysACKwait:0.09
2015.01.08 20:03:12 4: CUL_parse: myCULv3  dhmSt:48 hmSysACKwait:0.09
2015.01.08 20:03:12 4: CUL_parse: myCULv3  dhmSt:3232 hmSysACKwait:0.09
2015.01.08 20:03:12 4: CUL_parse: myCULv3  dhmSt:1312 hmSysACKwait:0.09
2015.01.08 20:04:13 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:04:20 4: CUL_parse: myCULv3  dhmSt:2432 hmSysACKwait:0.09
2015.01.08 20:04:25 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:04:27 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:04:40 4: CUL_parse: myCULv3  dhmSt:104 hmSysACKwait:0.094
2015.01.08 20:04:40 4: CUL_parse: myCULv3  dhmSt:448 hmSysACKwait:0.094
2015.01.08 20:04:41 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.092
2015.01.08 20:04:41 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:04:41 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:05:07 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:05:07 4: CUL_parse: myCULv3  dhmSt:616 hmSysACKwait:0.092
2015.01.08 20:05:08 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:05:08 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:05:10 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.09
2015.01.08 20:05:10 4: CUL_parse: myCULv3  dhmSt:136 hmSysACKwait:0.09
2015.01.08 20:05:10 4: CUL_parse: myCULv3  dhmSt:32 hmSysACKwait:0.09
2015.01.08 20:05:10 4: CUL_parse: myCULv3  dhmSt:48 hmSysACKwait:0.09
2015.01.08 20:05:11 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:05:11 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:05:11 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.09
2015.01.08 20:05:11 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:05:12 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:05:12 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:05:31 4: CUL_parse: myCULv3  dhmSt:112 hmSysACKwait:0.094
2015.01.08 20:05:31 4: CUL_parse: myCULv3  dhmSt:312 hmSysACKwait:0.094
2015.01.08 20:05:33 4: CUL_parse: myCULv3  dhmSt:136 hmSysACKwait:0.092
2015.01.08 20:05:33 4: CUL_parse: myCULv3  dhmSt:1232 hmSysACKwait:0.092
2015.01.08 20:05:33 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.09
2015.01.08 20:05:33 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:05:34 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:05:34 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:05:34 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:05:34 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:05:35 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.09
2015.01.08 20:05:35 4: CUL_parse: myCULv3  dhmSt:112 hmSysACKwait:0.094
2015.01.08 20:05:37 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.092
2015.01.08 20:05:38 4: CUL_parse: myCULv3  dhmSt:176 hmSysACKwait:0.092
2015.01.08 20:05:38 4: CUL_parse: myCULv3  dhmSt:56 hmSysACKwait:0.092
2015.01.08 20:05:38 4: CUL_parse: myCULv3  dhmSt:24 hmSysACKwait:0.092
2015.01.08 20:05:38 4: CUL_parse: myCULv3  dhmSt:96 hmSysACKwait:0.092
2015.01.08 20:05:38 4: CUL_parse: myCULv3  dhmSt:32 hmSysACKwait:0.092
2015.01.08 20:05:39 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:05:39 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:05:41 4: CUL_parse: myCULv3  dhmSt:136 hmSysACKwait:0.09
2015.01.08 20:05:41 4: CUL_parse: myCULv3  dhmSt:1952 hmSysACKwait:0.09
2015.01.08 20:05:41 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.09
2015.01.08 20:05:42 4: CUL_parse: myCULv3  dhmSt:112 hmSysACKwait:0.094
2015.01.08 20:05:42 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.094
2015.01.08 20:06:47 4: CUL_parse: myCULv3  dhmSt:144 hmSysACKwait:0.092
2015.01.08 20:06:50 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:06:53 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:07:00 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:09:31 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:10:08 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:11:46 4: CUL_parse: myCULv3  dhmSt:120 hmSysACKwait:0.092
2015.01.08 20:13:10 4: CUL_parse: myCULv3  dhmSt:128 hmSysACKwait:0.09


Gruß
Tobias
Test FHEM Server on RPi, CUL_HM
Prod FHEM Server on Odroid HC1, HM-USB, JeeLink
Devices: diverse HM, IT1500, 1wire, LaCrosse, MQTT

noansi

#56
Hallo Tobias, hallo Martin.

danke für den Test!

angehängt eine neue Version.

Diesmal mit einem send at in der Firmware. Die neuen 00_CUL.pm und Firmware müssen zusammen benutzt werden.

00_CUL.pm ist auch aufgeräumter.

Edit: Anhang gelöscht, da update siehe unten.

Gruß, Ansgar.

tpm88

Hallo Ansgar, Martin,

die Version 71b funktioniert gefühlt noch besser - auch wenn bei 2x Durchlauf meiner kleinen Testsuite wieder ein paar Resends dabei sind.


protoEvents done:
    name          :State           |CmdPend   |Snd       |Resnd     #CmdDel    |ResndFail |Nack      |IOerr
    az_Thermostat : done           | -        |60:       | -        # -        | -        | -        | -
    az_podP6026   : done           | -        |20:       | -        # -        | -        | -        | -
    bd_Thermostat : done           | -        |82:       |3:        # -        | -        | -        | -
    dg_Thermostat : done           | -        |61:       |1:        # -        | -        | -        | -
    hm_PowerMeter : Info_Cleared   | -        | -        | -        # -        | -        | -        | -
    hm_RC4_Tobi   : Info_Cleared   | -        | -        | -        # -        | -        | -        | -
    ke_Pumpe      : done           | -        |21:       | -        # -        | -        | -        | -
    ke_Switch4    : done           | -        |105:      |5:        # -        | -        | -        | -
    ku_Rollo      : done           | -        |22:       | -        # -        | -        | -        | -
    ku_Switch1    : done           | -        |24:       | -        # -        | -        | -        | -
    te_Markise    : done           | -        |22:       | -        # -        | -        | -        | -
    te_Sensor     : done           | -        |8:        | -        # -        | -        | -        | -
    tim_Rollo     : done           | -        |22:       | -        # -        | -        | -        | -
    vccu          : Info_Cleared   | -        | -        | -        # -        | -        | -        | -
    wz_Sensor     : done           | -        |9:        | -        # -        | -        | -        | -
    wz_Thermostat : done           | -        |76:       |1:        # -        | -        | -        | -
    wz_vT         : Info_Cleared   | -        | -        | -        # -        | -        | -        | -
================================================================================================================
    sum           0                |0         |532       |10        #0         |0         |0         |0


Ich hänge mal das verbose4 Log zum CUL während des Tests an, falls Interesse besteht.

Viele Grüße
Tobias
Test FHEM Server on RPi, CUL_HM
Prod FHEM Server on Odroid HC1, HM-USB, JeeLink
Devices: diverse HM, IT1500, 1wire, LaCrosse, MQTT

noansi

#58
Hallo Tobias, hallo Martin, hallo Testwillige,

im Anhang eine neue Version zum Testen. Firmware und 00_CUL.pm müssen unbedingt zusammen benutzt werden!

Zum Einsatz kommt wieder der neu creierte Aa (send at) Befehl. Er hat das Format AaTTTTm*.
TTTT ist der Sendezeitpunkt als 16bit Hex Zahl in 8ms Einheiten. Der Sendezeitpunkt bezieht sich auf die unteren 16 Bit des CUL internen 8ms Tickcounters. Der Sendezeitpunkt darf nicht weiter als etwa 7s vom aktuellen Tickcounterstand entfernt liegen. Die 7s sollten ausreichend sein, um auch mit einem stockenden System keine Probleme zu bekommen. Ist der Sendezeitpunkt verpasst, dann wird sofort gesendet (so weit das mit den 16 Bit erkennbar ist, als schön die 7s einhalten...).  Normalerweise liegt der Sendezeitpunkt etwa 100ms vom letzten Tickcounter Stand entfernt, wenn der Befehl zum Einsatz kommt. Der Watchdog ist auf 8s eingestellt, der würde CUL ggf. wieder in die Realität zwingen.  ;)
*m ist die eigentliche Sendenachricht, wie von As bekannt (Asm*).

Bis zum Erreichen des Sendezeitpunkts wird weiter auf ASKSIN empfangen und empfangene Nachrichten von CUL an den Host weiter gereicht. Jedoch werden Kommandos erst nach dem Senden weiter von CUL verarbeitet.
Die grobe Credits Info, die mit den Timestamps übergeben wird, ist auch geändert, siehe Code. Ergänzt habe ich nach der Tickcounter Stand noch zwei Nibbles, die bei der Sendequittung die Wartezeit zum freien Kanal (CCA) in 8ms Einheiten zurück meldet.

In 00_CUL.pm habe ich die HM Änderungen noch mal kräftig aufgeräumt und verschlankt. Weniger ist hier mehr, wie sich gezeigt hat.
Die HM Änderungen sind auch so weit möglich in separate Funktionen gepackt.
@Martin: Kommt Dir das so entgegen?
@Rudolf: kommt Dir das so entgegen?

Außerdem habe ich so weit erkennbar machbar auf Referenzenübergabe bei Funktionsaufrufen umgestellt. Das bringt noch etwas an Geschwindigkeit. Leider nutzen auch andere Module 00_CUL.pm Funktionen, so dass das nicht nebenwirkungsfrei komplett durchgezogen werden kann.
Mit einem anderen Modul habe ich das mal gemacht und bei den kritischen Funktionen ist dabei bis zu Faktor 2 raus gekommen.
Geht natürlich etwas auf Kosten der Lesbarkeit und erfordert Acht darauf, die Quelle nicht zu überschreiben.

Weiterhin wird nun auch bei ASKSIN "TRANSMIT LIMIT EXCEEDED" getriggert, wenn das Sendezeitlimit erreicht wurde (und deswegen nicht gesendet werden konnte).

@Tobias: Danke für den Test! Sieht doch gar nicht so schlecht aus. Wundern tut mich noch "Can't connect to socket!" das da eingestreut ist. Leider ohne Angabe der Quelle. Eventuell bräuchtest Du mal ein Update, da Rudolf an deviceio etwas geändert hat.

Edit: Anhang gelöscht, da update siehe unten.

Gruß, Ansgar.

tpm88

Zitat von: noansi am 15 Januar 2015, 01:00:00

@Tobias: Danke für den Test! Sieht doch gar nicht so schlecht aus. Wundern tut mich noch "Can't connect to socket!" das da eingestreut ist. Leider ohne Angabe der Quelle. Eventuell bräuchtest Du mal ein Update, da Rudolf an deviceio etwas geändert hat.

Hallo Ansgar,

das "Can't connect to socket!" wird vom LW12 Modul (zur Ansteuerung von RGB LED Streifen) jede Minute erzeugt, wenn es den LED Controller im Netz nicht erreichen kann. Ich habe schon überlegt, das während der Tests stillzulegen - andererseits wollte ich auch keine zu "sterile Laborumgebung" schaffen, da wir bei der Optimierung des CUL HM Timings wohl auch die "reale" übrige Modulwelt von FHEM nicht außen vorlassen sollten.

Zum Zeitpunkt des letzten Tests war die FHEM Installation eigentlich tagesaktuell. Sobald ich dazukomme, werde ich meine Tests mit der neuen Kombi auch wieder durchlaufen lassen.

Gruß
Tobias

PS: Es sieht übrigens nicht nur "gar nicht so schlecht" sondern IMHO bereits _SEHR GUT_ aus.  :)
Test FHEM Server on RPi, CUL_HM
Prod FHEM Server on Odroid HC1, HM-USB, JeeLink
Devices: diverse HM, IT1500, 1wire, LaCrosse, MQTT