diff --git a/esphome/const.py b/esphome/const.py index f3fda8f1d6..5b3d258cc8 100644 --- a/esphome/const.py +++ b/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" diff --git a/esphome/core/component.h b/esphome/core/component.h index a6bd8f81ac..e6ed55efb7 100644 --- a/esphome/core/component.h +++ b/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 diff --git a/esphome/core/config.py b/esphome/core/config.py index f2b8585143..72e9f6a65c 100644 --- a/esphome/core/config.py +++ b/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) diff --git a/esphome/core/defines.h b/esphome/core/defines.h index 7bc84a22dc..50a0847b78 100644 --- a/esphome/core/defines.h +++ b/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 diff --git a/esphome/core/scheduler.cpp b/esphome/core/scheduler.cpp index 012c9af3c6..7e83b3b705 100644 --- a/esphome/core/scheduler.cpp +++ b/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 diff --git a/esphome/core/scheduler.h b/esphome/core/scheduler.h index 44a58f37f5..872a8bd6f6 100644 --- a/esphome/core/scheduler.h +++ b/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}; }; diff --git a/tests/components/esphome/common.yaml b/tests/components/esphome/common.yaml new file mode 100644 index 0000000000..05954e37d7 --- /dev/null +++ b/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 + diff --git a/tests/components/esphome/test.esp32-ard.yaml b/tests/components/esphome/test.esp32-ard.yaml new file mode 100644 index 0000000000..a991f7e15a --- /dev/null +++ b/tests/components/esphome/test.esp32-ard.yaml @@ -0,0 +1,2 @@ +<<: !include common.yaml + diff --git a/tests/components/esphome/test.esp32-c3-ard.yaml b/tests/components/esphome/test.esp32-c3-ard.yaml new file mode 100644 index 0000000000..a991f7e15a --- /dev/null +++ b/tests/components/esphome/test.esp32-c3-ard.yaml @@ -0,0 +1,2 @@ +<<: !include common.yaml + diff --git a/tests/components/esphome/test.esp32-c3-idf.yaml b/tests/components/esphome/test.esp32-c3-idf.yaml new file mode 100644 index 0000000000..dade44d145 --- /dev/null +++ b/tests/components/esphome/test.esp32-c3-idf.yaml @@ -0,0 +1 @@ +<<: !include common.yaml diff --git a/tests/components/esphome/test.esp32-idf.yaml b/tests/components/esphome/test.esp32-idf.yaml new file mode 100644 index 0000000000..dade44d145 --- /dev/null +++ b/tests/components/esphome/test.esp32-idf.yaml @@ -0,0 +1 @@ +<<: !include common.yaml diff --git a/tests/components/esphome/test.esp8266-ard.yaml b/tests/components/esphome/test.esp8266-ard.yaml new file mode 100644 index 0000000000..dade44d145 --- /dev/null +++ b/tests/components/esphome/test.esp8266-ard.yaml @@ -0,0 +1 @@ +<<: !include common.yaml diff --git a/tests/components/esphome/test.host.yaml b/tests/components/esphome/test.host.yaml new file mode 100644 index 0000000000..dade44d145 --- /dev/null +++ b/tests/components/esphome/test.host.yaml @@ -0,0 +1 @@ +<<: !include common.yaml diff --git a/tests/components/esphome/test.rp2040-ard.yaml b/tests/components/esphome/test.rp2040-ard.yaml new file mode 100644 index 0000000000..dade44d145 --- /dev/null +++ b/tests/components/esphome/test.rp2040-ard.yaml @@ -0,0 +1 @@ +<<: !include common.yaml