HM-CC-RT-DN nimmt keine Befehle mehr an

Begonnen von uland2012, 02 Februar 2014, 09:30:25

Vorheriges Thema - Nächstes Thema

martinp876

hm -sehr seltsam, dass es so langsam ist bei dir. das ist definitv zu spät.
Habe ich sicher schon oft gefraft - das ist die aktuellen version?

      if ($modules{CUL_HM}{defptr}{$dst}{helper}{io}{nextSend}){
        my $dDly = $modules{CUL_HM}{defptr}{$dst}{helper}{io}{nextSend} - $tn;
        $dDly -= 0.05 if ($typ eq "02");# delay at least 50ms for ACK, but not 100
       Log 1,"HMLAN delay:".(($dDly > 0.1)?0.1:$dDly)  if ($dDly > 0.01);
        select(undef, undef, undef, (($dDly > 0.1)?0.1:$dDly))
              if ($dDly > 0.01);
      }

Du kannst einmal folgende Zeile in 00_HMLAN einbauen, ob das delay hier gemacht wird. Zeile 699




Gruss Martin

Herr 3x

Hallo Martin,

die Version vom fhem ist aktuell. Habe vor den Tests extra noch ein Update gemacht.
2014.02.09 19:32:22.970 0: Server started with 195 defined entities (version $Id: fhem.pl 4829 2014-02-07 07:27:47Z rudolfkoenig $, os darwin, user admin, pid 27688)
2014.02.09 19:32:22.971 1: HMLAN_Parse: HMLAN1 new condition ok
2014.02.09 19:32:30.284 1: HMLAN delay:0.0990369319915771
2014.02.09 19:32:41.220 1: HMLAN delay:0.0985410213470459
2014.02.09 19:34:40.525 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:0457E15A d:FF r:FFD8     m:39 8610 2324A7 000000 0AA0E00F0018
2014.02.09 19:34:40.526 1: HMLAN delay:0.0931150913238525
2014.02.09 19:34:40.693 0: HMLAN_Send:  HMLAN1 S:S17EE0D52 stat:  00 t:00000000 d:01 r:17EE0D52 m:0C A112 121212 2324A7
2014.02.09 19:34:41.296 0: HMLAN_Parse: HMLAN1 R:R17EE0D52 stat:0008 t:00000000 d:FF r:7FFF     m:0C A112 121212 2324A7
2014.02.09 19:34:41.297 0: HMLAN_Parse: HMLAN1 no ACK from 2324A7
2014.02.09 19:34:50.221 1: HMLAN delay:0.0924179553985596
2014.02.09 19:37:21.527 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045A565C d:FF r:FFD8     m:3A 8610 2324A7 000000 0AA0DF0F0018
2014.02.09 19:37:21.528 1: HMLAN delay:0.0942509174346924
2014.02.09 19:37:21.686 0: HMLAN_Send:  HMLAN1 S:S17F0823B stat:  00 t:00000000 d:01 r:17F0823B m:0E A112 121212 2324A7
2014.02.09 19:37:22.289 0: HMLAN_Parse: HMLAN1 R:R17F0823B stat:0008 t:00000000 d:FF r:7FFF     m:0E A112 121212 2324A7
2014.02.09 19:37:22.289 0: HMLAN_Parse: HMLAN1 no ACK from 2324A7
2014.02.09 19:37:48.726 1: HMLAN delay:0.0912721157073975
2014.02.09 19:39:48.277 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045C93B0 d:FF r:FFD3     m:3B 8610 2324A7 000000 0AA0DF0F0018
2014.02.09 19:39:48.278 1: HMLAN delay:0.0952539443969727
2014.02.09 19:39:48.384 0: HMLAN_Send:  HMLAN1 S:S17F2BF7A stat:  00 t:00000000 d:01 r:17F2BF7A m:10 A112 121212 2324A7
2014.02.09 19:39:48.541 0: HMLAN_Parse: HMLAN1 R:R17F2BF7A stat:0001 t:045C94BD d:FF r:FFD3     m:10 8002 2324A7 121212 00
2014.02.09 19:39:48.542 1: HMLAN delay:0.0988528728485107
2014.02.09 19:39:48.713 0: HMLAN_Send:  HMLAN1 S:+2324A7,00,01,
2014.02.09 19:39:48.714 0: HMLAN_Send:  HMLAN1 S:S17F2C082 stat:  00 t:00000000 d:01 r:17F2C082 m:11 A011 121212 2324A7 860429
2014.02.09 19:39:48.945 0: HMLAN_Parse: HMLAN1 R:R17F2C082 stat:0001 t:045C9651 d:FF r:FFD3     m:11 8002 2324A7 121212 00
2014.02.09 19:39:48.946 1: HMLAN delay:0.0990457534790039
2014.02.09 19:39:49.112 0: HMLAN_Send:  HMLAN1 S:+2324A7,00,01,
2014.02.09 19:39:49.113 0: HMLAN_Send:  HMLAN1 S:S17F2C216 stat:  00 t:00000000 d:01 r:17F2C216 m:12 A001 121212 2324A7 04040000000001
2014.02.09 19:39:49.352 0: HMLAN_Parse: HMLAN1 R:R17F2C216 stat:0001 t:045C97E8 d:FF r:FFD3     m:12 8010 2324A7 121212 0208000000
2014.02.09 19:39:49.353 1: HMLAN delay:0.0987308025360107
2014.02.09 19:39:49.504 0: HMLAN_Send:  HMLAN1 S:+2324A7,00,01,
2014.02.09 19:39:49.505 0: HMLAN_Send:  HMLAN1 S:S17F2C3AD stat:  00 t:00000000 d:01 r:17F2C3AD m:13 A001 121212 2324A7 00040000000007
2014.02.09 19:39:49.769 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045C9984 d:FF r:FFD3     m:13 A010 2324A7 121212 03012B22093D18030016073000640F0500
2014.02.09 19:39:49.881 0: HMLAN_Parse: HMLAN1 R:R17F2C3AD stat:0001 t:045C9989 d:FF r:FFD3     m:13 A010 2324A7 121212 03012B22093D18030016073000640F0500
2014.02.09 19:39:50.028 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045C9A87 d:FF r:FFD3     m:14 A010 2324A7 121212 03100000098E486656F049204520452045
2014.02.09 19:39:50.286 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045C9B89 d:FF r:FFD3     m:15 A010 2324A7 121212 031F204520452045204520452045204520
2014.02.09 19:39:50.544 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045C9C8B d:FF r:FFD3     m:16 A010 2324A7 121212 032E486656F04920452045204520452045
2014.02.09 19:39:50.803 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045C9D8E d:FF r:FFD3     m:17 A010 2324A7 121212 033D2045204520452045204520485456F0
2014.02.09 19:39:51.061 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045C9E90 d:FF r:FFD3     m:18 A010 2324A7 121212 034C492055084520452045204520452045
2014.02.09 19:39:51.319 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045C9F92 d:FF r:FFD3     m:19 A010 2324A7 121212 035B20452045204520485456F049205508
2014.02.09 19:39:51.577 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045CA094 d:FF r:FFD3     m:1A A010 2324A7 121212 036A452045204520452045204520452045
2014.02.09 19:39:51.836 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045CA197 d:FF r:FFD3     m:1B A010 2324A7 121212 0379204520485456F04920550845204520
2014.02.09 19:39:52.094 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045CA299 d:FF r:FFD3     m:1C A010 2324A7 121212 0388452045204520452045204520452048
2014.02.09 19:39:52.352 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045CA39B d:FF r:FFD3     m:1D A010 2324A7 121212 03975456F0492055084520452045204520
2014.02.09 19:39:52.611 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045CA49E d:FF r:FFD3     m:1E A010 2324A7 121212 03A645204520452045204520485456F049
2014.02.09 19:39:52.869 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045CA5A0 d:FF r:FFD3     m:1F A010 2324A7 121212 03B5205508452045204520452045204520
2014.02.09 19:39:53.124 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045CA69F d:FF r:FFD3     m:20 A010 2324A7 121212 03C445204520452012212D0F1E1E
2014.02.09 19:39:53.371 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:045CA797 d:FF r:FFD3     m:21 8010 2324A7 121212 0300
2014.02.09 19:40:32.977 1: HMLAN delay:0.0922799110412598


Die ersten delays sind vom Schalten eines Aktors.

Netzwerktechnisch ist der HMLAN problemlos erreichbar. Auf ping antwortet er sogar schneller als die FB. Die Route ist auch direkt. Und FHEM läuft auf einem Core 2 Duo mit 2,5 GHz mit SSD. Eigentlich auch schnell.  :o

Grüße

Herr 3x

martinp876

hi,

19:34:40.525  Parse: HMLAN1 R:E2324A7   stat:0000  m:39 8610 2324A7 000000 0AA0E00F0018
19:34:40.526  delay:0.0931150913238525
19:34:40.693  Send:  HMLAN1 S:S17EE0D52 stat:  00  m:0C A112 121212 2324A7

schlechtes timing. Die 93ms sind korrekt gerechnet - aber dein system führt es erst nach 160ms aus


19:37:21.527  Parse: HMLAN1 R:E2324A7   stat:0000  m:3A 8610 2324A7 000000 0AA0DF0F0018
19:37:21.528  delay:0.0942509174346924
19:37:21.686  Send:  HMLAN1 S:S17F0823B stat:  00  m:0E A112 121212 2324A7
19:37:48.726  delay:0.0912721157073975
19:39:48.277  Parse: HMLAN1 R:E2324A7   stat:0000  m:3B 8610 2324A7 000000 0AA0DF0F0018

die erste Berechnung ist wieder das gleiche.

Das 2. Delay verstehe ich nicht.

Seltsam, dass der Systemcall so unpräzise ist. Kenne ich so nicht.
Gruss Martin


Herr 3x

Hmmm, das zweite delay könnte von einem anderen Gerät stammen, der Zeile fürs Log unterscheidet ja nicht, oder?

Allerdings frage ich mich, was fhem in den 160 ms sonst so macht. Kann man das irgendwie tracen?
Immerhin scheinen andere Geräte keine solche Verzögerung zu haben:
2014.02.09 20:58:02.218 0: HMLAN_Send:  HMLAN1 S:+21D6F0,00,01,
2014.02.09 20:58:02.218 0: HMLAN_Send:  HMLAN1 S:S183A5F2E stat:  00 t:00000000 d:01 r:183A5F2E m:18 A001 121212 21D6F0 010E
2014.02.09 20:58:02.384 0: HMLAN_Parse: HMLAN1 R:E21D6F0   stat:0000 t:04A436B8 d:FF r:FFC1     m:18 A410 21D6F0 121212 0601C80042
2014.02.09 20:58:02.498 0: HMLAN_Parse: HMLAN1 R:R183A5F2E stat:0001 t:04A436BD d:FF r:FFC1     m:18 A410 21D6F0 121212 0601C80042
2014.02.09 20:58:55.093 0: HMLAN_Send:  HMLAN1 S:+21D6F0,00,01,
2014.02.09 20:58:55.093 0: HMLAN_Send:  HMLAN1 S:S183B2DB9 stat:  00 t:00000000 d:01 r:183B2DB9 m:1A A011 121212 21D6F0 0201C80000
2014.02.09 20:58:55.252 0: HMLAN_Parse: HMLAN1 R:R183B2DB9 stat:0001 t:04A50550 d:FF r:FFC1     m:1A 8002 21D6F0 121212 0101C80042


Herr 3x

martinp876

ZitatHmmm, das zweite delay könnte von einem anderen Gerät stammen, der Zeile fürs Log unterscheidet ja nicht, oder?

guter Punkt - wenn du selektiv gefiltert hast.

ZitatAllerdings frage ich mich, was fhem in den 160 ms sonst so macht. Kann man das irgendwie tracen?
FHEM kann nichts machen. Das ist (sehr weit gehens) single-threated. Ein Select ist ein system-call. Es erlaubt Linux andere Prozesse zu bearbeiten.
Zwischen dem Select (warten) und dem naehsten Log ist fast kein Code - es ist also davon auszugehen, das dies in "nullzeit" erledigt wird (oft bestaetigt).
FHEM ist single-threated - linix aber nicht.
Nachdem select eigentlich immer sauber funktiniert (man muss damit rechnen, dass das OS auch einmal etwas anderes tut, ist aber die Ausnahme) stellt sich die Frage, was in deinem System anders laeuft.
a) laeuft der Timer deines Select langsamer?
b) ist ein offset auf der Berechnung

test: setze $dDly = 0.05 in der IF abfrage und pruefe, ob 50ms, 100ms oder 160ms gewartet werden.

Aktuell scheint es ein Problem deines OS zu sein.
Gruss Martin

Herr 3x

Hallo Martin,

ich habe mal probehalber die Zeile $dDly = 0.05 angepasst,
      if ($modules{CUL_HM}{defptr}{$dst}{helper}{io}{nextSend}){
        my $dDly = $modules{CUL_HM}{defptr}{$dst}{helper}{io}{nextSend} - $tn;
        $dDly -= 0.05 if ($typ eq "02");# delay at least 50ms for ACK, but not 100
         Log 1,"HMLAN 1 delay:".(($dDly > 0.1)?0.1:$dDly)  if ($dDly > 0.01);
        select(undef, undef, undef, (($dDly > 0.1)?0.1:$dDly))
              if ($dDly = 0.05);
      Log 1, "HMLAN 2 delay select";

Die zusätzlichen Logeinträge habe ich zur Zeitmessung eingebaut.
Dann sieht mein Log so aus:

2014.02.11 20:36:17.467 0: HMLAN_Parse: HMLAN1 R:E2324A7   stat:0000 t:0EDD66EE d:FF r:FFD4     m:C4 8610 2324A7 000000 0A90DD0F0018
2014.02.11 20:36:17.468 1: HMLAN 1 delay:0.094271183013916
2014.02.11 20:36:17.561 1: HMLAN 2 delay select
2014.02.11 20:36:17.561 0: HMLAN_Send:  HMLAN1 S:S22732E80 stat:  00 t:00000000 d:01 r:22732E80 m:10 A112 121212 2324A7
2014.02.11 20:36:17.562 1: HMLAN delay end syswrite
2014.02.11 20:36:17.718 0: HMLAN_Parse: HMLAN1 R:R22732E80 stat:0001 t:0EDD67EF d:FF r:FFD4     m:10 8002 2324A7 121212 00
2014.02.11 20:36:17.720 1: HMLAN 1 delay:0.099085807800293
2014.02.11 20:36:17.829 1: HMLAN 2 delay select
2014.02.11 20:36:17.829 0: HMLAN_Send:  HMLAN1 S:+2324A7,00,01,
2014.02.11 20:36:17.829 0: HMLAN_Send:  HMLAN1 S:S22732F7C stat:  00 t:00000000 d:01 r:22732F7C m:11 A011 121212 2324A7 86042A
2014.02.11 20:36:17.830 1: HMLAN delay end syswrite
2014.02.11 20:36:18.121 0: HMLAN_Parse: HMLAN1 R:R22732F7C stat:0001 t:0EDD6982 d:FF r:FFD4     m:11 8002 2324A7 121212 00
2014.02.11 20:36:31.891 1: HMLAN delay end syswrite


Damit wird die Temperatur meistens gesetzt.

Um der Sache etwas tiefer auf den Grund zu gehen würde ich gern verstehen, was das select eigentlich da macht.

Herr 3x

betateilchen

Zitat von: Herr 3x am 11 Februar 2014, 20:49:10

select(undef, undef, undef, (($dDly > 0.1)?0.1:$dDly))

Um der Sache etwas tiefer auf den Grund zu gehen würde ich gern verstehen, was das select eigentlich da macht.

Das select() macht eine Verzögerung von 0,1s falls das ermittelte $dDly größer als 0.1 ist, ansonsten beträgt die Verzögerung $dDly
-----------------------
Formuliere die Aufgabe möglichst einfach und
setze die Lösung richtig um - dann wird es auch funktionieren.
-----------------------
Lesen gefährdet die Unwissenheit!

martinp876

im letzten Beispiel funktioniert es ja auch... da sind keine 160ms mehr dabei. Hast du etwas geaendert?

Herr 3x

Hallo Martin,

mit einem
sleep(0.05);
statt dem select scheint das Timing besser zu klappen.
Meine Vermutung ist, dass das select bei mir eine andere Zeit zählt oder irgendwas anderes verzögert.
Es gibt eine real time, user time und sys time. Mit real = user + sys + x
Wenn ich perl -e 'select(undef,undef,undef,.1)' als script mit "time" aufrufe bekomme ich:
real 0m0.113s
user 0m0.004s
sys 0m0.006s


Mit dem unschönen Workaround klappt es erst mal.

Danke
Herr 3x

martinp876

hm - select ist ganz allgemein eine Methode um ein paar ms zu warten. Muss etwas an deinem System sein...

Herr 3x

Hallo,

heute habe ich meine Gesamtconfig nochmal auf der FB7390 getestet: Da läuft alles. Also muss es an dem Server liegen :-\
Nachdem die GUI sich schnell anfühlt und auch sonst eigentlich alles andere gut funktioniert habe ich mir gedacht, dass ich die Wartezeit mal selbst bestimmt, wenn das OS nicht echtzeitfähig ist.
Herausgekommen ist das (man möge mir mein Amateur-Perl verzeihen):
Log 1,"HMLAN delay:".(($dDly > 0.1)?0.1:$dDly)  if ($dDly > 0.01);
#        select(undef, undef, undef, (($dDly > 0.1)?0.1:$dDly))
        my $t0 = [gettimeofday];
       my $elap_time = 0;
       my $elap_test = 0;
       do{
        sleep(0.001);
        $elap_time = tv_interval ( $t0,[gettimeofday]);
        if ($elap_time > $dDly) {$elap_test = 1};
        }while($elap_test == 0);
        Log 1,"HMLAN delay end".$elap_time."  ".$elap_test;


Im Log sieht das etwa so aus:
2014.02.15 22:02:45.255 0: HMLAN_Send:  HMLAN1 S:S375BC6EF stat:  00 t:00000000 d:01 r:375BC6EF m:5F A001 121212 2324A7 0503
2014.02.15 22:02:45.417 0: HMLAN_Parse: HMLAN1 R:R375BC6EF stat:0001 t:23C6C871 d:FF r:FFD5     m:5F 8010 2324A7 121212 0100000000
2014.02.15 22:02:45.418 1: HMLAN delay:0.0990607738494873
2014.02.15 22:02:45.518 1: HMLAN delay end0.099649  1
2014.02.15 22:02:45.518 0: HMLAN_Send:  HMLAN1 S:S375BC7EE stat:  00 t:00000000 d:01 r:375BC7EE m:60 A001 121212 2324A7 05040000000001
2014.02.15 22:02:45.823 0: HMLAN_Parse: HMLAN1 R:R375BC7EE stat:0001 t:23C6CA08 d:FF r:FFD5     m:60 8010 2324A7 121212 0208000000
2014.02.15 22:02:45.825 1: HMLAN delay:0.0988819599151611
2014.02.15 22:02:45.925 1: HMLAN delay end0.100192  1


Na ja, elegant ist anders, aber es funktioniert.  An der Prozessorlast sehe ich keinen Unterschied gegenüber vorher.
Jetzt funktioniert das setzen der Soll-Temperatur reibungslos (vermutlich bis Montag) ;)

Herr 3x

martinp876

wie du es magst.
es arbeitet schon mehr. Ein Select lässt andere Processe - ausser FHEM zu wort kommen, sleep kann ich aktuell nicht klar zuordnen, Aber du rufst es in jeden Fall mehrfach auf - das OS muss den prozess immer wieder in den Fordergrund switchen - das kostet in jedem Fall kernal zeit.

Da dein System aber generell eine korrekte Zeit errechnen kann scheint eine Einstellung im Linux falsch zu sein. Mit echtzeitfähigkeit im eigentlichen Sinn hat dies nichts zu tun.... fast alle hier verwendeten Linux sind nicht wirklich echzeit programmiert...

Herr 3x

Hallo Martin,

Vermutlich ist das untergegangen, aber ich habe fhem nicht auf Linux laufen sondern auf OSX 10.9.
Vor dem Hintergrund kann das Verhalten schon anders sein. Kann natürlich auch ein Bug sein.

Mir ist bewusst, dass ich mit dem Workaround mehr Prozessorlast erzeuge. Das scheint aber in der Gesamtlast des Systems unter zu gehen, fhem kommt nicht über eine einstellige Prozentzahl der CPU-Last hinaus. Ich werde nach Updates einfach die Stelle patchen und gut is.

Danke für deine Unterstützung

Herr 3x

martinp876

ok - select sollte trotzdem arbeiten. Ich denke was ist irgendwo einstellbar ist.
Du könntest ausmessen, ob es ein offset, oder eine Lineare Abweichung ist - oder schlimmstenfalls random.

Du kannst natürlich auch die Funktion überschreiben. Wenn du  HMLAN_SimpleWrite(@) rauskopierst und in ein eingenes Modul einbaust wird die Orginale mit deiner ersetzt.
Dann kannst du es einfach einauen und musst nicht patchen (oder - es patchet automatisch). Wenn natürlich die Funktion geändert wird musst du nachziehen... der Rest läuft

Gruss Martin

thermo

#44
Hallo Zusammen,

ich habe ebenfalls Probleme mit meinem neu erworbenen HM-CC-RT-DN.
Bisher hatte ich lediglich MAX! Komponenten, die über einen MAX-LAN angesteuert werden und einen CUL v3 mit Version 1.55 zum Lesen eines S330TH   und FHEM Version 5.5 mit dem neusten update.
Da MAX nicht sehr ausbaubar ist möchte ich mit Homematic Komponenten weitermachen und habe den oben erwähnten    HM-CC-RT-DN mit dem CUL (unter rfmode HomeMatic)
erfolgreich gepairt. Es erscheint

PairedTo 0xF11234

wobei F11234 mein CUL ist. Auch kann ich Befehle zum  HM-CC-RT-DN senden. Zum Beispiel habe ich das Temperaturprofil gesetzt 
und kann auf bestimmte manuelle Temperaturen stellen.  Empgfangen geht problemlos, ich bekomme regelmäßig die Temperaturen im Log.

ABER:

Es akkumulieren sich CMDs_pending. Morgens sind es leicht 150. Manachmal werden es weniger, das heiß ein paar scheint er los zu werden und
es heißt auch

Activity                        alive   2014-02-16 09:12:39
CommandAccepted yes     2014-02-16 12:22:48


Nach Suchen im Forum habe ich folgende Ursachen ausgeschlossen:

1) schlecher Empfang : 
rssi_at_CUL_HM      avg:-29.42 min:-70.5 max:-27.5 lst:-29 cnt:318

2) HMInfo gab Fehler bei IODev das habe ich durch setzen von
attr CUL_HM hmId F11234
attr Thermo IODev CUL_HM
loswerden können.

An der Sache hat sich aber nichts geändert.

Kann mir jemand raten?

Gruß George