Merge remote-tracking branch 'upstream/runtime-stats-loop-overhead' into integration

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);

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};
 };

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<iters>\d+),\s+"
+        r"active_avg=(?P<active_avg>[\d.]+)ms,\s+"
+        r"active_max=(?P<active_max>[\d.]+)ms,\s+"
+        r"active_total=(?P<active_total>[\d.]+)ms,\s+"
+        r"overhead_total=(?P<overhead_total>[\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}"
+            )