Weekdaytimer schaltet manchmal nicht "off"

[Lars721]

Hallo,
ich bin neu angemeldet im Forum, obwohl eigentlich schon mehrere Jahre Fhem benutze und hier auch schon viel gelesen habe.

Eventuell hat auch jemand schon dieses Verhalten beim Weekdaytimer beobachtet.
Ich habe eine Zeitschaltuhr nach dieser Vorlage (etwas abgeändert) https://forum.fhem.de/index.php/topic,18294.0.html in mein Fhem eingebaut.
Das Einschalten des Timers auf "on" funktioniert soweit ohne Probleme.
Nur das Ausschalten des Timers funktioniert manchmal nicht (Timer schaltet nicht "off").

Ich konnte bislang nicht nachvollziehen, bei welchen Umständen das Problem auftritt.
Zuerst dachte ich, dass das Attribut "switchInThePast=1" mit diesem Problem zusammen hängt. Das war es allerdings nicht.

Wie man in meinem folgenden Code sieht, wurde der Timer um 15:20 Uhr pünklich eingeschaltet und hätte um 15:25 Uhr wieder ausgeschaltet werden müssen. Das ist aber nicht geschehen. Jetzt aktuell 16:05 Uhr.

Wenn ich es richtig verstehe, wird ja genau nur 1xMal (um 15:25:00 Uhr) das Ereignis ausgelöst.
Könnte es eventuell sein, dass mein Raspian genau zu dieser Zeit mit anderen Sachen beschäftigt war und deswegen nicht geschaltet wurde? Ich wüsste aber auch nicht genau, wo ich da nachschauen kann...in Logfiles vom Raspi....?

Danke für eure Hilfe
Lars

Code Auswählen Erweitern

define Timer1.GPIO28.schalten WeekdayTimer GPIO28 Mo-So|15:20|on Mo-So|15:25|off
attr Timer1.GPIO28.schalten alias Timer 1: Mo-So 15:20 - 15:25 Uhr
attr Timer1.GPIO28.schalten commandTemplate set $NAME  $EVENT
attr Timer1.GPIO28.schalten devStateIcon active:time_timer on:black_Steckdose.on off:black_Steckdose.off
attr Timer1.GPIO28.schalten disable 0
attr Timer1.GPIO28.schalten group geplante Schaltzeiten GPIO28
attr Timer1.GPIO28.schalten room Schaltautomatik
attr Timer1.GPIO28.schalten switchInThePast 1
attr Timer1.GPIO28.schalten webCmd loeschen

setstate Timer1.GPIO28.schalten on
setstate Timer1.GPIO28.schalten 2017-09-05 15:20:00 currValue on
setstate Timer1.GPIO28.schalten 2017-09-05 15:17:03 disabled 0
setstate Timer1.GPIO28.schalten 2017-09-05 15:20:00 nextUpdate 2017-09-05 15:25:00
setstate Timer1.GPIO28.schalten 2017-09-05 15:20:00 nextValue off
setstate Timer1.GPIO28.schalten 2017-09-05 15:20:00 state on

[Beta-User]

Also offiziell willkommen im Forum...

Das hier deutet eher darauf hin, dass Dein PI ziemlich beschäftigt zu sein scheint:

setstate Timer1.GPIO28.schalten 2017-09-05 15:20:00 nextUpdate 2017-09-05 15:25:00
setstate Timer1.GPIO28.schalten 2017-09-05 15:20:00 nextValue off

(Jedenfalls, wenn das der Stand von 16:05 Uhr war).
Grundsätzlich werden alle fhem-Befehle innerhalb einer einzigen Queue abgearbeitet und auch alle Timer geprüft. Das sieht mir mehr danach aus, dass irgendwas FHEM ziemlich ausbremst (GPIO-Nutzung ist neben schlecht konfiguriertem 1-Wire und Milight_Bridge seit neuestem einer meiner Lieblings-Verdächtigen dafür).

Evtl. mal mit Bordmitteln prüfen, wie es mit der Systemlast aussieht und ob irgendwelche Module zu viel Systemzeit brauchen.

Edit: Mit Bordmitteln waren insbesondere apptime und perfmon gemeint.

Gruß, Beta-User

[Lars721]

Gut, ich werde mal nach Systemlast schauen.

Vielen Dank erst Mal

[Lars721]

Hallo,

ich habe mal apptime ausprobiert. Folgend ist ein Log zu der Zeit als ein Timer auf off hätte geschaltet werden müssen.
Ist daran etwas außergewöhnliches zu sehen?

Code Auswählen Erweitern

name                                     function                               max  count    total  average maxDly TS Max call     param Max call
WEB_xxx.xxx.xx.xx_50758                  FW_Read                                951      5      986   197.20      0 10.09. 11:30:25 HASH(WEB_xxx.xxx.xx.xx_50758)
SpeichernTimer                           FS20_Set                               248      6      248    41.33      0 10.09. 11:22:44 HASH(SpeichernTimer); SpeichernTimer; on
Timer                                    notify_Exec                            241      1      241   241.00      0 10.09. 11:22:44 HASH(Timer); HASH(SpeichernTimer)
tmr-WeekdayTimer_Update                  HASH(0x1a19ab8)                         67      1       67    67.00 85969016 10.09. 11:22:49 HASH(Timer2.GPIO5.schalten_2)
Timer2.GPIO5.schalten                    WeekdayTimer_Attr                       55      6       55     9.17      0 10.09. 11:22:44 set; Timer2.GPIO5.schalten; switchInThePast; 1
GPIO5                                    dummy_Set                               46      3       67    22.33      0 10.09. 11:22:49 HASH(GPIO5); GPIO5; off
tmr-WeekdayTimer_SetTimer                HASH(0x12fa790)                         40      1       40    40.00    643 10.09. 11:22:44 HASH(Timer2.GPIO5.schalten)
WEB_xxx.xxx.xx.xx_50760                  FW_Read                                 35      3       47    15.67      0 10.09. 11:30:15 HASH(WEB_xxx.xxx.xx.xx_50760)
notify_GPIO5                             notify_Exec                             33      2       51    25.50      0 10.09. 11:22:49 HASH(notify_GPIO5); HASH(GPIO5)
tmr-WeekdayTimer_Update                  HASH(0x1946b28)                         31      1       31    31.00      1 10.09. 11:25:00 HASH(Timer2.GPIO5.schalten_1)
tmr-Wunderground_GetStatus               HASH(0x1147540)                         27      2       53    26.50      8 10.09. 11:24:58 HASH(WUweather)
WEB_xxx.xxx.xx.xx_50746                  FW_Read                                 20      3       22     7.33      0 10.09. 11:25:49 HASH(WEB_xxx.xxx.xx.xx_50746)
tmr-DOIF_TimerTrigger                    REF(0x1945348)                          20      1       20    20.00      2 10.09. 11:24:00 REF(0x1945348)
tmr-DOIF_TimerTrigger                    REF(0x1a02230)                          19      1       19    19.00      2 10.09. 11:26:00 REF(0x1a02230)
tmr-DOIF_TimerTrigger                    REF(0x1a125a8)                          19      1       19    19.00      2 10.09. 11:27:00 REF(0x1a125a8)
tmr-DOIF_TimerTrigger                    REF(0x1945bf0)                          15      1       15    15.00      2 10.09. 11:23:00 REF(0x1945bf0)
tmr-DOIF_TimerTrigger                    REF(0x19c1698)                          15      1       15    15.00      2 10.09. 11:28:00 REF(0x19c1698)
tmr-DOIF_TimerTrigger                    REF(0x19d4c10)                          15      1       15    15.00      2 10.09. 11:29:00 REF(0x19d4c10)
tmr-DOIF_TimerTrigger                    REF(0x1a19a88)                          15      1       15    15.00      1 10.09. 11:30:00 REF(0x1a19a88)
Dum_pageswap_D                           dummy_Set                               13      8       17     2.12      0 10.09. 11:22:44 HASH(Dum_pageswap_D); Dum_pageswap_D; /fhem?room=Schaltautomatik
Timer2.GPIO5.disabling                   dummy_Set                               13     13       13     1.00      0 10.09. 11:22:44 HASH(Timer2.GPIO5.disabling); Timer2.GPIO5.disabling; enable

Zusätzlich habe ich den verbose Level auf 5 gesetzt.
Im Logfile kann ich bei nicht ausgeführten Timer-Schaltungen überhaupt keine Einträge zu der jeweiligen Schaltzeit finden.
(Also auch keine Verzögerungen.) Das Verhalten habe ich sowohl auf meinem Raspi 2 als auch auf einem Raspi 3.
Als ständige Aktualisierungen habe ich bei Fhem z.B. auch eine Uhr dessen Zeit alle 60 Sekunden aktualisiert wird und auch Wetterdatenabruf von WeatherUnderground alle 300 Sekunden. Diese Aktualisierungen werden (soweit ich gesehen habe) sekundengenau abgerufen. Deshalb glaube ich nicht an einen ausgelasteten Raspi.
Merkwürdig ist ja auch, dass beim Timer immer nur die "Off" Schaltungen manchmal nicht funktionieren. Die "On" Schaltungen habe zu 100% (soweit ich nachverfolgt hatte) immer funktioniert.

Was kann ich denn noch prüfen?
Auszüge aus den Logdateien kann ich gerne anfügen wenn es hilft.

Vielen Dank für eure Hilfe und einen schönen Sonntag.
Lars

[Lars721]

Hallo,
ich noch mal.

Inzwischen bin ich nun doch der Meinung, dass dieses Verhalten an dem Weekdaytimer Attribut "switchInThePast" liegt.
Wenn ich das Attribut bei meinen Timern nicht benutze, scheint der Fehler bei "Off" nicht mehr aufzutreten.

So ganz verstanden habe ich das Attribut irgendwie nicht. Hauptsächlich war es wohl für das HeatingModul benutzt.
Wenn ein Heizkörper o.ä. bereits eingeschaltet ist wenn man danach einen Timer programmiert wird der Status "on" richtig angezeigt.

Ich dachte, dass ich dann auch Devices nachträglich einschalten kann...
Bei "On" funktioniert es zumindest. Allerdings gibt es dann beim Ausschalten Probleme.

Vielen Dank nochmals.
Lars