diff --git a/esphome/components/runtime_stats/runtime_stats.cpp b/esphome/components/runtime_stats/runtime_stats.cpp index 06714b5a446..9ed141155a5 100644 --- a/esphome/components/runtime_stats/runtime_stats.cpp +++ b/esphome/components/runtime_stats/runtime_stats.cpp @@ -32,40 +32,101 @@ void RuntimeStatsCollector::log_stats_() { " Period stats (last %" PRIu32 "ms): %zu active components", this->log_interval_, count); - if (count == 0) { - return; + // Sum component time so we can derive main-loop overhead + // (active loop time minus time attributable to component loop()s). + // Period sum iterates the active-in-period subset; total sum must iterate + // all components since total_active_time_us_ includes iterations where + // currently-idle components previously ran. + uint64_t period_component_sum_us = 0; + for (size_t i = 0; i < count; i++) { + period_component_sum_us += sorted[i]->runtime_stats_.period_time_us; + } + uint64_t total_component_sum_us = 0; + for (auto *component : components) { + total_component_sum_us += component->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; + // Use double for µs→ms conversion so multi-day uptimes (where total + // microsecond counters exceed float's ~7-digit mantissa) keep resolution. + ESP_LOGI(TAG, + " main_loop: iters=%" PRIu64 ", active_avg=%.3fms, active_max=%.2fms, active_total=%.1fms, " + "overhead_total=%.1fms", + this->period_active_count_, + static_cast(active) / static_cast(this->period_active_count_) / 1000.0, + static_cast(this->period_active_max_us_) / 1000.0, static_cast(active) / 1000.0, + static_cast(overhead) / 1000.0); + 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", + static_cast(before) / 1000.0, static_cast(tail) / 1000.0, + static_cast(inter) / 1000.0); } // 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=%" PRIu64 ", active_avg=%.3fms, active_max=%.2fms, active_total=%.1fms, " + "overhead_total=%.1fms", + this->total_active_count_, + static_cast(active) / static_cast(this->total_active_count_) / 1000.0, + static_cast(this->total_active_max_us_) / 1000.0, static_cast(active) / 1000.0, + static_cast(overhead) / 1000.0); + 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", + static_cast(before) / 1000.0, static_cast(tail) / 1000.0, + static_cast(inter) / 1000.0); } // 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; + 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 3c2c9f78add..82e0fb7c618 100644 --- a/esphome/components/runtime_stats/runtime_stats.h +++ b/esphome/components/runtime_stats/runtime_stats.h @@ -29,6 +29,31 @@ 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(). + // 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_ += 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_ += 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: void log_stats_(); // Static comparators — member functions have friend access, lambdas do not @@ -37,6 +62,22 @@ class RuntimeStatsCollector { uint32_t log_interval_; uint32_t next_log_time_{0}; + + // Main loop active-time stats (wall time per iteration, excluding yield/sleep). + // Counters are uint64_t — at sub-millisecond loop times a uint32_t can wrap in + // a few weeks of uptime, which is well within ESPHome device lifetimes. + uint64_t period_active_count_{0}; + uint64_t period_active_time_us_{0}; + uint32_t period_active_max_us_{0}; + 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 db8af735bd4..19245ab203b 100644 --- a/esphome/core/application.h +++ b/esphome/core/application.h @@ -875,6 +875,17 @@ inline uint32_t ESPHOME_ALWAYS_INLINE Application::before_loop_tasks_(uint32_t l } 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) − + // 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(); @@ -907,12 +918,24 @@ 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) { + uint32_t loop_now_us = micros(); + // 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); } #endif diff --git a/esphome/core/component.cpp b/esphome/core/component.cpp index 8949b4b76dc..e33652482ea 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 9e339dce649..717ca362576 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; diff --git a/tests/integration/test_runtime_stats.py b/tests/integration/test_runtime_stats.py index 9e93035d835..bd7f36341d2 100644 --- a/tests/integration/test_runtime_stats.py +++ b/tests/integration/test_runtime_stats.py @@ -26,6 +26,7 @@ async def test_runtime_stats( # Track component stats component_stats_found = set() + main_loop_lines: list[dict[str, str]] = [] # Patterns to match - need to handle ANSI color codes and timestamps # The log format is: [HH:MM:SS][color codes][I][tag]: message @@ -34,6 +35,14 @@ async def test_runtime_stats( component_pattern = re.compile( r"^\[[^\]]+\].*?\s+([\w.]+):\s+count=(\d+),\s+avg=([\d.]+)ms" ) + # Main loop overhead line emitted by runtime_stats + main_loop_pattern = re.compile( + r"main_loop:\s+iters=(?P\d+),\s+" + r"active_avg=(?P[\d.]+)ms,\s+" + r"active_max=(?P[\d.]+)ms,\s+" + r"active_total=(?P[\d.]+)ms,\s+" + r"overhead_total=(?P[\d.]+)ms" + ) def check_output(line: str) -> None: """Check log output for runtime stats messages.""" @@ -54,6 +63,11 @@ async def test_runtime_stats( component_name = match.group(1) component_stats_found.add(component_name) + # Check for main_loop overhead line + ml_match = main_loop_pattern.search(line) + if ml_match: + main_loop_lines.append(ml_match.groupdict()) + async with ( run_compiled(yaml_config, line_callback=check_output), api_client_connected() as client, @@ -86,3 +100,22 @@ async def test_runtime_stats( assert "template.switch" in component_stats_found, ( f"Expected template.switch stats, found: {component_stats_found}" ) + + # Verify the main_loop overhead line is emitted (at least once for + # the period section and once for the total section, per log cycle). + assert len(main_loop_lines) >= 2, ( + f"Expected at least 2 main_loop lines, got {len(main_loop_lines)}" + ) + for fields in main_loop_lines: + assert int(fields["iters"]) > 0, f"iters should be > 0: {fields}" + assert float(fields["active_total"]) > 0.0, ( + f"active_total should be > 0: {fields}" + ) + assert float(fields["active_avg"]) >= 0.0, ( + f"active_avg should be >= 0: {fields}" + ) + # overhead_total is derived and may be 0 if components dominate, + # but the field must still be present and parseable as a float. + assert float(fields["overhead_total"]) >= 0.0, ( + f"overhead_total should be >= 0: {fields}" + )