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

esphome/components/runtime_stats/runtime_stats.cpp

@@ -32,40 +32,74 @@ void RuntimeStatsCollector::log_stats_() {
            " Period stats (last %" PRIu32 "ms): %zu active components",
            this->log_interval_, count);
 
-  if (count == 0) {
-    return;
+  // Sum component period time so we can derive main-loop overhead
+  // (active loop time minus time attributable to component loop()s).
+  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;
   }
 
-  // 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;
+    ESP_LOGI(TAG,
+             "  main_loop: iters=%" PRIu32 ", 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);
   }
 
   // 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=%" PRIu32 ", 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);
   }
 
   // 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;
 }
 
 bool RuntimeStatsCollector::compare_period_time(Component *a, Component *b) {

esphome/components/runtime_stats/runtime_stats.h

@@ -29,6 +29,21 @@ 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(). Overhead (loop machinery,
+  // scheduler, before/after-loop tasks) is derived at log time as
+  // (loop_active_time) - (sum of per-component time).
+  void record_loop_active(uint32_t duration_us) {
+    this->period_active_count_++;
+    this->period_active_time_us_ += duration_us;
+    if (duration_us > this->period_active_max_us_)
+      this->period_active_max_us_ = duration_us;
+    this->total_active_count_++;
+    this->total_active_time_us_ += duration_us;
+    if (duration_us > this->total_active_max_us_)
+      this->total_active_max_us_ = duration_us;
+  }
+
  protected:
   void log_stats_();
   // Static comparators — member functions have friend access, lambdas do not
@@ -37,6 +52,14 @@ 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};
+  uint64_t period_active_time_us_{0};
+  uint32_t period_active_max_us_{0};
+  uint32_t total_active_count_{0};
+  uint64_t total_active_time_us_{0};
+  uint32_t total_active_max_us_{0};
 };
 
 }  // namespace runtime_stats

esphome/core/application.h

@@ -569,10 +569,14 @@ inline void ESPHOME_ALWAYS_INLINE Application::before_loop_tasks_(uint32_t loop_
   this->in_loop_ = true;
 }
 
+<<<<<<< HEAD
 // NOLINTNEXTLINE(clang-diagnostic-unknown-attributes)
 inline void ESPHOME_ALWAYS_INLINE __attribute__((optimize("O2"))) Application::loop() {
-  uint8_t new_app_state = 0;
-
+#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).
+  uint32_t loop_active_start_us = micros();
+#endif
   // Get the initial loop time at the start
   uint32_t last_op_end_time = millis();
 
@@ -601,6 +605,7 @@ inline void ESPHOME_ALWAYS_INLINE __attribute__((optimize("O2"))) Application::l
   // 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) {
+    global_runtime_stats->record_loop_active(micros() - loop_active_start_us);
     global_runtime_stats->process_pending_stats(last_op_end_time);
   }
 #endif