stündliches at mit $hour-Abfrage löst doppelt aus

[roedert]

Zu jeder vollen Stunde führe ich einen Check aus:

Code Auswählen Erweitern

def check at +*01:00:00 {.....}
attr check alignTime 00:00:00
Um 18:00 soll der check jedoch ein wenig mehr machen, deshalb ist im Perl-Code ein if ($hour == 18) hinterlegt.
Das Kuriose ist jedoch, das diese Aktion sowohl um 18:00 als auch um 19:00 ausgeführt wird.
Kann es irgendwie sein, dass die $hour-Variable ein bisschen hinterherhinkt und um genau 19:00:00 noch auf 18 steht?

[rudolfkoenig]

Kannst du bitte ein Log mit "attr glbal mseclog" anfertigen?

[roedert]

Danke, gute Idee. Ich habe jetzt mal eine Zeile Log 1, "if ($hour == 18)" eingefügt ... sieht im Log dann so aus:

Code Auswählen Erweitern

2018.01.16 16:59:32.524 1: if (16 == 18)
Mal schauen was um 18:00 bzw. 19:00 kommt ... die wiederholte Auslösung um 19:00 passiert glaube ich auch nicht immer.

Klar könnte ich den Check auch statt auf der vollen Stunde ein paar Sekunden danach laufen lassen, aber ist schon interessant warum es manchmal zu diesem scheinbaren Fehlverhalten kommt.

[rudolfkoenig]

Das schaut bei dir aber schwer daneben aus, mit aligntime schaut es bei mir so aus:

fhem> def check at +*00:01:00 { Log 1, "Hallo" }
fhem> attr check alignTime 00:00:00
2018.01.16 17:09:00.001 1: Hallo
2018.01.16 17:10:00.001 1: Hallo

Kannst du bitte "list check" hier anhaengen? Relevant ist STATE, TRIGGERTIME und TRIGGERTIME_FMT.

[roedert]

Das schaut bei dir aber schwer daneben aus, mit aligntime schaut es bei mir so aus

Ja, sorry - das war nur ein test mit set execNow auf das at

Der Eintrag ist jetzt korrekt:

Code Auswählen Erweitern

2018.01.16 18:00:01.352 1: if (18 == 18)

List liefert

Code Auswählen Erweitern

   STATE      Next: 19:00:00
   TIMESPEC   01:00:00
   TRIGGERTIME 1516125600
   TRIGGERTIME_FMT 2018-01-16 19:00:00
   TYPE       at

[roedert]

Heute hat mein 18:00-if gar nicht ausgelöst ... und siehe da im Log, es hat sich bestätigt, die $hour-Variable "geht manchmal falsch"

2018.01.17 16:00:01.466 1: if (16 == 18)
2018.01.17 17:00:00.112 1: if (17 == 18)
2018.01.17 18:00:00.017 1: if (17 == 18)
2018.01.17 19:00:00.096 1: if (19 == 18)
2018.01.17 20:00:00.022 1: if (19 == 18)
2018.01.17 21:00:00.026 1: if (21 == 18)
2018.01.17 22:00:00.014 1: if (21 == 18)

[rudolfkoenig]

Aus deinem Log koennte man folgern, dass $hour falsch ist, wenn die Ausgabe weniger als 26 ms nach der bestellten Zeit aufgerufen wird, vmtl. weil der Perl-Ausdruck knapp vor der richtigen Zeit aufgerufen wird.

Moegliche Fehlerursachen:
- at_Exec wird frueher als bestellt aufgerufen. Das kann ich aber nach Studieren von fhem.pl/HandleTimeout() nicht vorstellen, es werden nur die Funktionen aufgerufen, wo "$intAt{$_}{TRIGGERTIME} <= $now", und $now = gettimeofday().
- at ruft InternalTimer mit der falschen Zeit auf: kann ich eigentlich auch ausschliessen, es sollte immer TRIGGERTIME sein. Es waere interessant TRIGGERTIME* beim Ausfuehren der Routine zu sehen, da ist es noch nicht verstellt. Z.Bsp. mit Log 1, $defs{check}{TRIGGERTIME};
- $hour wird "gecached". Laut Code nicht. Kannst du bitte auch $min und $sec ausgeben?
- perl/der Kernel liefert die Zeit nicht linear, aber das will ich mal lieber ausschliessen.

Habe keine weiteren Ideen

[rudolfkoenig]

Hoffentlich ist das Problem identisch mit diesem hier: https://forum.fhem.de/index.php?topic=82991
Und hoffentlich jetzt auch geloest.

[rudolfkoenig]

@roedert: laeuft dein FHEM in einem VM?

Nachtrag: Kannst du bitte auch das Ergebnis der folgenden Befehle hier anhaengen:
cat /sys/devices/system/clocksource/clocksource0/current_clocksource
grep tsc /proc/cpuinfo

[roedert]

Nein, keine VM - ein i3-NUC mit Linux

Mehr Infos Dienstag oder Mittwoch - bin gerade noch im Urlaub

[roedert]

Code Auswählen Erweitern

root@MSIcubi:~# cat /sys/devices/system/clocksource/clocksource0/current_clocksource
tsc
root@MSIcubi:~# grep tsc /proc/cpuinfo
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch arat epb xsaveopt pln pts dtherm tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid rdseed adx smap
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch arat epb xsaveopt pln pts dtherm tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid rdseed adx smap
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch arat epb xsaveopt pln pts dtherm tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid rdseed adx smap
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch arat epb xsaveopt pln pts dtherm tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid rdseed adx smap


[rudolfkoenig]

Danke!

Besteht das Problem noch nach einem update?

[roedert]

Hab gerade ein update gemacht ... ich berichte in ein paar Stunden oder morgen.....

[roedert]

Nach nun ca 24h konnte ich keine Abweichung mehr zwischen der Uhrzeit und $hour mehr feststellen - bei jedem at zur vollen Stunde passte auch $hour.
Nur interessehalber ohne zu tief ins Detail zu gehen ... was hast du geändert?

[rudolfkoenig]

https://forum.fhem.de/index.php/topic,82991.msg752795.html#msg752795

Das Problem von CoolTux war was ganz Anderes, aber da er die gleichen Stichwoerter verwendet hat, habe ich ihn missverstanden und "dein" Bug gefixt