[runtime_stats] Track main loop active time and report overhead (#15743)

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<double>(active) / static_cast<double>(this->period_active_count_) / 1000.0,
+             static_cast<double>(this->period_active_max_us_) / 1000.0, static_cast<double>(active) / 1000.0,
+             static_cast<double>(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<double>(before) / 1000.0, static_cast<double>(tail) / 1000.0,
+             static_cast<double>(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<double>(active) / static_cast<double>(this->total_active_count_) / 1000.0,
+             static_cast<double>(this->total_active_max_us_) / 1000.0, static_cast<double>(active) / 1000.0,
+             static_cast<double>(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<double>(before) / 1000.0, static_cast<double>(tail) / 1000.0,
+             static_cast<double>(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) {

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

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<uint32_t>(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

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;

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;

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}"
+            )