[runtime_stats] report tail_us=0 on Phase A-only ticks

Previously loop_tail_start_us defaulted to loop_before_end_us, so on
ticks where Phase B was gated out (loop_interval_ not yet elapsed, no
wake, no high-frequency request) tail_us measured "time from end of
Phase A to stats recording" — i.e. gate-check + stats-prefix overhead —
and was accumulated into the per-tick "tail" bucket even though no
component tail had actually run.

That mis-attributed gate-check + stats-prefix overhead to the tail
metric, which is supposed to represent trailing overhead of the
component phase specifically (after_component_phase_ + the little bit
before record_loop_active). On a device whose loop_interval_ is raised
for power savings, Phase A-only ticks dominate and the mis-attributed
tail would skew the stats report.

Fix: gate the tail_us computation on do_component_phase. Initialize
loop_tail_start_us to 0 (unused on Phase A-only ticks) and only
subtract from loop_now_us when Phase B ran. The overhead that used to
land in "tail" now falls into "residual" (active − before − components
− tail), which is the correct bucket for per-iteration bookkeeping that
is not phase-specific.
This commit is contained in:
J. Nick Koston
2026-04-21 06:22:55 +02:00
parent 66e0c866d7
commit ecdbe0f9bb
2 changed files with 11 additions and 9 deletions
@@ -42,9 +42,9 @@ class RuntimeStatsCollector {
// before_us = time spent in Phase A (scheduler tick) excluding time
// already attributed to per-component stats.
// tail_us = time spent in after_component_phase_ + the trailing record/stats
// prefix. On Phase A-only ticks (component phase gated) this
// is just the small trailing prefix between loop_before_end_us
// and loop_now_us — non-zero but typically a few µs.
// prefix. Only meaningful on component-phase ticks; reported
// as 0 on Phase A-only ticks (no component phase ran, so any
// overhead between Phase A and stats belongs to "residual").
// 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,
+8 -6
View File
@@ -649,10 +649,10 @@ inline void ESPHOME_ALWAYS_INLINE Application::loop() {
#ifdef USE_RUNTIME_STATS
uint32_t loop_before_end_us = micros();
uint64_t loop_before_scheduled_us = ComponentRuntimeStats::global_recorded_us - loop_recorded_snap;
// Default tail_start to end-of-before so tail_us on Phase A-only ticks
// captures only the small gate-check + record_loop_active prefix between
// here and the loop_now_us sample below (not strictly zero, but tiny).
uint32_t loop_tail_start_us = loop_before_end_us;
// Only meaningful when do_component_phase is true; initialized to 0 so the
// tail bucket receives 0 on Phase A-only ticks (no component tail happened,
// the gate-check / stats-prefix overhead belongs to "residual", not "tail").
uint32_t loop_tail_start_us = 0;
#endif
// Gate the component phase on loop_interval_, an active high-frequency
@@ -711,8 +711,10 @@ inline void ESPHOME_ALWAYS_INLINE Application::loop() {
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);
// tail_us is only defined when Phase B ran; 0 on Phase A-only ticks so the
// stats bucket keeps its "component-phase trailing overhead" meaning.
uint32_t loop_tail_us = do_component_phase ? (loop_now_us - loop_tail_start_us) : 0;
global_runtime_stats->record_loop_active(loop_now_us - loop_active_start_us, loop_before_overhead_us, loop_tail_us);
global_runtime_stats->process_pending_stats(now);
}
#endif