From 5d2e7a014c8f9d388a6bb7298f60c4691805e987 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 14 Apr 2026 16:50:27 -1000 Subject: [PATCH 1/2] [runtime_stats] Split main loop overhead into before/tail/inter_component MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds a second log line per section that breaks overhead down into: before — time in before_loop_tasks_ (scheduler + ISR enable_loop) tail — time in after_loop_tasks_ + trailing record prefix inter_component — residual: per-iteration bookkeeping between components (set_current_component, WarnIfComponentBlockingGuard construction/destruction, feed_wdt_with_time, the for loop itself) Useful for isolating whether per-loop overhead changes come from scheduler work, loop teardown, or inter-component bookkeeping. --- .../runtime_stats/runtime_stats.cpp | 14 ++++++++ .../components/runtime_stats/runtime_stats.h | 36 +++++++++++++------ esphome/core/application.h | 14 ++++++-- 3 files changed, 52 insertions(+), 12 deletions(-) diff --git a/esphome/components/runtime_stats/runtime_stats.cpp b/esphome/components/runtime_stats/runtime_stats.cpp index 17efdad176..d287855429 100644 --- a/esphome/components/runtime_stats/runtime_stats.cpp +++ b/esphome/components/runtime_stats/runtime_stats.cpp @@ -70,6 +70,12 @@ void RuntimeStatsCollector::log_stats_() { "overhead_total=%.1fms", this->period_active_count_, active / (float) this->period_active_count_ / 1000.0f, this->period_active_max_us_ / 1000.0f, active / 1000.0f, overhead / 1000.0f); + uint64_t before = this->period_before_time_us_; + uint64_t tail = this->period_tail_time_us_; + uint64_t accounted = before + tail; + uint64_t inter = overhead > accounted ? overhead - accounted : 0; + ESP_LOGI(TAG, " main_loop_overhead_section: before=%.1fms, tail=%.1fms, inter_component=%.1fms", before / 1000.0f, + tail / 1000.0f, inter / 1000.0f); } // Log total stats since boot (only for active components - idle ones haven't changed) @@ -96,6 +102,12 @@ void RuntimeStatsCollector::log_stats_() { "overhead_total=%.1fms", this->total_active_count_, active / (float) this->total_active_count_ / 1000.0f, this->total_active_max_us_ / 1000.0f, active / 1000.0f, overhead / 1000.0f); + uint64_t before = this->total_before_time_us_; + uint64_t tail = this->total_tail_time_us_; + uint64_t accounted = before + tail; + uint64_t inter = overhead > accounted ? overhead - accounted : 0; + ESP_LOGI(TAG, " main_loop_overhead_section: before=%.1fms, tail=%.1fms, inter_component=%.1fms", before / 1000.0f, + tail / 1000.0f, inter / 1000.0f); } // Reset period stats @@ -105,6 +117,8 @@ void RuntimeStatsCollector::log_stats_() { this->period_active_count_ = 0; this->period_active_time_us_ = 0; this->period_active_max_us_ = 0; + this->period_before_time_us_ = 0; + this->period_tail_time_us_ = 0; } bool RuntimeStatsCollector::compare_period_time(Component *a, Component *b) { diff --git a/esphome/components/runtime_stats/runtime_stats.h b/esphome/components/runtime_stats/runtime_stats.h index 4f0e3bbe1e..82e0fb7c61 100644 --- a/esphome/components/runtime_stats/runtime_stats.h +++ b/esphome/components/runtime_stats/runtime_stats.h @@ -30,18 +30,28 @@ class RuntimeStatsCollector { void process_pending_stats(uint32_t current_time); // Record the wall time of one main loop iteration excluding the yield/sleep. - // Called once per loop from Application::loop(). Overhead (loop machinery, - // scheduler, before/after-loop tasks) is derived at log time as - // (loop_active_time) - (sum of per-component time). - void record_loop_active(uint32_t duration_us) { + // Called once per loop from Application::loop(). + // active_us = total time between loop start and just before yield. + // before_us = time spent in before_loop_tasks_ (scheduler + ISR enable_loop). + // tail_us = time spent in after_loop_tasks_ + the trailing record/stats prefix. + // Residual overhead at log time = active − Σ(component) − before − tail, + // which captures per-iteration inter-component bookkeeping (set_current_component, + // WarnIfComponentBlockingGuard construction/destruction, feed_wdt_with_time calls, + // the for-loop itself). + void record_loop_active(uint32_t active_us, uint32_t before_us, uint32_t tail_us) { this->period_active_count_++; - this->period_active_time_us_ += duration_us; - if (duration_us > this->period_active_max_us_) - this->period_active_max_us_ = duration_us; + this->period_active_time_us_ += active_us; + if (active_us > this->period_active_max_us_) + this->period_active_max_us_ = active_us; this->total_active_count_++; - this->total_active_time_us_ += duration_us; - if (duration_us > this->total_active_max_us_) - this->total_active_max_us_ = duration_us; + this->total_active_time_us_ += active_us; + if (active_us > this->total_active_max_us_) + this->total_active_max_us_ = active_us; + + this->period_before_time_us_ += before_us; + this->total_before_time_us_ += before_us; + this->period_tail_time_us_ += tail_us; + this->total_tail_time_us_ += tail_us; } protected: @@ -62,6 +72,12 @@ class RuntimeStatsCollector { uint64_t total_active_count_{0}; uint64_t total_active_time_us_{0}; uint32_t total_active_max_us_{0}; + + // Split of overhead sections — accumulated per iteration. + uint64_t period_before_time_us_{0}; + uint64_t total_before_time_us_{0}; + uint64_t period_tail_time_us_{0}; + uint64_t total_tail_time_us_{0}; }; } // namespace runtime_stats diff --git a/esphome/core/application.h b/esphome/core/application.h index f015099437..e2701b6ec3 100644 --- a/esphome/core/application.h +++ b/esphome/core/application.h @@ -879,13 +879,17 @@ inline void ESPHOME_ALWAYS_INLINE Application::before_loop_tasks_(uint32_t loop_ inline void ESPHOME_ALWAYS_INLINE Application::loop() { #ifdef USE_RUNTIME_STATS // Capture the start of the active (non-sleeping) portion of this iteration. - // Used to derive main-loop overhead = active time − Σ(component time). + // Used to derive main-loop overhead = active time − Σ(component time) − + // before/tail splits recorded below. uint32_t loop_active_start_us = micros(); #endif // Get the initial loop time at the start uint32_t last_op_end_time = millis(); this->before_loop_tasks_(last_op_end_time); +#ifdef USE_RUNTIME_STATS + uint32_t loop_before_end_us = micros(); +#endif for (this->current_loop_index_ = 0; this->current_loop_index_ < this->looping_components_active_end_; this->current_loop_index_++) { @@ -904,13 +908,19 @@ inline void ESPHOME_ALWAYS_INLINE Application::loop() { this->feed_wdt_with_time(last_op_end_time); } +#ifdef USE_RUNTIME_STATS + uint32_t loop_tail_start_us = micros(); +#endif this->after_loop_tasks_(); #ifdef USE_RUNTIME_STATS // Process any pending runtime stats printing after all components have run // This ensures stats printing doesn't affect component timing measurements if (global_runtime_stats != nullptr) { - global_runtime_stats->record_loop_active(micros() - loop_active_start_us); + uint32_t loop_now_us = micros(); + global_runtime_stats->record_loop_active(loop_now_us - loop_active_start_us, + loop_before_end_us - loop_active_start_us, + loop_now_us - loop_tail_start_us); global_runtime_stats->process_pending_stats(last_op_end_time); } #endif From a3a531f672834b885811700c2c3bcde2822e2c81 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 14 Apr 2026 16:58:03 -1000 Subject: [PATCH 2/2] [runtime_stats] Subtract scheduled-callback time from before bucket The scheduler also constructs WarnIfComponentBlockingGuard around scheduled item execution (scheduler.cpp:740), so set_interval / set_timeout / defer callbacks record into the affected component's runtime_stats_. Since scheduler.call() runs inside before_loop_tasks_, that time was double-counted: once in component period/total, once in the "before" overhead bucket. Observed in the field as before > overhead_total with inter_component clamped to 0. Fix: add a global cumulative counter on ComponentRuntimeStats that record_time() bumps on every guard finish, snapshot it around before_loop_tasks_, and subtract the delta from the before bucket before passing it to record_loop_active. --- esphome/core/application.h | 15 +++++++++++++-- esphome/core/component.cpp | 4 ++++ esphome/core/component.h | 8 ++++++++ 3 files changed, 25 insertions(+), 2 deletions(-) diff --git a/esphome/core/application.h b/esphome/core/application.h index e2701b6ec3..d7c3b441da 100644 --- a/esphome/core/application.h +++ b/esphome/core/application.h @@ -882,6 +882,11 @@ inline void ESPHOME_ALWAYS_INLINE Application::loop() { // Used to derive main-loop overhead = active time − Σ(component time) − // before/tail splits recorded below. uint32_t loop_active_start_us = micros(); + // Snapshot the cumulative component-recorded time so we can subtract the + // slice that the scheduler spends inside its own WarnIfComponentBlockingGuard + // (scheduler.cpp) — that time is already counted in per-component stats, + // so charging it again to "before" would double-count. + uint64_t loop_recorded_snap = ComponentRuntimeStats::global_recorded_us_; #endif // Get the initial loop time at the start uint32_t last_op_end_time = millis(); @@ -889,6 +894,7 @@ inline void ESPHOME_ALWAYS_INLINE Application::loop() { this->before_loop_tasks_(last_op_end_time); #ifdef USE_RUNTIME_STATS uint32_t loop_before_end_us = micros(); + uint64_t loop_before_scheduled_us = ComponentRuntimeStats::global_recorded_us_ - loop_recorded_snap; #endif for (this->current_loop_index_ = 0; this->current_loop_index_ < this->looping_components_active_end_; @@ -918,8 +924,13 @@ inline void ESPHOME_ALWAYS_INLINE Application::loop() { // This ensures stats printing doesn't affect component timing measurements if (global_runtime_stats != nullptr) { uint32_t loop_now_us = micros(); - global_runtime_stats->record_loop_active(loop_now_us - loop_active_start_us, - loop_before_end_us - loop_active_start_us, + // Subtract scheduled-component time from the "before" bucket so it is + // not double-counted (it is already attributed to per-component stats). + uint32_t loop_before_wall_us = loop_before_end_us - loop_active_start_us; + uint32_t loop_before_overhead_us = loop_before_wall_us > loop_before_scheduled_us + ? loop_before_wall_us - static_cast(loop_before_scheduled_us) + : 0; + global_runtime_stats->record_loop_active(loop_now_us - loop_active_start_us, loop_before_overhead_us, loop_now_us - loop_tail_start_us); global_runtime_stats->process_pending_stats(last_op_end_time); } diff --git a/esphome/core/component.cpp b/esphome/core/component.cpp index 8949b4b76d..235903cf7d 100644 --- a/esphome/core/component.cpp +++ b/esphome/core/component.cpp @@ -506,6 +506,10 @@ void PollingComponent::stop_poller() { uint32_t PollingComponent::get_update_interval() const { return this->update_interval_; } +#ifdef USE_RUNTIME_STATS +uint64_t ComponentRuntimeStats::global_recorded_us_ = 0; // NOLINT(cppcoreguidelines-avoid-non-const-global-variables) +#endif + void __attribute__((noinline, cold)) WarnIfComponentBlockingGuard::warn_blocking(Component *component, uint32_t blocking_time) { bool should_warn; diff --git a/esphome/core/component.h b/esphome/core/component.h index 3307c5ae76..648cbda870 100644 --- a/esphome/core/component.h +++ b/esphome/core/component.h @@ -116,6 +116,13 @@ struct ComponentRuntimeStats { uint64_t total_time_us{0}; uint32_t total_max_time_us{0}; + // Cumulative sum of every record_time() duration since boot, across all + // components. Used by Application::loop() to snapshot time spent inside + // WarnIfComponentBlockingGuard (including guards constructed by the + // scheduler at scheduler.cpp) so main-loop overhead accounting can + // subtract scheduled-callback time from the before_loop_tasks_ wall time. + static uint64_t global_recorded_us_; // NOLINT(cppcoreguidelines-avoid-non-const-global-variables) + void record_time(uint32_t duration_us) { this->period_count++; this->period_time_us += duration_us; @@ -125,6 +132,7 @@ struct ComponentRuntimeStats { this->total_time_us += duration_us; if (duration_us > this->total_max_time_us) this->total_max_time_us = duration_us; + global_recorded_us_ += duration_us; } void reset_period() { this->period_count = 0;