github/esphome
2
0
Fork 0
mirror of https://github.com/esphome/esphome.git synced 2026-09-17 01:58:39 +00:00
Code Issues Packages Projects Releases Wiki Activity

[runtime_stats] Split main loop overhead into before/tail/inter_component

Browse Source 
Adds a second log line per section that breaks overhead down into:
  before          — time in before_loop_tasks_ (scheduler + ISR enable_loop)
  tail            — time in after_loop_tasks_ + trailing record prefix
  inter_component — residual: per-iteration bookkeeping between components
                    (set_current_component, WarnIfComponentBlockingGuard
                    construction/destruction, feed_wdt_with_time, the for
                    loop itself)

Useful for isolating whether per-loop overhead changes come from
scheduler work, loop teardown, or inter-component bookkeeping.
This commit is contained in:
J. Nick Koston
2026-04-14 16:50:27 -10:00
parent 2f14912196
commit 5d2e7a014c
3 changed files with 52 additions and 12 deletions
Download Patch File Download Diff File Expand all files Collapse all files
esphome/components/runtime_stats/runtime_stats.cpp
+14
View File
@@ -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
+26 -10
View File
@@ -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
+12 -2
View File
@@ -879,13 +879,17 @@ inline void ESPHOME_ALWAYS_INLINE Application::before_loop_tasks_(uint32_t loop_
inline void ESPHOME_ALWAYS_INLINE 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();
#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();
#endif
for (this->current_loop_index_ = 0; this->current_loop_index_ < this->looping_components_active_end_;
this->current_loop_index_++) {
@@ -904,13 +908,19 @@ inline void ESPHOME_ALWAYS_INLINE Application::loop() {
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();
global_runtime_stats->record_loop_active(loop_now_us - loop_active_start_us,
loop_before_end_us - loop_active_start_us,
loop_now_us - loop_tail_start_us);
global_runtime_stats->process_pending_stats(last_op_end_time);
}
#endif