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

esphome/components/runtime_stats/runtime_stats.cpp

@@ -70,6 +70,12 @@ void RuntimeStatsCollector::log_stats_() {
              "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);
+    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", before / 1000.0f,
+             tail / 1000.0f, inter / 1000.0f);
   }
 
   // Log total stats since boot (only for active components - idle ones haven't changed)
@@ -96,6 +102,12 @@ void RuntimeStatsCollector::log_stats_() {
              "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);
+    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", before / 1000.0f,
+             tail / 1000.0f, inter / 1000.0f);
   }
 
   // Reset period stats
@@ -105,6 +117,8 @@ void RuntimeStatsCollector::log_stats_() {
   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

@@ -30,18 +30,28 @@ class RuntimeStatsCollector {
   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) {
+  // 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_ += duration_us;
-    if (duration_us > this->period_active_max_us_)
-      this->period_active_max_us_ = duration_us;
+    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_ += duration_us;
-    if (duration_us > this->total_active_max_us_)
-      this->total_active_max_us_ = duration_us;
+    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:
@@ -62,6 +72,12 @@ class RuntimeStatsCollector {
   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

@@ -573,13 +573,23 @@ inline void ESPHOME_ALWAYS_INLINE Application::before_loop_tasks_(uint32_t loop_
 inline void ESPHOME_ALWAYS_INLINE __attribute__((optimize("O2"))) 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).
+  // 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();
 
   this->before_loop_tasks_(last_op_end_time);
+#ifdef USE_RUNTIME_STATS
+  uint32_t loop_before_end_us = micros();
+  uint64_t loop_before_scheduled_us = ComponentRuntimeStats::global_recorded_us_ - loop_recorded_snap;
+#endif
 
   for (this->current_loop_index_ = 0; this->current_loop_index_ < this->looping_components_active_end_;
        this->current_loop_index_++) {
@@ -598,13 +608,24 @@ inline void ESPHOME_ALWAYS_INLINE __attribute__((optimize("O2"))) Application::l
     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) {
-    global_runtime_stats->record_loop_active(micros() - loop_active_start_us);
+    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;