[runtime_stats] Subtract scheduled-callback time from before bucket

The scheduler also constructs WarnIfComponentBlockingGuard around
scheduled item execution (scheduler.cpp:740), so set_interval /
set_timeout / defer callbacks record into the affected component's
runtime_stats_. Since scheduler.call() runs inside before_loop_tasks_,
that time was double-counted: once in component period/total, once
in the "before" overhead bucket. Observed in the field as
before > overhead_total with inter_component clamped to 0.

Fix: add a global cumulative counter on ComponentRuntimeStats that
record_time() bumps on every guard finish, snapshot it around
before_loop_tasks_, and subtract the delta from the before bucket
before passing it to record_loop_active.
This commit is contained in:
J. Nick Koston
2026-04-14 16:58:03 -10:00
parent 5d2e7a014c
commit a3a531f672
3 changed files with 25 additions and 2 deletions
+13 -2
View File
@@ -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<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);
}
+4
View File
@@ -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;
+8
View File
@@ -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;