From e93f49978b2858003239e87a470e6d4caf8b24c4 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 14 Apr 2026 16:19:12 -1000 Subject: [PATCH] [runtime_stats] Track main loop active time and report overhead Records per-iteration active wall time (excluding yield/sleep) and reports it alongside the component table. Overhead is computed at log time as active_total minus the sum of per-component time, exposing time spent in scheduler dispatch, before/after-loop tasks, and other loop machinery not attributed to any component. --- .../runtime_stats/runtime_stats.cpp | 72 ++++++++++++++----- .../components/runtime_stats/runtime_stats.h | 23 ++++++ esphome/core/application.h | 6 ++ 3 files changed, 82 insertions(+), 19 deletions(-) diff --git a/esphome/components/runtime_stats/runtime_stats.cpp b/esphome/components/runtime_stats/runtime_stats.cpp index 06714b5a44..82c38c80c4 100644 --- a/esphome/components/runtime_stats/runtime_stats.cpp +++ b/esphome/components/runtime_stats/runtime_stats.cpp @@ -32,40 +32,74 @@ void RuntimeStatsCollector::log_stats_() { " Period stats (last %" PRIu32 "ms): %zu active components", this->log_interval_, count); - if (count == 0) { - return; + // Sum component period time so we can derive main-loop overhead + // (active loop time minus time attributable to component loop()s). + uint64_t period_component_sum_us = 0; + uint64_t total_component_sum_us = 0; + for (size_t i = 0; i < count; i++) { + period_component_sum_us += sorted[i]->runtime_stats_.period_time_us; + total_component_sum_us += sorted[i]->runtime_stats_.total_time_us; } - // Sort by period runtime (descending) - std::sort(sorted, sorted + count, compare_period_time); + if (count > 0) { + // Sort by period runtime (descending) + std::sort(sorted, sorted + count, compare_period_time); - // Log top components by period runtime - for (size_t i = 0; i < count; i++) { - const auto &stats = sorted[i]->runtime_stats_; - ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.3fms, max=%.2fms, total=%.1fms", - LOG_STR_ARG(sorted[i]->get_component_log_str()), stats.period_count, - stats.period_count > 0 ? stats.period_time_us / (float) stats.period_count / 1000.0f : 0.0f, - stats.period_max_time_us / 1000.0f, stats.period_time_us / 1000.0f); + // Log top components by period runtime + for (size_t i = 0; i < count; i++) { + const auto &stats = sorted[i]->runtime_stats_; + ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.3fms, max=%.2fms, total=%.1fms", + LOG_STR_ARG(sorted[i]->get_component_log_str()), stats.period_count, + stats.period_count > 0 ? stats.period_time_us / (float) stats.period_count / 1000.0f : 0.0f, + stats.period_max_time_us / 1000.0f, stats.period_time_us / 1000.0f); + } + } + + // Main-loop overhead for the period: active wall time minus component time. + // active = sum of per-iteration loop time excluding yield/sleep. + if (this->period_active_count_ > 0) { + uint64_t active = this->period_active_time_us_; + uint64_t overhead = active > period_component_sum_us ? active - period_component_sum_us : 0; + ESP_LOGI(TAG, + " main_loop: iters=%" PRIu32 ", active_avg=%.3fms, active_max=%.2fms, active_total=%.1fms, " + "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); } // Log total stats since boot (only for active components - idle ones haven't changed) ESP_LOGI(TAG, " Total stats (since boot): %zu active components", count); - // Re-sort by total runtime for all-time stats - std::sort(sorted, sorted + count, compare_total_time); + if (count > 0) { + // Re-sort by total runtime for all-time stats + std::sort(sorted, sorted + count, compare_total_time); - for (size_t i = 0; i < count; i++) { - const auto &stats = sorted[i]->runtime_stats_; - ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.3fms, max=%.2fms, total=%.1fms", - LOG_STR_ARG(sorted[i]->get_component_log_str()), stats.total_count, - stats.total_count > 0 ? stats.total_time_us / (float) stats.total_count / 1000.0f : 0.0f, - stats.total_max_time_us / 1000.0f, stats.total_time_us / 1000.0); + for (size_t i = 0; i < count; i++) { + const auto &stats = sorted[i]->runtime_stats_; + ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.3fms, max=%.2fms, total=%.1fms", + LOG_STR_ARG(sorted[i]->get_component_log_str()), stats.total_count, + stats.total_count > 0 ? stats.total_time_us / (float) stats.total_count / 1000.0f : 0.0f, + stats.total_max_time_us / 1000.0f, stats.total_time_us / 1000.0); + } + } + + if (this->total_active_count_ > 0) { + uint64_t active = this->total_active_time_us_; + uint64_t overhead = active > total_component_sum_us ? active - total_component_sum_us : 0; + ESP_LOGI(TAG, + " main_loop: iters=%" PRIu32 ", active_avg=%.3fms, active_max=%.2fms, active_total=%.1fms, " + "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); } // Reset period stats for (auto *component : components) { component->runtime_stats_.reset_period(); } + this->period_active_count_ = 0; + this->period_active_time_us_ = 0; + this->period_active_max_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 3c2c9f78ad..24534d222a 100644 --- a/esphome/components/runtime_stats/runtime_stats.h +++ b/esphome/components/runtime_stats/runtime_stats.h @@ -29,6 +29,21 @@ class RuntimeStatsCollector { // Process any pending stats printing (should be called after component loop) 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) { + 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->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; + } + protected: void log_stats_(); // Static comparators — member functions have friend access, lambdas do not @@ -37,6 +52,14 @@ class RuntimeStatsCollector { uint32_t log_interval_; uint32_t next_log_time_{0}; + + // Main loop active-time stats (wall time per iteration, excluding yield/sleep) + uint32_t period_active_count_{0}; + uint64_t period_active_time_us_{0}; + uint32_t period_active_max_us_{0}; + uint32_t total_active_count_{0}; + uint64_t total_active_time_us_{0}; + uint32_t total_active_max_us_{0}; }; } // namespace runtime_stats diff --git a/esphome/core/application.h b/esphome/core/application.h index 60087d527d..f015099437 100644 --- a/esphome/core/application.h +++ b/esphome/core/application.h @@ -877,6 +877,11 @@ 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). + uint32_t loop_active_start_us = micros(); +#endif // Get the initial loop time at the start uint32_t last_op_end_time = millis(); @@ -905,6 +910,7 @@ inline void ESPHOME_ALWAYS_INLINE Application::loop() { // 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); global_runtime_stats->process_pending_stats(last_op_end_time); } #endif