Fix precision of time used in timers

Fix a bug where truncation of system time would yield incoherent time measurement, as seen in flappy CI test with Pico. Also fix a bug where late timers would eventually be ignored. Signed-off-by: Paul Guyot <pguyot@kallisys.net>
atomvm · Nov 24, 2023 · 71cab02 · 71cab02
1 parent 0615929
commit 71cab02
Show file tree

Hide file tree

Showing 12 changed files with 116 additions and 47 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -19,10 +19,12 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 - Fixed invalid src_clk error on ESP-IDF >= 5.0
 - Fixed changed default to `AVM_USE_32BIT_FLOAT=on` for STM32 platform to enable use of single precision hardware FPU on F4/F7 devices.
 - Fixed a bug where emscripten `register_*_callback/1` functions would use x[1] as second argument
+- Fixed precision of integers used with timers which could yield to halts and wait times smaller than expected
 
 ### Changed
 
 - Crypto functions on generic_unix platform now rely on MbedTLS instead of OpenSSL
+- Platform function providing time used by timers was changed from `sys_monotonic_millis` to `sys_monotonic_time_u64`, `sys_monotonic_time_u64_to_ms` and `sys_monotonic_time_ms_to_u64`.
 
 ### Added
 

diff --git a/src/libAtomVM/scheduler.c b/src/libAtomVM/scheduler.c
@@ -52,16 +52,20 @@ static int update_timer_list(GlobalContext *global)
         // Do not fetch the current date if there is no timer
         return -1;
     }
-    uint64_t millis_now = sys_monotonic_millis();
-    timer_list_next(tw, millis_now, scheduler_timeout_callback);
+    uint64_t native_now = sys_monotonic_time_u64();
+    timer_list_next(tw, native_now, scheduler_timeout_callback);
     if (tw->next_timer == 0) {
         return -1;
     }
-    uint64_t wait_timeout = tw->next_timer - millis_now;
-    if (wait_timeout > INT_MAX) {
-        wait_timeout = INT_MAX;
+    if (native_now >= tw->next_timer) {
+        return 0;
     }
-    return (int) wait_timeout;
+    uint64_t wait_timeout = tw->next_timer - native_now;
+    uint64_t wait_timeout_ms = sys_monotonic_time_u64_to_ms(wait_timeout);
+    if (wait_timeout_ms > INT_MAX) {
+        wait_timeout_ms = INT_MAX;
+    }
+    return (int) wait_timeout_ms;
 }
 
 Context *scheduler_wait(Context *ctx)
@@ -367,8 +371,8 @@ static void scheduler_timeout_callback(struct TimerListItem *it)
 void scheduler_set_timeout(Context *ctx, avm_int64_t timeout)
 {
     GlobalContext *glb = ctx->global;
-    uint64_t millis_now = sys_monotonic_millis();
-    uint64_t expiry = millis_now + timeout;
+    uint64_t native_now = sys_monotonic_time_u64();
+    uint64_t expiry = native_now + sys_monotonic_time_ms_to_u64(timeout);
 
     context_update_flags(ctx, ~NoFlags, WaitingTimeout);
     struct TimerList *tw = &glb->timer_list;

diff --git a/src/libAtomVM/sys.h b/src/libAtomVM/sys.h
@@ -200,29 +200,43 @@ enum OpenAVMResult sys_open_avm_from_file(
 /**
  * @brief gets wall clock time
  *
- * @details gets system wall clock time.
+ * @details gets system wall clock time, used by `erlang:system_time/1`
  * @param t the timespec that will be updated.
  */
 void sys_time(struct timespec *t);
 
 /**
  * @brief gets monotonic time
  *
- * @details gets monotonic time. Must have the same origin as
- * `sys_monotonic_millis`.
+ * @details gets the time that is used by `erlang:monotonic_time/1`
  * @param t the timespec that will be updated.
  */
 void sys_monotonic_time(struct timespec *t);
 
 /**
- * @brief gets monotonic time in milliseconds.
- * @details This function must have the same origin as `sys_monotonic_time`.
- * The native format depends on platform and this function should be fast as it
- * is used in timers.
+ * @brief gets monotonic time for timers
+ * @details This function must return a non-overflowing counter in the highest
+ * precision the platform permits to make sure that we don't have truncation
+ * errors when compared with sys_time or sys_monotonic_time.
+ * Returning the number of microseconds or nanoseconds since boot would work.
  *
- * @return a monotonic time in milliseconds
+ * @return a monotonic time in a system-chosen unit
  */
-uint64_t sys_monotonic_millis();
+uint64_t sys_monotonic_time_u64();
+
+/**
+ * @brief convert a number of milliseconds to system-chosen unit
+ * @param ms the number of milliseconds to convert
+ * @return the result of the conversion
+ */
+uint64_t sys_monotonic_time_ms_to_u64(uint64_t ms);
+
+/**
+ * @brief convert a number in system-chosen unit to milliseconds
+ * @param t the number to convert
+ * @return the result of the conversion
+ */
+uint64_t sys_monotonic_time_u64_to_ms(uint64_t t);
 
 /**
  * @brief Loads a BEAM module using platform dependent methods.

diff --git a/src/platforms/emscripten/src/lib/sys.c b/src/platforms/emscripten/src/lib/sys.c
@@ -578,11 +578,21 @@ void sys_monotonic_time(struct timespec *t)
     }
 }
 
-uint64_t sys_monotonic_millis()
+uint64_t sys_monotonic_time_u64()
 {
-    struct timespec ts;
-    sys_monotonic_time(&ts);
-    return (ts.tv_nsec / 1000000UL) + (ts.tv_sec * 1000UL);
+    // 2^64/10^9/86400/365 around 585 years
+    double now = emscripten_get_now() * 1000000.0;
+    return (uint64_t) now;
+}
+
+uint64_t sys_monotonic_time_ms_to_u64(uint64_t ms)
+{
+    return ms * 1000000;
+}
+
+uint64_t sys_monotonic_time_u64_to_ms(uint64_t t)
+{
+    return t / 1000000;
 }
 
 static emscripten_fetch_t *fetch_file(const char *url)

diff --git a/src/platforms/esp32/components/avm_sys/sys.c b/src/platforms/esp32/components/avm_sys/sys.c
@@ -167,21 +167,30 @@ void sys_time(struct timespec *t)
     }
 
     t->tv_sec = tv.tv_sec;
-    t->tv_nsec = tv.tv_usec * 1000;
+    t->tv_nsec = (uint_least64_t) tv.tv_usec * 1000;
 }
 
 void sys_monotonic_time(struct timespec *t)
 {
-    int64_t us_since_boot = esp_timer_get_time();
+    uint64_t us_since_boot = (uint64_t) esp_timer_get_time();
 
-    t->tv_sec = us_since_boot / 1000000UL;
-    t->tv_nsec = (us_since_boot % 1000000UL) * 1000UL;
+    t->tv_sec = us_since_boot / 1000000;
+    t->tv_nsec = (us_since_boot % 1000000) * 1000;
 }
 
-uint64_t sys_monotonic_millis()
+uint64_t sys_monotonic_time_u64()
 {
-    int64_t usec = esp_timer_get_time();
-    return usec / 1000UL;
+    return esp_timer_get_time();
+}
+
+uint64_t sys_monotonic_time_ms_to_u64(uint64_t ms)
+{
+    return ms * 1000;
+}
+
+uint64_t sys_monotonic_time_u64_to_ms(uint64_t t)
+{
+    return t / 1000;
 }
 
 void sys_init_platform(GlobalContext *glb)

diff --git a/src/platforms/generic_unix/lib/sys.c b/src/platforms/generic_unix/lib/sys.c
@@ -137,7 +137,7 @@ static inline void sys_poll_events_with_kqueue(GlobalContext *glb, int timeout_m
         ts_ptr = NULL;
     } else {
         ts.tv_sec = timeout_ms / 1000;
-        ts.tv_nsec = (timeout_ms % 1000) * 1000000UL;
+        ts.tv_nsec = (uint_least64_t) (timeout_ms % 1000) * 1000000;
     }
 
     int nbEvents = kevent(platform->kqueue_fd, NULL, 0, notified, poll_count, ts_ptr);
@@ -377,12 +377,23 @@ void sys_monotonic_time(struct timespec *t)
     }
 }
 
-uint64_t sys_monotonic_millis()
+uint64_t sys_monotonic_time_u64()
 {
     // On generic unix, native format is timespec.
     struct timespec ts;
     sys_monotonic_time(&ts);
-    return (ts.tv_nsec / 1000000UL) + (ts.tv_sec * 1000UL);
+    // 2^64/10^9/86400/365 around 585 years
+    return ((uint_least64_t) ts.tv_sec * 1000000000) + ts.tv_nsec;
+}
+
+uint64_t sys_monotonic_time_ms_to_u64(uint64_t ms)
+{
+    return ms * 1000000;
+}
+
+uint64_t sys_monotonic_time_u64_to_ms(uint64_t t)
+{
+    return t / 1000000;
 }
 
 enum OpenAVMResult sys_open_avm_from_file(

diff --git a/src/platforms/rp2040/src/lib/sys.c b/src/platforms/rp2040/src/lib/sys.c
@@ -154,6 +154,8 @@ void sys_poll_events(GlobalContext *glb, int timeout_ms)
         }
         mutex_exit(&platform->event_poll_mutex);
     }
+#else
+    UNUSED(timeout_ms);
 #endif
     queue_t *event = NULL;
     while (queue_try_remove(&platform->event_queue, &event)) {
@@ -203,11 +205,20 @@ void sys_monotonic_time(struct timespec *t)
     t->tv_sec = (usec / 1000000);
 }
 
-uint64_t sys_monotonic_millis()
+uint64_t sys_monotonic_time_u64()
 {
     absolute_time_t now = get_absolute_time();
-    uint64_t usec = to_us_since_boot(now);
-    return usec / 1000;
+    return to_us_since_boot(now);
+}
+
+uint64_t sys_monotonic_time_ms_to_u64(uint64_t ms)
+{
+    return ms * 1000;
+}
+
+uint64_t sys_monotonic_time_u64_to_ms(uint64_t t)
+{
+    return t / 1000;
 }
 
 enum OpenAVMResult sys_open_avm_from_file(

diff --git a/src/platforms/rp2040/tests/package-lock.json b/src/platforms/rp2040/tests/package-lock.json
diff --git a/src/platforms/rp2040/tests/package.json b/src/platforms/rp2040/tests/package.json
@@ -3,7 +3,7 @@
   "description": "Tests using rp2040js emulator",
   "dependencies": {
     "@tsconfig/node20": "^20.1.2",
-    "rp2040js": "^0.19.1",
+    "rp2040js": "^0.19.3",
     "sync-fetch": "^0.5.2",
     "tsx": "^3.12.8",
     "typescript": "^5.2.2",

diff --git a/src/platforms/rp2040/tests/test_erl_sources/test_clocks.erl b/src/platforms/rp2040/tests/test_erl_sources/test_clocks.erl
@@ -34,8 +34,6 @@ start() ->
         true ->
             ok
     end,
-    % give time to the emulator to synchronize rtc time and system time
-    timer:sleep(500),
     test_clock(system_time_after_set_rtc, fun() -> erlang:system_time(millisecond) end),
     NewDate = erlang:universaltime(),
     if

diff --git a/src/platforms/stm32/src/lib/avm_log.h b/src/platforms/stm32/src/lib/avm_log.h
@@ -80,25 +80,25 @@ enum AVMLogLevel
 
 #define AVM_LOGE(tag, format, ...)                                                                                                               \
     do {                                                                                                                                         \
-        uint64_t logtime = sys_monotonic_millis();                                                                                               \
+        uint64_t logtime = sys_monotonic_time_u64();                                                                                             \
         if (LOG_LEVEL_MAX >= LOG_ERROR)                                                                                                          \
             printf(LOG_COLOR_ERROR "ERROR [%llu] %s: " format " (%s:%i)" LOG_RESET_COLOR "\n", logtime, tag, ##__VA_ARGS__, __FILE__, __LINE__); \
     } while (0)
 #define AVM_LOGW(tag, format, ...)                                                                                                    \
     do {                                                                                                                              \
-        uint64_t logtime = sys_monotonic_millis();                                                                                    \
+        uint64_t logtime = sys_monotonic_time_u64();                                                                                  \
         if (LOG_LEVEL_MAX >= LOG_WARN)                                                                                                \
             printf(LOG_COLOR_WARN "WARN [%llu] %s: " format LINE_FORMAT LOG_RESET_COLOR "\n", logtime, tag, ##__VA_ARGS__ LINE_DATA); \
     } while (0)
 #define AVM_LOGI(tag, format, ...)                                                                                                    \
     do {                                                                                                                              \
-        uint64_t logtime = sys_monotonic_millis();                                                                                    \
+        uint64_t logtime = sys_monotonic_time_u64();                                                                                  \
         if (LOG_LEVEL_MAX >= LOG_INFO)                                                                                                \
             printf(LOG_COLOR_INFO "INFO [%llu] %s: " format LINE_FORMAT LOG_RESET_COLOR "\n", logtime, tag, ##__VA_ARGS__ LINE_DATA); \
     } while (0)
 #define AVM_LOGD(tag, format, ...)                                                                                                      \
     do {                                                                                                                                \
-        uint64_t logtime = sys_monotonic_millis();                                                                                      \
+        uint64_t logtime = sys_monotonic_time_u64();                                                                                    \
         if (LOG_LEVEL_MAX >= LOG_DEBUG)                                                                                                 \
             printf(LOG_COLOR_DEBUG "DEBUG [%llu] %s: " format LINE_FORMAT LOG_RESET_COLOR "\n", logtime, tag, ##__VA_ARGS__ LINE_DATA); \
     } while (0)

diff --git a/src/platforms/stm32/src/lib/sys.c b/src/platforms/stm32/src/lib/sys.c
@@ -97,7 +97,7 @@ void sys_tick_handler()
 
 static inline void sys_clock_gettime(struct timespec *t)
 {
-    uint64_t now = sys_monotonic_millis();
+    uint64_t now = sys_monotonic_time_u64();
     t->tv_sec = (time_t) now / 1000;
     t->tv_nsec = ((int32_t) now % 1000) * 1000000;
 }
@@ -221,11 +221,21 @@ void sys_monotonic_time(struct timespec *t)
     sys_clock_gettime(t);
 }
 
-uint64_t sys_monotonic_millis()
+uint64_t sys_monotonic_time_u64()
 {
     return system_millis;
 }
 
+uint64_t sys_monotonic_time_ms_to_u64(uint64_t ms)
+{
+    return ms;
+}
+
+uint64_t sys_monotonic_time_u64_to_ms(uint64_t t)
+{
+    return t;
+}
+
 enum OpenAVMResult sys_open_avm_from_file(
     GlobalContext *global, const char *path, struct AVMPackData **data)
 {