From 2f1491219676c931efdf7c9badf53136c6249885 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 14 Apr 2026 16:33:39 -1000 Subject: [PATCH] [runtime_stats] Widen iteration counters, fix overhead total, test main_loop line - Widen period/total iteration counters to uint64_t to avoid wrapping on long-running high-frequency loops. - Compute total component-time sum over all components (not just the period-active subset) so total overhead is not inflated by components that ran earlier but are idle now. - Extend integration test to parse the main_loop line and validate the iters/active_avg/active_total/overhead_total fields. --- .../runtime_stats/runtime_stats.cpp | 15 ++++++--- .../components/runtime_stats/runtime_stats.h | 8 +++-- tests/integration/test_runtime_stats.py | 33 +++++++++++++++++++ 3 files changed, 48 insertions(+), 8 deletions(-) diff --git a/esphome/components/runtime_stats/runtime_stats.cpp b/esphome/components/runtime_stats/runtime_stats.cpp index 82c38c80c4..17efdad176 100644 --- a/esphome/components/runtime_stats/runtime_stats.cpp +++ b/esphome/components/runtime_stats/runtime_stats.cpp @@ -32,13 +32,18 @@ void RuntimeStatsCollector::log_stats_() { " Period stats (last %" PRIu32 "ms): %zu active components", this->log_interval_, count); - // Sum component period time so we can derive main-loop overhead + // 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; - 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; + } + uint64_t total_component_sum_us = 0; + for (auto *component : components) { + total_component_sum_us += component->runtime_stats_.total_time_us; } if (count > 0) { @@ -61,7 +66,7 @@ void RuntimeStatsCollector::log_stats_() { 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, " + " main_loop: iters=%" PRIu64 ", 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); @@ -87,7 +92,7 @@ void RuntimeStatsCollector::log_stats_() { 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, " + " main_loop: iters=%" PRIu64 ", 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); diff --git a/esphome/components/runtime_stats/runtime_stats.h b/esphome/components/runtime_stats/runtime_stats.h index 24534d222a..4f0e3bbe1e 100644 --- a/esphome/components/runtime_stats/runtime_stats.h +++ b/esphome/components/runtime_stats/runtime_stats.h @@ -53,11 +53,13 @@ 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}; + // 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}; - uint32_t total_active_count_{0}; + uint64_t total_active_count_{0}; uint64_t total_active_time_us_{0}; uint32_t total_active_max_us_{0}; }; diff --git a/tests/integration/test_runtime_stats.py b/tests/integration/test_runtime_stats.py index 9e93035d83..bd7f36341d 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}" + )