diff --git a/esphome/core/application.h b/esphome/core/application.h index e2701b6ec3b..d7c3b441da2 100644 --- a/esphome/core/application.h +++ b/esphome/core/application.h @@ -882,6 +882,11 @@ inline void ESPHOME_ALWAYS_INLINE Application::loop() { // 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(); @@ -889,6 +894,7 @@ inline void ESPHOME_ALWAYS_INLINE Application::loop() { 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_; @@ -918,8 +924,13 @@ inline void ESPHOME_ALWAYS_INLINE Application::loop() { // This ensures stats printing doesn't affect component timing measurements if (global_runtime_stats != nullptr) { uint32_t loop_now_us = micros(); - global_runtime_stats->record_loop_active(loop_now_us - loop_active_start_us, - loop_before_end_us - loop_active_start_us, + // 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(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); } diff --git a/esphome/core/component.cpp b/esphome/core/component.cpp index 8949b4b76dc..235903cf7d4 100644 --- a/esphome/core/component.cpp +++ b/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; diff --git a/esphome/core/component.h b/esphome/core/component.h index 3307c5ae76e..648cbda870c 100644 --- a/esphome/core/component.h +++ b/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;