Peering HM-TC-IT-WM-W-EU mit HM-CC-VD zerschießt fhem.cfg

[martinp876]

wenn du die messages aufgezeichnet hast einfach mit "erweiterte optionen" die Datei anhängen

[dan1180]

So, da bin ich wieder. Musste beruflich ein paar Tage weg...

Wie man eine Datei anhängt ist mir klar...ich weiß nur nicht welche?!?
Wo wird die Rohmessage gespeichert. Hab da leider nichts zu gefunden.

[martinp876]

wenn du sie eingeschaltet hast werden sie im globalen Log abgelegt

[dan1180]

Hallo zusammen,

ich hab jetzt mal die log-Datei der letzten 24h angehängt. Ich hoffe, ich hab das mit den Rohmessages richtig eingeschaltet. Wie schalte ich das wieder aus? Oder hat das keinen Einfluss auf die Größe der log-Dateien?

Es ist noch immer so, dass der VD immer wieder die Verbindung verliert und auf 15% geht, dann nach einer Weile wieder Verbindung aufnimmt und die eingestellten 0% anfährt.

Bin wirklich jedem von euch für die Hilfe dankbar!

[martinp876]

das Timing deines Systems ist unzuverlässig.

Beispiel
20:42:09.642  TC1_1  :150.25 => next trigger in 42:09.642 + 150.25sec = 44:39.89
20:42:09.850 Parse:           m:58 8202 1F914E 100001 0101000044
20:44:39.898  TC1_1  :135.75 => trigger perfekt, next um 46:55.65
20:44:40.119 Parse:           m:59 8202 1F914E 100001 0101000044
20:46:55.651  TC1_1 :121.5 => trigger perfekt, next um 48:57.15
20:46:55.905 Parse:           m:5A 8202 1F914E 100001 0101000044
20:49:01.872  TC1_1  :171  => UPPS!!! 4 sec zu spät. next um  48:57.15 + 171 = 51:48.15
20:49:11.878  TC1_1 virtualTC use fail-timer
20:51:48.159  TC1_1  :156.5 => trigger perfekt, next um 53:24.66
20:51:48.474 Parse:           m:5C 8202 1F914E 100001 0101000044
20:54:24.664  TC1_1  :142.25 => trigger perfekt, next um....
20:54:25.150 Parse:           m:5D 8202 1F914E 100001 0101000044

Dein system muss sehr präzise antworten, damit nichts schief geht. Das macht es nicht immer. Du musst also suchen, welche Prozesse hie und da einen Delay einbauen.

Du könntest mit apptime einmal nach langläufern suchen  - oder probieren, welche Processe hier zu bummeln.
Die Verzögerung war hier immerhin 4 sec - für echtzeit ein Unding.

[dan1180]

Kann das an meinen 1Wire Sensoren liegen? Ich habe bei manchen event-on-change-reading aktiviert. Ich könnte mir vorstellen, dass ein Reading aufgrund eines Canges dazwischenfunkt wenn die HM Komponenten ihre Signale austauschen. Kann das sein? Ich werde das Attribut mal bei allen deaktivieren.

[martinp876]

möglich... ist vieles.
4 Sec ist eine lange Zeit... - um es zum kippen zu gringen bracht es erheblich weniger.
starte einmal apptime und werte die Zeiten aus. Das wäre m.E. der 1. Schritt.

[dan1180]

Hier das Resultat von apptime:

Code Auswählen Erweitern


                                name            function    max     count  total  average  maxDly
               tmr-OWTHERM_GetValues      HASH(0x27ae330)   7416      2    14284  7142.00  11988 HASH(0x27ae330)
               tmr-OWTHERM_GetValues      HASH(0x27ae7b0)   6957      2    13814  6907.00  11742 HASH(0x27ae7b0)
               tmr-OWTHERM_GetValues      HASH(0x27aec30)   6890      2    13747  6873.50  11963 HASH(0x27aec30)
               tmr-OWTHERM_GetValues      HASH(0x2779498)   6888      2    13748  6874.00  12174 HASH(0x2779498)
               tmr-OWTHERM_GetValues      HASH(0x27936a8)   6885      2    13732  6866.00  12055 HASH(0x27936a8)
               tmr-OWTHERM_GetValues      HASH(0x27ac9c0)   6881      2    13732  6866.00  12033 HASH(0x27ac9c0)
               tmr-OWTHERM_GetValues      HASH(0x2793b28)   6880      2    13748  6874.00  12033 HASH(0x2793b28)
               tmr-OWTHERM_GetValues      HASH(0x27ace40)   6880      2    13729  6864.50  11990 HASH(0x27ace40)
               tmr-OWTHERM_GetValues      HASH(0x2792488)   6874      2    13732  6866.00  12277 HASH(0x2792488)
               tmr-OWTHERM_GetValues      HASH(0x2792908)   6873      2    13736  6868.00  12322 HASH(0x2792908)
               tmr-OWTHERM_GetValues      HASH(0x2792da8)   6870      2    13726  6863.00  12244 HASH(0x2792da8)
               tmr-OWTHERM_GetValues      HASH(0x2735de0)   6869      2    13724  6862.00  12013 HASH(0x2735de0)
               tmr-OWTHERM_GetValues      HASH(0x2792008)   6868      2    13725  6862.50  12285 HASH(0x2792008)
               tmr-OWTHERM_GetValues      HASH(0x27af0d0)   6868      2    13734  6867.00  11968 HASH(0x27af0d0)
               tmr-OWTHERM_GetValues      HASH(0x27af550)   6867      2    13726  6863.00  12093 HASH(0x27af550)
               tmr-OWTHERM_GetValues      HASH(0x2778b98)   6866      2    13720  6860.00  12101 HASH(0x2778b98)
               tmr-OWTHERM_GetValues      HASH(0x2779918)   6866      2    13714  6857.00  12146 HASH(0x2779918)
               tmr-OWTHERM_GetValues      HASH(0x2779018)   6864      2    13727  6863.50  12081 HASH(0x2779018)
               tmr-OWTHERM_GetValues      HASH(0x2793228)   6863      2    13702  6851.00  12345 HASH(0x2793228)
                              HMLAN1           HMLAN_Read    142     11      663    60.27      0 HASH(0x2219840)
         FHEMWEB:192.168.2.103:51120              FW_Read    120      6      153    25.50      0 HASH(0x2ad4e98)


Was kann man da jetzt sehen?

[martinp876]

max: Zeit in ms. Du hast jede Menge Jons, die ~7sec dauern. Die wurden im Beobachtungszeitraum 2-mal aufgerufen.
Das sind wohl one-wire timern (tmr sind Timer).

Diese Prozedur "OWTHERM_GetValues" ist schlicht nicht echtzeitfähig - die blockiert dein FHEM KOMLETT für 7 sec - immer wieder.
Du solltest mit dem Entwickler reden - ich sehe das als ernstes Problem.
Eine Prozedur kann schon einmal länger dauern... aber regelmäßig geht das nicht.

Der Entwickler muss dies in einen separaten Threat auslagern - oder sonst wie gerhacken. Offensichtlich wird hier aktiv gewartet.
Das kann u.a. dazu führen, dass deine Schaltkommandos um 7 sec verzögert werden - allein das ist schon nervig...

[dan1180]

Ich habe jetzt mal alle OWTHERM, sowie meinen OWX, deaktiviert. Nun sieht das Ergebnis von "apptime" so aus:

Code Auswählen Erweitern


                                name             function    max   count    total  average     maxDly
             tmr-CUL_HM_updateConfig         updateConfig    496      1      496   496.00      4 updateConfig
                              HMLAN1           HMLAN_Read     80     16      164    10.25      0 HASH(0x2b913c0)
                          eventTypes    eventTypes_Define     59      1       59    59.00      0 HASH(0x2b8a310); eventTypes eventTypes ./log/eventTypes.txt
                   tmr-CUL_HM_procQs        CUL_HM_procQs     44      4      116    29.00    150 CUL_HM_procQs
             tmr-CUL_HM_respPendTout      respPend:254C27     44      8      107    13.38    196 respPend:254C27
                              HMLAN1         HMLAN_Define     34      1       34    34.00      0 HASH(0x2b913c0); HMLAN1 HMLAN 192.168.2.151:1000
             tmr-CUL_HM_respPendTout      respPend:254AEA     29      5       53    10.60   2171 respPend:254AEA
                          GlobalAttr                          19     13       20     1.54      0 set; global; modpath; .
             tmr-CUL_HM_valvePosUpdt    valvePos:10000101     11      1       11    11.00 3856922 valvePos:10000101
                              HKS_BD           CUL_HM_Set      9      2       18     9.00      0 HASH(0x1eb0058); HKS_BD; ?
                        HKT_BU_Clima           CUL_HM_Set      9      2       17     8.50      0 HASH(0x2b07ee8); HKT_BU_Clima; ?
                               TC1B1           CUL_HM_Set      9      2       17     8.50      0 HASH(0x28a4340); TC1B1; ?
                             VIR_SA1        CUL_HM_Define      9      1        9     9.00      0 HASH(0x2a99eb0); VIR_SA1 CUL_HM 100002
                              WTS_BD          CUL_HM_Attr      9     14       10     0.71      0 set; WTS_BD; model; HM-TC-IT-WM-W-EU
                             HMSA4.1        CUL_HM_Define      8      1        8     8.00      0 HASH(0x2219510); HMSA4.1 CUL_HM 254C27
                           HMSA4.2_3           CUL_HM_Set      8      2       11     5.50      0 HASH(0x27359d0); HMSA4.2_3; ?
                             VIR_TC1        CUL_HM_Define      8      1        8     8.00      0 HASH(0x2a9b520); VIR_TC1 CUL_HM 100001
                      WTS_BD_Climate           CUL_HM_Set      8      2       16     8.00      0 HASH(0x1daaa08); WTS_BD_Climate; ?
                              HKS_BD        CUL_HM_Define      7      1        7     7.00      0 HASH(0x1eb0058); HKS_BD CUL_HM 1F914E
                              HKT_BU          CUL_HM_Attr      7     13        8     0.62      0 set; HKT_BU; model; HM-CC-RT-DN
                              HKT_BU        CUL_HM_Define      7      1        7     7.00      0 HASH(0x2b12e20); HKT_BU CUL_HM 248BD9


Besser oder? Ich denke, dass es eine gute Idee ist an anderer Stelle dieses Problem zur Diskussion zu stellen. Wo finde ich heraus wer der Entwickler dieses Moduls ist? Darf ich dem deine Bemerkung, was er machen sollte, schicken?

Werde jetzt mal meinen VD beobachten...aber ich habe da eine Vermutung wie oft er sich jetzt aufhängt...

Soweit mal vielen Dank!

[martinp876]

im file MAINTAINER.txt sind die Namen aufgeführt. In diesem Fall "pahenning".
Du kannst es einfach im 1-wire bereich posten - da sollte er als maintainer sowieso aktiv sein.
Klar kannst du meinen Kommentar posten.
Vielleicht hat er eh schon eine Lösung für das Problem....

[dan1180]

Also ich hab das mal im "1wire" Forum gepostet und die sind der Meinung, dass mein Selbstgebauter DS9097 daran schuld ist. Also nicht weil ich den falsch gebaut habe sondern weil:

Die Verzögerungen kommen daher, dass OWTHERM beim normalen OWX bei jeder Themperaturmessung den DS18B20 erst triggern und nach Abschluss der Messung (ca. 1 Sekunde Verzögerung) auslesen kann. Die Sekunde Verzögerung erfolgt mit OWX immer synchron (d.h. einfach durch Anhalten des Prozesses). 19 Sensoren machen damit 19 Sekunden Wartezeit, verteilt auf das Wiederholinterval.

Seit ich meinen OWX und die Sensoren deaktiviert habe rennt mir FHEM beinahe davon  ...und ich finde in den letzten 24h keinen Aussetzer mehr im log meines VD 

Ich denke als Fazit kann ich zusammenfassen, dass mein langsamer OWX schuld an der ganzen Misere ist. Warum es mir meine fhem.cfg zerschossen hat weiß ich zwar noch nicht aber das kann auch ein individueller Fehler gewesen sein. Auf jeden Fall war an der fehlerhaften Kommunikation ein (unregelmäßiges) Blockieren der durch die OWTHERM-Sensorabfrage schuld. Gefunden wurde dieser Fehler durch den Befehl "apptime". Hier wurde deutlich, dass FHEM von OWTHERM 7-11 Sekunden beschäftigt wurde...eindeutig zu lane.

Vielen Dank an alle, die mich bei der Fehlersuche unterstützt und mir mit ihren Tipps geholfen haben. Ich hoffe irgendwann mal einem neuen, nervigen newbe mit meinem (dann angeeigneten) Wissen um FHEM helfen zu können 

Werd diesen Beitrag Ende der Woche schließen, falls jemand noch etwas anmerken oder nachfragen möchte.

[frank]

...und ich finde in den letzten 24h keinen Aussetzer mehr im log meines VD

so kenne ich das auch. na dann viel spass.

gruss frank

[Joachim]

@ dan1180,
Einfach mal als Tipp, dass 1-Wire FHEM verzögert, ist bekannt, und ein Designfehler beider! 1-Wire-Varianten für FHEM.
Wenn man 1-Wire Sensoren auf eine eigene FHEM-Instanz auslagert, und dann mit FHEM2FHEM und cloneDummy abfragt, dann läuft es hervorragend.
Anders ausgedrückt, 1-Wire mag nichts anderes neben sich.

Gruß Joachim

[martinp876]

Die alternative wäre, 1-wire mit blocking zu implementieren. Da ich mir aber 1-wire nicht angesehen habe, könnte dies durchaus schwierig werden.
Im Prinzip ist daher Joachims Vorschlag wohl der pragmatische.