[scheduler] Properly handle millis() overflow (#8197)

esphome/const.py

@@ -196,6 +196,7 @@ CONF_DC_PIN = "dc_pin"
 CONF_DEASSERT_RTS_DTR = "deassert_rts_dtr"
 CONF_DEBOUNCE = "debounce"
 CONF_DEBUG = "debug"
+CONF_DEBUG_SCHEDULER = "debug_scheduler"
 CONF_DECAY_MODE = "decay_mode"
 CONF_DECELERATION = "deceleration"
 CONF_DEFAULT_MODE = "default_mode"

esphome/core/component.h

@@ -165,10 +165,17 @@ class Component {
    * This will call f every interval ms. Can be cancelled via CancelInterval().
    * Similar to javascript's setInterval().
    *
-   * IMPORTANT: Do not rely on this having correct timing. This is only called from
-   * loop() and therefore can be significantly delay. If you need exact timing please
+   * IMPORTANT NOTE:
+   * The only guarantee offered by this call is that the callback will be called no *earlier* than
+   * the specified interval after the previous call. Any given interval may be longer due to
+   * other components blocking the loop() call.
+   *
+   * So do not rely on this having correct timing. If you need exact timing please
    * use hardware timers.
    *
+   * Note also that the first call to f will not happen immediately, but after a random delay. This is
+   * intended to prevent many interval functions from being called at the same time.
+   *
    * @param name The identifier for this interval function.
    * @param interval The interval in ms.
    * @param f The function (or lambda) that should be called

esphome/core/config.py

@@ -10,6 +10,7 @@ from esphome.const import (
     CONF_BUILD_PATH,
     CONF_COMMENT,
     CONF_COMPILE_PROCESS_LIMIT,
+    CONF_DEBUG_SCHEDULER,
     CONF_ESPHOME,
     CONF_FRIENDLY_NAME,
     CONF_INCLUDES,
@@ -144,6 +145,7 @@ CONFIG_SCHEMA = cv.All(
             cv.Optional(CONF_INCLUDES, default=[]): cv.ensure_list(valid_include),
             cv.Optional(CONF_LIBRARIES, default=[]): cv.ensure_list(cv.string_strict),
             cv.Optional(CONF_NAME_ADD_MAC_SUFFIX, default=False): cv.boolean,
+            cv.Optional(CONF_DEBUG_SCHEDULER, default=False): cv.boolean,
             cv.Optional(CONF_PROJECT): cv.Schema(
                 {
                     cv.Required(CONF_NAME): cv.All(
@@ -369,6 +371,8 @@ async def to_code(config):
     cg.add_build_flag("-Wno-unused-variable")
     cg.add_build_flag("-Wno-unused-but-set-variable")
     cg.add_build_flag("-Wno-sign-compare")
+    if config[CONF_DEBUG_SCHEDULER]:
+        cg.add_define("ESPHOME_DEBUG_SCHEDULER")
 
     if CORE.using_arduino and not CORE.is_bk72xx:
         CORE.add_job(add_arduino_global_workaround)

esphome/core/defines.h

@@ -13,6 +13,7 @@
 #define ESPHOME_PROJECT_VERSION "v2"
 #define ESPHOME_PROJECT_VERSION_30 "v2"
 #define ESPHOME_VARIANT "ESP32"
+#define ESPHOME_DEBUG_SCHEDULER
 
 // logger
 #define ESPHOME_LOG_LEVEL ESPHOME_LOG_LEVEL_VERY_VERBOSE

esphome/core/scheduler.cpp

@@ -1,4 +1,5 @@
 #include "scheduler.h"
+#include "esphome/core/defines.h"
 #include "esphome/core/log.h"
 #include "esphome/core/helpers.h"
 #include "esphome/core/hal.h"
@@ -21,7 +22,7 @@ static const uint32_t MAX_LOGICALLY_DELETED_ITEMS = 10;
 
 void HOT Scheduler::set_timeout(Component *component, const std::string &name, uint32_t timeout,
                                 std::function<void()> func) {
-  const uint32_t now = this->millis_();
+  const auto now = this->millis_();
 
   if (!name.empty())
     this->cancel_timeout(component, name);
@@ -29,17 +30,16 @@ void HOT Scheduler::set_timeout(Component *component, const std::string &name, u
   if (timeout == SCHEDULER_DONT_RUN)
     return;
 
-  ESP_LOGVV(TAG, "set_timeout(name='%s', timeout=%" PRIu32 ")", name.c_str(), timeout);
-
   auto item = make_unique<SchedulerItem>();
   item->component = component;
   item->name = name;
   item->type = SchedulerItem::TIMEOUT;
-  item->timeout = timeout;
-  item->last_execution = now;
-  item->last_execution_major = this->millis_major_;
+  item->next_execution_ = now + timeout;
   item->callback = std::move(func);
   item->remove = false;
+#ifdef ESPHOME_DEBUG_SCHEDULER
+  ESP_LOGD(TAG, "set_timeout(name='%s/%s', timeout=%" PRIu32 ")", item->get_source(), name.c_str(), timeout);
+#endif
   this->push_(std::move(item));
 }
 bool HOT Scheduler::cancel_timeout(Component *component, const std::string &name) {
@@ -47,7 +47,7 @@ bool HOT Scheduler::cancel_timeout(Component *component, const std::string &name
 }
 void HOT Scheduler::set_interval(Component *component, const std::string &name, uint32_t interval,
                                  std::function<void()> func) {
-  const uint32_t now = this->millis_();
+  const auto now = this->millis_();
 
   if (!name.empty())
     this->cancel_interval(component, name);
@@ -60,19 +60,18 @@ void HOT Scheduler::set_interval(Component *component, const std::string &name,
   if (interval != 0)
     offset = (random_uint32() % interval) / 2;
 
-  ESP_LOGVV(TAG, "set_interval(name='%s', interval=%" PRIu32 ", offset=%" PRIu32 ")", name.c_str(), interval, offset);
-
   auto item = make_unique<SchedulerItem>();
   item->component = component;
   item->name = name;
   item->type = SchedulerItem::INTERVAL;
   item->interval = interval;
-  item->last_execution = now - offset - interval;
-  item->last_execution_major = this->millis_major_;
-  if (item->last_execution > now)
-    item->last_execution_major--;
+  item->next_execution_ = now + offset;
   item->callback = std::move(func);
   item->remove = false;
+#ifdef ESPHOME_DEBUG_SCHEDULER
+  ESP_LOGD(TAG, "set_interval(name='%s/%s', interval=%" PRIu32 ", offset=%" PRIu32 ")", item->get_source(),
+           name.c_str(), interval, offset);
+#endif
   this->push_(std::move(item));
 }
 bool HOT Scheduler::cancel_interval(Component *component, const std::string &name) {
@@ -138,36 +137,36 @@ optional<uint32_t> HOT Scheduler::next_schedule_in() {
   if (this->empty_())
     return {};
   auto &item = this->items_[0];
-  const uint32_t now = this->millis_();
-  uint32_t next_time = item->last_execution + item->interval;
-  if (next_time < now)
+  const auto now = this->millis_();
+  if (item->next_execution_ < now)
     return 0;
-  return next_time - now;
+  return item->next_execution_ - now;
 }
 void HOT Scheduler::call() {
-  const uint32_t now = this->millis_();
+  const auto now = this->millis_();
   this->process_to_add();
 
 #ifdef ESPHOME_DEBUG_SCHEDULER
-  static uint32_t last_print = 0;
+  static uint64_t last_print = 0;
 
   if (now - last_print > 2000) {
     last_print = now;
     std::vector<std::unique_ptr<SchedulerItem>> old_items;
-    ESP_LOGVV(TAG, "Items: count=%u, now=%" PRIu32, this->items_.size(), now);
+    ESP_LOGD(TAG, "Items: count=%u, now=%" PRIu64 " (%u, %" PRIu32 ")", this->items_.size(), now, this->millis_major_,
+             this->last_millis_);
     while (!this->empty_()) {
       this->lock_.lock();
       auto item = std::move(this->items_[0]);
       this->pop_raw_();
       this->lock_.unlock();
 
-      ESP_LOGVV(TAG, "  %s '%s' interval=%" PRIu32 " last_execution=%" PRIu32 " (%u) next=%" PRIu32 " (%u)",
-                item->get_type_str(), item->name.c_str(), item->interval, item->last_execution,
-                item->last_execution_major, item->next_execution(), item->next_execution_major());
+      ESP_LOGD(TAG, "  %s '%s/%s' interval=%" PRIu32 " next_execution in %" PRIu64 "ms at %" PRIu64,
+               item->get_type_str(), item->get_source(), item->name.c_str(), item->interval,
+               item->next_execution_ - now, item->next_execution_);
 
       old_items.push_back(std::move(item));
     }
-    ESP_LOGVV(TAG, "\n");
+    ESP_LOGD(TAG, "\n");
 
     {
       LockGuard guard{this->lock_};
@@ -206,14 +205,10 @@ void HOT Scheduler::call() {
     {
       // Don't copy-by value yet
       auto &item = this->items_[0];
-      if ((now - item->last_execution) < item->interval) {
+      if (item->next_execution_ > now) {
         // Not reached timeout yet, done for this call
         break;
       }
-      uint8_t major = item->next_execution_major();
-      if (this->millis_major_ - major > 1)
-        break;
-
       // Don't run on failed components
       if (item->component != nullptr && item->component->is_failed()) {
         LockGuard guard{this->lock_};
@@ -221,9 +216,10 @@ void HOT Scheduler::call() {
         continue;
       }
 
-#ifdef ESPHOME_LOG_HAS_VERY_VERBOSE
-      ESP_LOGVV(TAG, "Running %s '%s' with interval=%" PRIu32 " last_execution=%" PRIu32 " (now=%" PRIu32 ")",
-                item->get_type_str(), item->name.c_str(), item->interval, item->last_execution, now);
+#ifdef ESPHOME_DEBUG_SCHEDULER
+      ESP_LOGV(TAG, "Running %s '%s/%s' with interval=%" PRIu32 " next_execution=%" PRIu64 " (now=%" PRIu64 ")",
+               item->get_type_str(), item->get_source(), item->name.c_str(), item->interval, item->next_execution_,
+               now);
 #endif
 
       // Warning: During callback(), a lot of stuff can happen, including:
@@ -254,13 +250,7 @@ void HOT Scheduler::call() {
       }
 
       if (item->type == SchedulerItem::INTERVAL) {
-        if (item->interval != 0) {
-          const uint32_t before = item->last_execution;
-          const uint32_t amount = (now - item->last_execution) / item->interval;
-          item->last_execution += amount * item->interval;
-          if (item->last_execution < before)
-            item->last_execution_major++;
-        }
+        item->next_execution_ = now + item->interval;
         this->push_(std::move(item));
       }
     }
@@ -322,43 +312,20 @@ bool HOT Scheduler::cancel_item_(Component *component, const std::string &name,
 
   return ret;
 }
-uint32_t Scheduler::millis_() {
+uint64_t Scheduler::millis_() {
   const uint32_t now = millis();
   if (now < this->last_millis_) {
-    ESP_LOGD(TAG, "Incrementing scheduler major");
     this->millis_major_++;
+    ESP_LOGD(TAG, "Incrementing scheduler major at %" PRIu64 "ms",
+             now + (static_cast<uint64_t>(this->millis_major_) << 32));
   }
   this->last_millis_ = now;
-  return now;
+  return now + (static_cast<uint64_t>(this->millis_major_) << 32);
 }
 
 bool HOT Scheduler::SchedulerItem::cmp(const std::unique_ptr<SchedulerItem> &a,
                                        const std::unique_ptr<SchedulerItem> &b) {
-  // min-heap
-  // return true if *a* will happen after *b*
-  uint32_t a_next_exec = a->next_execution();
-  uint8_t a_next_exec_major = a->next_execution_major();
-  uint32_t b_next_exec = b->next_execution();
-  uint8_t b_next_exec_major = b->next_execution_major();
-
-  if (a_next_exec_major != b_next_exec_major) {
-    // The "major" calculation is quite complicated.
-    // Basically, we need to check if the major value lies in the future or
-    //
-
-    // Here are some cases to think about:
-    // Format: a_major,b_major -> expected result (a-b, b-a)
-    // a=255,b=0 -> false (255, 1)
-    // a=0,b=1 -> false   (255, 1)
-    // a=1,b=0 -> true    (1, 255)
-    // a=0,b=255 -> true  (1, 255)
-
-    uint8_t diff1 = a_next_exec_major - b_next_exec_major;
-    uint8_t diff2 = b_next_exec_major - a_next_exec_major;
-    return diff1 < diff2;
-  }
-
-  return a_next_exec > b_next_exec;
+  return a->next_execution_ > b->next_execution_;
 }
 
 }  // namespace esphome

esphome/core/scheduler.h

@@ -32,23 +32,10 @@ class Scheduler {
     Component *component;
     std::string name;
     enum Type { TIMEOUT, INTERVAL } type;
-    union {
-      uint32_t interval;
-      uint32_t timeout;
-    };
-    uint32_t last_execution;
+    uint32_t interval;
+    uint64_t next_execution_;
     std::function<void()> callback;
     bool remove;
-    uint8_t last_execution_major;
-
-    inline uint32_t next_execution() { return this->last_execution + this->timeout; }
-    inline uint8_t next_execution_major() {
-      uint32_t next_exec = this->next_execution();
-      uint8_t next_exec_major = this->last_execution_major;
-      if (next_exec < this->last_execution)
-        next_exec_major++;
-      return next_exec_major;
-    }
 
     static bool cmp(const std::unique_ptr<SchedulerItem> &a, const std::unique_ptr<SchedulerItem> &b);
     const char *get_type_str() {
@@ -61,9 +48,12 @@ class Scheduler {
           return "";
       }
     }
+    const char *get_source() {
+      return this->component != nullptr ? this->component->get_component_source() : "unknown";
+    }
   };
 
-  uint32_t millis_();
+  uint64_t millis_();
   void cleanup_();
   void pop_raw_();
   void push_(std::unique_ptr<SchedulerItem> item);
@@ -77,7 +67,7 @@ class Scheduler {
   std::vector<std::unique_ptr<SchedulerItem>> items_;
   std::vector<std::unique_ptr<SchedulerItem>> to_add_;
   uint32_t last_millis_{0};
-  uint8_t millis_major_{0};
+  uint16_t millis_major_{0};
   uint32_t to_remove_{0};
 };
 

tests/components/esphome/common.yaml

@@ -0,0 +1,20 @@
+esphome:
+  debug_scheduler: true
+  platformio_options:
+    board_build.flash_mode: dio
+  area: testing
+  on_boot:
+    logger.log: on_boot
+  on_shutdown:
+    logger.log: on_shutdown
+  on_loop:
+    logger.log: on_loop
+  compile_process_limit: 1
+  min_version: "2025.1"
+  name_add_mac_suffix: true
+  project:
+    name: esphome.test
+    version: "1.1"
+    on_update:
+      logger.log: on_update
+

tests/components/esphome/test.esp32-ard.yaml

@@ -0,0 +1,2 @@
+<<: !include common.yaml
+

tests/components/esphome/test.esp32-c3-ard.yaml

@@ -0,0 +1,2 @@
+<<: !include common.yaml
+

tests/components/esphome/test.esp32-c3-idf.yaml

@@ -0,0 +1 @@
+<<: !include common.yaml

tests/components/esphome/test.esp32-idf.yaml

@@ -0,0 +1 @@
+<<: !include common.yaml

tests/components/esphome/test.esp8266-ard.yaml

@@ -0,0 +1 @@
+<<: !include common.yaml

tests/components/esphome/test.host.yaml

@@ -0,0 +1 @@
+<<: !include common.yaml

tests/components/esphome/test.rp2040-ard.yaml

@@ -0,0 +1 @@
+<<: !include common.yaml