[gelöst] at feuert eine Sekunde zu früh

[cb2sela]

Ich bin kürzlich von einem raspi2 auf einen raspi4 umgezogen. Eine jahrelang sauber laufende Routine lief auf einmal nicht mehr wie erwartet und den Grund konnte ich nun identifizieren:
at feuert eine Sekunde zu früh. Das bedeutet u.a., dass ich mich noch in der Stunde 22 befinde, auch wenn der at um 23:00:00 laufen soll. Steps zum Reproduzieren:

in der 99_my_utils.pm eine Routine anlegen:

Code Auswählen Erweitern


sub zeit_test {
my ($sec,$min,$hour,$day,$mon,$year) = localtime();   
Log 1, "Hour, min und sec sind $hour, $min und $sec";
}


Ein at anlegen, z.B.:

Code Auswählen Erweitern


defmod AT_zeit_test at *09:10:00 { zeit_test() }


Warten und dann ins log schauen:

Code Auswählen Erweitern


2022.04.04 09:10:00 1: Hour, min und sec sind 9, 9 und 59


Wie man sieht ist der Timestamp des Logeintrags zwar schon 09:10:00, aber das localtime() innerhalb der Routine liefert noch 09:09:59 Uhr.

[rudolfkoenig]

Habs gerade nachgestellt (mit einer anderen Uhrzeit), konnte aber kein Problem feststellen:

2022.04.04 16:48:00.027 1: Hour, min und sec sind 16, 48 und 0

Da sowas zum erstenmal gemeldet wird, duerfte sich nicht um ein generelles Problem handeln.
Die Funktion wird aus fhem.pl / HandleTimeout() aufgerufen, was fuer alle internen Timer zustaendig ist, und ich sehe da keinen offensichtlichen Fehler.

Was steht in der TRIGGERTIME Internal vor der Ausfuehrung?
Wie schaut die Ausgabe mit "attr global mseclog 1" aus?
Und mit "attr global verbose 5"?

[DetlefR]

Das ist ein Problem auf Multicore Systemen und findett sich unter "TSC" Time Stamp Counter.
Bestenfalls kann man einen 127.0.0.1 Ping mit negativer Laufzeit beobachten.

[Damian]

Du arbeitest mit localtime(), at arbeitet indirekt mit localtime(gettimeofday()) - da kann schon mal die Zeit auseinander laufen.

Gib mal in der Kommandozeile in deinem System ein:

Code Auswählen Erweitern

{time()." ". gettimeofday()}

und vergleiche beide Ergebnisse.

[Otto123]

Also nur aus Interesse heute morgen und jetzt

Code Auswählen Erweitern

2022.04.04 10:10:00 1: Hour, min und sec sind 10, 9 und 59

Code Auswählen Erweitern

2022.04.04 20:08:00 1: Hour, min und sec sind 20, 7 und 59

Und Damians Code liefert

1649095777.77512 1649095777.77512

Auf einem Pi3 ...

Also falls es was zu Testen gibt?

Die Ausgabe nach Rudis Wunsch - da passt es.

Code Auswählen Erweitern

2022.04.04 20:22:00.273 5: exec at command AT_zeit_test
2022.04.04 20:22:00.273 5: Cmd: >{ zeit_test() }<
2022.04.04 20:22:00.274 1: Hour, min und sec sind 20, 22 und 0
2022.04.04 20:22:00.274 5: redefine at command AT_zeit_test as *20:22:00 { zeit_test() }

[Damian]

siehe: https://forum.fhem.de/index.php/topic,27292.msg204685.html#msg204685

[rudolfkoenig]

Ich habe die Funktion etwas erweitert:

Code Auswählen Erweitern

sub zeit_test {
  my $ts = "GT:".gettimeofday()." T:".time();
  my ($sec,$min,$hour,$day,$mon,$year) = localtime();
  Log 1, "Hour, min und sec sind $hour, $min und $sec / $ts";
}

und ich habe die Zeit-Spezifikation in der at Definition auf +*00:00:10 geaendert, mit "attr AT_zeit_test alignTime 00:00"
Ergebnis:

2022.04.04 21:34:10.005 1: Hour, min und sec sind 21, 34 und 10 / GT:1649100850.00597 T:1649100850
2022.04.04 21:34:20.009 1: Hour, min und sec sind 21, 34 und 20 / GT:1649100860.00938 T:1649100860
2022.04.04 21:34:30.000 1: Hour, min und sec sind 21, 34 und 29 / GT:1649100870.00069 T:1649100869
2022.04.04 21:34:40.000 1: Hour, min und sec sind 21, 34 und 39 / GT:1649100880.00071 T:1649100879
2022.04.04 21:34:50.000 1: Hour, min und sec sind 21, 34 und 49 / GT:1649100890.00068 T:1649100889

localtime ohne Argument ruft time() auf, ich folgere daraus, dass time() und gettimeofday() nicht synchron laufen.

Da der FHEM-Interne Timer gettimeofday verwendet, empfehle ich an relevanten Stellen immer mit gettimeofday zu arbeiten, z.Bsp. localtime(gettimeofday()).

Ich habe jetzt 'ne Weile gesucht, um die Begruendung dafuer zu finden, ohne Ergebnis.
Wenn jemand mich aufklaeren kann, bin ich dankbar.

[xenos1984]

Ich habe jetzt 'ne Weile gesucht, um die Begruendung dafuer zu finden, ohne Ergebnis.
Wenn jemand mich aufklaeren kann, bin ich dankbar.

Kann es das sein?

NOTE 1: This higher resolution timer can return values either less or more than the core time(), depending on whether your platform rounds the higher resolution timer values up, down, or to the nearest second to get the core time(), but naturally the difference should be never more than half a second. See also "clock_getres", if available in your system.

http://perldoc.perl.org/Time::HiRes

[cb2sela]

Danke für die hilfreichen Rückmeldungen. Bei mir liefert damians code auch eine Abweichung.

Code Auswählen Erweitern


1649143330 1649143330.68915


gettimeofday hatte ich bisher nie verwendet, aber da es aus Time::HiRes kommt sind Abweichungen zu erwarten.

Ich habe jetzt meine Zeit-Ermittlung wie von Rudi beschrieben auf localtime(gettimeofday()) umgestellt und damit läufts.

[rudolfkoenig]

@xenos1984: Die Doku habe ich auch gelesen, allerdings bezieht sie sich auf Time::HiRes::time, und diesen haben wir nicht importiert.
Wenn ich sie explizit verwende, dann kriege ich exakt die gleichen Werte wie bei gettimeofday.
Auch die beschriebene Rundung kommt mir unpassend vor: ich kriege nur dann abweichende Werte, wenn die Routine weniger als 1ms nach dem Zeitpunkt aufgerufen wird, so als ob time() konstant 1ms hinter gettimeofday() waere.
"the difference should be never more than half a second" stimmt auch nicht.

Soweit ich sehe, wird fuers Zeitholen kein syscall verwendet (weder bei time, noch bei gettimeofday), d.h. der Timer ist im Userspace ablesbar, und offensichtlich verwendet "time aus perl" und Time::HiRes unterschiedliche Timer.
@DetelfR hat auf Probleme bei TSC auf Multicore hingewiesen, dagegen spricht mAn, dass gettimeofday oefters auszulesen (scheinbar?) konsistent ist.

Wenn in fhem.pl nicht nur gettimeofday, sondern auch time von Time::HiRes geholt wird, dann kann ich das Problem nicht wiederholen, offensichtlich verwendet localtime() dann auch Time::HiRes::time. Allerdings liefert das Original keine Nachkommastellen, was zu Nebeneffekten fuehren koennte. Auf der anderen Seite enthalten bereits 17 Module "use Time::HiRes qw( time )", d.h. ein Einbau in fhem.pl wuerde die Sache nur konsistent fuer alle machen.

Zusammengefasst:
- time aus perl "direkt", und  Time::HiRes::gettimeofday sind nicht synchron
- Time::HiRes::time ist synchron mit  Time::HiRes::gettimeofday, und wird bereits von 17 Modulen importiert

=> Ich habe fhem.pl erweitert, time kommt ab sofort fuer alle aus Time::HiRes

[xenos1984]

@xenos1984: Die Doku habe ich auch gelesen, allerdings bezieht sie sich auf Time::HiRes::time, und diesen haben wir nicht importiert.

Ich hatte es so verstanden, dass die Doku mit the core time() die Perl-Standard time() meint, und dass gettimeofday() davon abweichen kann, weil es i.A. einen anderen Timer benutzt.

[Sidey]

.
Allerdings liefert das Original keine Nachkommastellen, was zu Nebeneffekten fuehren koennte.

Ich melde hier den Nebeneffekt an. Hat jetzt einiges an Zeit gekostet um dahinter zu kommen, dass eine Berechnung eines durchschnittlichen Windwertes nicht mehr stimmt weil time jetzt float und nicht mehr int liefert.

Irgendwie blöde, die Time Funktion aus dem Code zu überschreiben.


Grüße Sidey

[rudolfkoenig]

Irgendwie blöde, die Time Funktion aus dem Code zu überschreiben.

Ich bin auch nicht begeistert, aber wenigstens ist die aktuelle Loesung gleich fuer alle, unabhaengig davon, wer welche Module einsetzt.