From 89fca4f446aea83c1de4b9eac6750ecb3bdd1ab0 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 23 Apr 2026 06:01:08 -0500 Subject: [PATCH] merge --- .../runtime_stats/runtime_stats.cpp | 21 +++++++++++++++++++ .../components/runtime_stats/runtime_stats.h | 12 ++++++++++- esphome/core/application.cpp | 3 +++ 3 files changed, 35 insertions(+), 1 deletion(-) diff --git a/esphome/components/runtime_stats/runtime_stats.cpp b/esphome/components/runtime_stats/runtime_stats.cpp index d733394b78..26571a4054 100644 --- a/esphome/components/runtime_stats/runtime_stats.cpp +++ b/esphome/components/runtime_stats/runtime_stats.cpp @@ -81,6 +81,19 @@ void RuntimeStatsCollector::log_stats_() { ESP_LOGI(TAG, " main_loop_overhead_section: before=%.1fms, tail=%.1fms, inter_component=%.1fms", static_cast(before) / 1000.0, static_cast(tail) / 1000.0, static_cast(inter) / 1000.0); + uint64_t sched = this->period_before_sched_time_us_; + uint64_t wdt = this->period_before_wdt_time_us_; + uint64_t before_residual = before > sched + wdt ? before - sched - wdt : 0; + ESP_LOGI(TAG, " main_loop_before_breakdown: sched=%.1fms, wdt=%.1fms, residual=%.1fms", + static_cast(sched) / 1000.0, static_cast(wdt) / 1000.0, + static_cast(before_residual) / 1000.0); + uint32_t wdt_slow_hits = App.wdt_slow_count_; + App.wdt_slow_count_ = 0; + ESP_LOGI(TAG, " wdt_slow_path: hits=%" PRIu32 " (%.1f%% of iters, avg=%.2fus/hit)", wdt_slow_hits, + this->period_active_count_ > 0 + ? 100.0 * static_cast(wdt_slow_hits) / static_cast(this->period_active_count_) + : 0.0, + wdt_slow_hits > 0 ? static_cast(wdt) / static_cast(wdt_slow_hits) : 0.0); } // Log total stats since boot (only for active components - idle ones haven't changed) @@ -116,6 +129,12 @@ void RuntimeStatsCollector::log_stats_() { ESP_LOGI(TAG, " main_loop_overhead_section: before=%.1fms, tail=%.1fms, inter_component=%.1fms", static_cast(before) / 1000.0, static_cast(tail) / 1000.0, static_cast(inter) / 1000.0); + uint64_t sched = this->total_before_sched_time_us_; + uint64_t wdt = this->total_before_wdt_time_us_; + uint64_t before_residual = before > sched + wdt ? before - sched - wdt : 0; + ESP_LOGI(TAG, " main_loop_before_breakdown: sched=%.1fms, wdt=%.1fms, residual=%.1fms", + static_cast(sched) / 1000.0, static_cast(wdt) / 1000.0, + static_cast(before_residual) / 1000.0); } // Reset period stats @@ -126,6 +145,8 @@ void RuntimeStatsCollector::log_stats_() { this->period_active_time_us_ = 0; this->period_active_max_us_ = 0; this->period_before_time_us_ = 0; + this->period_before_sched_time_us_ = 0; + this->period_before_wdt_time_us_ = 0; this->period_tail_time_us_ = 0; } diff --git a/esphome/components/runtime_stats/runtime_stats.h b/esphome/components/runtime_stats/runtime_stats.h index 888d48e672..68409fbbfe 100644 --- a/esphome/components/runtime_stats/runtime_stats.h +++ b/esphome/components/runtime_stats/runtime_stats.h @@ -49,7 +49,8 @@ class RuntimeStatsCollector { // 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) { + void record_loop_active(uint32_t active_us, uint32_t before_us, uint32_t sched_us, uint32_t wdt_us, + uint32_t tail_us) { this->period_active_count_++; this->period_active_time_us_ += active_us; if (active_us > this->period_active_max_us_) @@ -61,6 +62,10 @@ class RuntimeStatsCollector { this->period_before_time_us_ += before_us; this->total_before_time_us_ += before_us; + this->period_before_sched_time_us_ += sched_us; + this->total_before_sched_time_us_ += sched_us; + this->period_before_wdt_time_us_ += wdt_us; + this->total_before_wdt_time_us_ += wdt_us; this->period_tail_time_us_ += tail_us; this->total_tail_time_us_ += tail_us; } @@ -88,6 +93,11 @@ class RuntimeStatsCollector { // Split of overhead sections — accumulated per iteration. uint64_t period_before_time_us_{0}; uint64_t total_before_time_us_{0}; + // Sub-split of `before` into scheduler_tick_ vs. post-scheduler feed_wdt_with_time. + uint64_t period_before_sched_time_us_{0}; + uint64_t total_before_sched_time_us_{0}; + uint64_t period_before_wdt_time_us_{0}; + uint64_t total_before_wdt_time_us_{0}; uint64_t period_tail_time_us_{0}; uint64_t total_tail_time_us_{0}; }; diff --git a/esphome/core/application.cpp b/esphome/core/application.cpp index d03696fbb6..c390b26cd4 100644 --- a/esphome/core/application.cpp +++ b/esphome/core/application.cpp @@ -210,6 +210,9 @@ void HOT Application::feed_wdt_slow_(uint32_t time) { // confirmed the WDT_FEED_INTERVAL_MS rate limit was exceeded. arch_feed_wdt(); this->last_wdt_feed_ = time; +#ifdef USE_RUNTIME_STATS + this->wdt_slow_count_++; +#endif } #ifdef USE_STATUS_LED