InternalTimer um 00:00:00

Begonnen von Loredo, 12 Juni 2019, 10:28:13

Vorheriges Thema - Nächstes Thema

Loredo

Hallo Rudi,


beim setzen von InternalTimer mit einer Zeit um Mitternacht fällt mir auf, dass diese immer erst exakt 2 Sekunden später ausgeführt werden.
In InternalTimer() und HandleTimeout() konnte ich keinen Grund dafür finden, hast du eine Idee für dieses Verhalten? Soll das die Peak Systemlast zu der Zeit reduzieren (man kann ja annehmen, dass das Hostsystem selbst zu der Zeit auch so einiges zu tun hat)?

Die Forumsuche hat mir auch nichts zu Tage befördert; in %intAt steht der von mir gesetzte Wert drin, nicht jener +2sec.


Gruß
Julian
Hat meine Arbeit dir geholfen? ⟹ https://paypal.me/pools/c/8gDLrIWrG9

Maintainer:
FHEM-Docker Image, https://github.com/fhem, Astro(Co-Maintainer), ENIGMA2, GEOFANCY, GUEST, HP1000, Installer, LaMetric2, MSG, msgConfig, npmjs, PET, PHTV, Pushover, RESIDENTS, ROOMMATE, search, THINKINGCLEANER

rudolfkoenig

Zitatbeim setzen von InternalTimer mit einer Zeit um Mitternacht fällt mir auf, dass diese immer erst exakt 2 Sekunden später ausgeführt werden.
Mir ist kein Mechanismus bewusst, was dieses Verhalten verursachen koennte.
Ich wuerde mit "fhemdebug timerList" pruefen, welche Funktionen um Mitternacht ausgefuehrt werden, evtl. ist einer von diesen Funktionen CPU-Intensiv. und blockiert die anderen.

Loredo

"fhemdebug timerList" zeigt hier wie gesagt 00:00:00 an, so wie erwartet:




2019-06-13 09:52:24.00000 FW_closeInactiveClients
2019-06-13 10:47:41.53170 Weather_GetUpdate
2019-06-13 22:12:45.00000 at_Exec
2019-06-13 22:12:45.17691 Twilight_fireEvent
2019-06-13 23:11:59.18561 Twilight_fireEvent
2019-06-14 00:00:00.00000 FHEM::Astro::Update
2019-06-14 00:00:01.00000 FileLog_dailySwitch
2019-06-14 00:00:01.19949 Twilight_Midnight
2019-06-14 04:42:51.00000 at_Exec



Es lässt sich auch mit fhem.cfg.demo reproduzieren (zugegeben nur mit Umstellung der Systemzeit, wenn man nicht warten will), da blockiert AFAIK nichts.


:(


Ist jetzt sicherlich nicht höchst dramatisch, aber eben seltsam.


Könnte es etwas mit FileLog_dailySwitch zu tun haben?
Hat meine Arbeit dir geholfen? ⟹ https://paypal.me/pools/c/8gDLrIWrG9

Maintainer:
FHEM-Docker Image, https://github.com/fhem, Astro(Co-Maintainer), ENIGMA2, GEOFANCY, GUEST, HP1000, Installer, LaMetric2, MSG, msgConfig, npmjs, PET, PHTV, Pushover, RESIDENTS, ROOMMATE, search, THINKINGCLEANER

rudolfkoenig

Ich habe die Uhr auf 2019-06-12 23:55 gestellt, "perl fhem.pl fhem.cfg.demo" gestartet, und ein at definiert:

fhem> define midnightAt at 00:00 { Log 1, "Bing!" } 

fhem> fhemdebug timerList
2019-06-12 23:58:15.00000 FW_closeInactiveClients
2019-06-12 23:58:32.20107 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.20239 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.20330 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.20418 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.20502 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.20586 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.20672 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.20743 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.20814 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.20884 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.20940 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.21008 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.21083 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.21147 RESIDENTStk_DurationTimer
2019-06-12 23:58:32.21200 RESIDENTStk_DurationTimer
2019-06-13 00:00:00.00000 at_Exec
2019-06-13 00:00:01.00000 FileLog_dailySwitch
2019-06-13 00:56:17.39050 Weather_GetUpdate
2019-06-13 00:56:46.37771 Weather_GetUpdate
2019-06-13 04:30:59.00000 at_Exec
2019-06-13 22:19:53.00000 at_Exec


Im Log steht um "Mitternacht":
2019.06.13 00:00:00.006 1: Bing!
Ich sehe das Problem noch nicht.


Off-Topic:
ich habe in fhem.cfg.demo eine telnet Instanz hinzugefuegt, und "attr rg_Guest4 subType minor" entfernt, da sonst beim Starten eine Warnung kam (configfile: invalid value minor)

Loredo


Ich habe mein Problem nicht genau genug beschrieben, da fehlt vielleicht noch eine entscheidende Info:Also was ich konkret sehe ist, dass die geschriebenen Readings, für die die Berechnung um 00:00:00 angestoßen werden (sollten), mit einem Timestamp exakt 2 Sek später geschrieben werden, die Berechnung jedoch zu anderen Tageszeiten keine 2 Sekunden dauert, sondern unter einer Sekunde bleibt und demnach der Timestamp des Readings auch wie erwartet auf der entsprechenden Triggerzeit steht.


Ich teste auch nochmal mit einem Logeintrag zusätzlich.


Zitat von: rudolfkoenig am 13 Juni 2019, 10:21:24
Off-Topic:
ich habe in fhem.cfg.demo eine telnet Instanz hinzugefuegt, und "attr rg_Guest4 subType minor" entfernt, da sonst beim Starten eine Warnung kam (configfile: invalid value minor)


Die Telnet Instanz verwirrt mich jetzt (so ist das wohl bei OT  ;D ), aber danke für den Hinweis mit dem subType - der hat sich tatsächlich nochmals geändert und sollte dort "childcare" heißen und ich hatte es vergessen anzupassen.
Hat meine Arbeit dir geholfen? ⟹ https://paypal.me/pools/c/8gDLrIWrG9

Maintainer:
FHEM-Docker Image, https://github.com/fhem, Astro(Co-Maintainer), ENIGMA2, GEOFANCY, GUEST, HP1000, Installer, LaMetric2, MSG, msgConfig, npmjs, PET, PHTV, Pushover, RESIDENTS, ROOMMATE, search, THINKINGCLEANER

Beta-User

Weiß nicht, ob das hier reinpaßt:

A) Hat hier (bzgl. twilight) jemand berichtet, dass er auch (genau) 2 Sekunden Versatz hat bzw. dann auch einen Doppeleffekt: https://forum.fhem.de/index.php/topic,95281.msg952875.html#msg952875

und

B) kann ich selbst ganz ähnliches beobachten, was die durch AutoShuttersControl angelegten Timer angeht; die entsprechenden Einträge wurden jeweils ebenfalls genau 2 Sek. nach Mitternacht erstellt (wenn erforderlich, kann ich dazu noch weitere Infos liefern, komme nur grade nicht auf die Maschine bzw. muß das vermutlich morgens checken).
(Mein Umfeld: ziemlich aktuelles FHEM (letzter update So oder Mo), recht aktuelles i386-Debian-Stretch auf einem single-core-Atom.)

Bitte um Info, wenn ich sonst was dazu liefern kann, was weiterhilft.
Server: HP-elitedesk@Debian 12, aktuelles FHEM@ConfigDB | CUL_HM (VCCU) | MQTT2: MiLight@ESP-GW, BT@OpenMQTTGw | MySensors: seriell, v.a. 2.3.1@RS485 | ZWave | ZigBee@deCONZ | SIGNALduino | MapleCUN | RHASSPY
svn: u.a MySensors, Weekday-&RandomTimer, Twilight,  div. attrTemplate-files

rudolfkoenig

A) Das Doppeleffekt ist normal: at bestimmt den naechsten Ausfuehrungszeitpunk nach dem ausfuehren der Aktuellen. Mit "einfachen" Sonnenaufgangszeiten gibt es zw. 21.6 und 21.12 Probleme, und mit Sonnenuntergang zw. 21.12 und 21.6. Aus diesem Grund sollte man sunrise()/sunset() verwenden und _nicht_ sunrise_abs()/sunset_abs(), weil die ohne _abs dieses Problem kennen, und automatisch 24 Stunden addieren (bzw. die Zeiten fuer den naechsten Tag berechnen).

B). Ich brauche dafuer mindestens ein "attr global verbose 5" log.

Beta-User

Zitat von: rudolfkoenig am 26 Juni 2019, 17:46:18
A) Das Doppeleffekt ist normal: at bestimmt den naechsten Ausfuehrungszeitpunk nach dem ausfuehren der Aktuellen. Mit "einfachen" Sonnenaufgangszeiten gibt es zw. 21.6 und 21.12 Probleme, und mit Sonnenuntergang zw. 21.12 und 21.6. Aus diesem Grund sollte man sunrise()/sunset() verwenden und _nicht_ sunrise_abs()/sunset_abs(), weil die ohne _abs dieses Problem kennen, und automatisch 24 Stunden addieren (bzw. die Zeiten fuer den naechsten Tag berechnen).

B). Ich brauche dafuer mindestens ein "attr global verbose 5" log.
Hmm, lustig...

Vermutlich hat ASC dann das von CoolTux hier als gelöst beschriebene Verhalten immer noch...
Zitat von: CoolTux am 26 Juni 2019, 17:23:55
Mit der Yahoo API wird das nichts zu tun haben. Wird wohl zweimal berechnet  warum auch immer.
Hatte das selbe Problem wie ich AutoShuttersControl entwickelt habe . Kannst Du übrigens zum steuern nehmen.
(Ich habe das auf einen sunrise/sunset-Mode laufen, was dann vermutlich sunrise_EL im Hintergrund verwendet und werde das dann bei Gelegenheit dort weiter verfolgen).

Was aber echt irritiert: Wieso sind das ganz genau diese 2 Sekunden Versatz? (Ich habe jedenfalls nie was anderes beobachtet, es war aber auch nicht soooo wichtig, hat ja funktioniert...)
Server: HP-elitedesk@Debian 12, aktuelles FHEM@ConfigDB | CUL_HM (VCCU) | MQTT2: MiLight@ESP-GW, BT@OpenMQTTGw | MySensors: seriell, v.a. 2.3.1@RS485 | ZWave | ZigBee@deCONZ | SIGNALduino | MapleCUN | RHASSPY
svn: u.a MySensors, Weekday-&RandomTimer, Twilight,  div. attrTemplate-files

rudolfkoenig

ZitatWas aber echt irritiert: Wieso sind das ganz genau diese 2 Sekunden Versatz?
Weil an den beobachteten Tagen die Sonnenauf/untergangszeiten sich um 2 Sekunden von heute auf morgen verschieben?

Beta-User

 ;D ;D Das wäre für unsere breiten aber sehr zufällig...Oder rechne ich da falsch?
Server: HP-elitedesk@Debian 12, aktuelles FHEM@ConfigDB | CUL_HM (VCCU) | MQTT2: MiLight@ESP-GW, BT@OpenMQTTGw | MySensors: seriell, v.a. 2.3.1@RS485 | ZWave | ZigBee@deCONZ | SIGNALduino | MapleCUN | RHASSPY
svn: u.a MySensors, Weekday-&RandomTimer, Twilight,  div. attrTemplate-files