search

cesanta / mongoose-os

Mongoose OS - an IoT Firmware Development Framework. Supported microcontrollers: ESP32, ESP8266, CC3220, CC3200, STM32F4, STM32L4, STM32F7. Amazon AWS IoT, Microsoft Azure, Google IoT Core integrated. Code in C or JavaScript.
https://mongoose-os.com
Other
2.49k stars 430 forks source link

Fix timer created in MGOS_EVENT_TIME_CHANGED handler never gets fired #474

Closed nliviu closed 4 years ago

nliviu commented 5 years ago

Timer created in MGOS_EVENT_TIME_CHANGED handler never gets fired:

[Jan 16 11:35:51.226] mgos_sntp_ev         SNTP reply from 216.239.35.4: time 1547631352.057400, local 4.872570, delta 1547631347.184830
[Jan 16 11:35:51.231] sntp_time_change_cb  delta=1547631347.172553
[Jan 16 11:35:51.238] timer_create         timer_create - timer2 interval=12000, id=0x3ffbba08
[Jan 16 11:35:51.243] mgos_time_change_cb  delta=1547631347.172553
[Jan 16 11:35:51.252] mgos_time_change_cb  ti=0x3ffbba08 - next_invocation=3095262711.234699 (was 1547631364.062146)
[Jan 16 11:35:51.260] mgos_time_change_cb  ti=0x3ffc7f1c - next_invocation=1547631353.766591 (was 6.594038)
[Jan 16 11:35:51.268] mgos_time_change_cb  ti=0x3ffc8578 - next_invocation=1547631358.592369 (was 11.419816)
[Jan 16 11:35:57.769] timer1_cb            timer1_cb - timer1 interval=11000, id=0x3ffc8578

After:

[Jan 16 11:55:05.606] mgos_sntp_ev         SNTP reply from 216.239.35.4: time 1547632506.382546, local 4.820541, delta 1547632501.562005
[Jan 16 11:55:05.611] sntp_time_change_cb  delta=1547632501.549685
[Jan 16 11:55:05.618] timer_create         timer_create - timer2 interval=12000, id=0x3ffbb2e4
[Jan 16 11:55:05.623] mgos_time_change_cb  delta=1547632501.549685
[Jan 16 11:55:05.632] mgos_time_change_cb  ti=0x3ffbb2e4 - next_invocation=1547632518.387334 (was 1547632518.387334)
[Jan 16 11:55:05.640] mgos_time_change_cb  ti=0x3ffc7f1c - next_invocation=1547632508.176424 (was 6.626739)
[Jan 16 11:55:05.649] mgos_time_change_cb  ti=0x3ffc8578 - next_invocation=1547632512.970347 (was 11.420662)
[Jan 16 11:55:12.202] timer1_cb            timer1_cb - timer1 interval=11000, id=0x3ffc8578
[Jan 16 11:55:17.619] timer2_cb            timer2_cb - timer2 interval=12000, id=0x3ffbb2e4
rojer commented 5 years ago

so, the problem is that correction gets applied twice to the timer created in the callback. however, the solution is not correct because it won't work on subsequent time syncs, when time is adjusted by smaller amounts.

nliviu commented 5 years ago

Ahhh, missed that. I removed logging too early :( Correction:

    /* 1547596800 is Wed Jan 16 00:00:00 UTC 2019 */
    if(ev_data->delta > 1547596800){
      if(ti->next_invocation < 1547596800){
        ti->next_invocation += ev_data->delta;
      }
    }else{
      ti->next_invocation += ev_data->delta;
    }

Test:

[Jan 16 14:36:31.476] mgos_time_change_cb  delta=1547642187.376304
[Jan 16 14:36:31.486] mgos_time_change_cb  ti=0x3ffbba08 - next_invocation=1547642204.321447 (was 1547642204.321447, diff 0.000000)
[Jan 16 14:36:31.497] mgos_time_change_cb  ti=0x3ffc7e98 - next_invocation=1547642194.179967 (was 6.803663, diff 1547642187.376304)
[Jan 16 14:36:31.508] mgos_time_change_cb  ti=0x3ffc84f4 - next_invocation=1547642198.799379 (was 11.423075, diff 1547642187.376304)
[Jan 16 14:36:37.949] timer1_cb            timer1_cb - timer1 interval=11000, id=0x3ffc84f4
[Jan 16 14:36:43.473] timer2_cb            timer2_cb - timer2 interval=12000, id=0x3ffbba08
...
[Jan 16 14:38:41.703] mgos_sntp_query      SNTP query to time.google.com
[Jan 16 14:38:41.796] mgos_sntp_ev         SNTP reply from 216.239.35.0: time 1547642322.390497, local 1547642322.640506, delta -0.250009
[Jan 16 14:38:41.801] sntp_time_change_cb  delta=-0.262503
[Jan 16 14:38:41.805] mgos_time_change_cb  delta=-0.262503
[Jan 16 14:38:41.815] mgos_time_change_cb  ti=0x3ffbd84c - next_invocation=1547642436.106490 (was 1547642436.368993, diff -0.262503)
[Jan 16 14:38:41.826] mgos_time_change_cb  ti=0x3ffbba08 - next_invocation=1547642324.058944 (was 1547642324.321447, diff -0.262503)
[Jan 16 14:38:41.836] mgos_time_change_cb  ti=0x3ffc84f4 - next_invocation=1547642330.536876 (was 1547642330.799379, diff -0.262503)
[Jan 16 14:38:43.473] timer2_cb            timer2_cb - timer2 interval=12000, id=0x3ffbba08
[Jan 16 14:38:49.951] timer1_cb            timer1_cb - timer1 interval=11000, id=0x3ffc84f4
[Jan 16 14:38:55.473] timer2_cb            timer2_cb - timer2 interval=12000, id=0x3ffbba08

was is ti->next_invocation before the if

rojer commented 5 years ago

so, upon further musing on this, i still don't quite like the solution. it takes care of the initial big jump in time, but the problem - double correction - is still there. it still affects timers created from time change callbacks.

the underlying problem is that what we really need for timers is a stable monotonic clock but wall time tends to jump around, sometimes by huge amounts (initial setting). so, today i worked on a change that adds high precision, monotonic clock to all platforms - mgos_uptime_micros() (will be submitted soon). we should make mongoose use that for timers. it will require no adjustment and therefore will also fix this bug.

so, i'm not going to merge this PR and will leave it open instead, and will close it when the timer refactoring happens.

nliviu commented 5 years ago

Great ideea to implement a monotonic clock.