diff --git a/esphome/components/runtime_stats/runtime_stats.cpp b/esphome/components/runtime_stats/runtime_stats.cpp index 410695da04..d9fa22d949 100644 --- a/esphome/components/runtime_stats/runtime_stats.cpp +++ b/esphome/components/runtime_stats/runtime_stats.cpp @@ -13,12 +13,12 @@ RuntimeStatsCollector::RuntimeStatsCollector() : log_interval_(60000), next_log_ global_runtime_stats = this; } -void RuntimeStatsCollector::record_component_time(Component *component, uint32_t duration_ms, uint32_t current_time) { +void RuntimeStatsCollector::record_component_time(Component *component, uint32_t duration_us, uint32_t current_time) { if (component == nullptr) return; // Record stats using component pointer as key - this->component_stats_[component].record_time(duration_ms); + this->component_stats_[component].record_time(duration_us); if (this->next_log_time_ == 0) { this->next_log_time_ = current_time + this->log_interval_; @@ -58,15 +58,16 @@ void RuntimeStatsCollector::log_stats_() { // Sort by period runtime (descending) std::sort(sorted, sorted + count, [this](Component *a, Component *b) { - return this->component_stats_[a].get_period_time_ms() > this->component_stats_[b].get_period_time_ms(); + return this->component_stats_[a].get_period_time_us() > this->component_stats_[b].get_period_time_us(); }); // Log top components by period runtime for (size_t i = 0; i < count; i++) { const auto &stats = this->component_stats_[sorted[i]]; - ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", - LOG_STR_ARG(sorted[i]->get_component_log_str()), stats.get_period_count(), stats.get_period_avg_time_ms(), - stats.get_period_max_time_ms(), stats.get_period_time_ms()); + ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.3fms, max=%.2fms, total=%.1fms", + LOG_STR_ARG(sorted[i]->get_component_log_str()), stats.get_period_count(), + stats.get_period_avg_time_us() / 1000.0f, stats.get_period_max_time_us() / 1000.0f, + stats.get_period_time_us() / 1000.0f); } // Log total stats since boot (only for active components - idle ones haven't changed) @@ -74,14 +75,15 @@ void RuntimeStatsCollector::log_stats_() { // Re-sort by total runtime for all-time stats std::sort(sorted, sorted + count, [this](Component *a, Component *b) { - return this->component_stats_[a].get_total_time_ms() > this->component_stats_[b].get_total_time_ms(); + return this->component_stats_[a].get_total_time_us() > this->component_stats_[b].get_total_time_us(); }); for (size_t i = 0; i < count; i++) { const auto &stats = this->component_stats_[sorted[i]]; - ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", - LOG_STR_ARG(sorted[i]->get_component_log_str()), stats.get_total_count(), stats.get_total_avg_time_ms(), - stats.get_total_max_time_ms(), stats.get_total_time_ms()); + ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.3fms, max=%.2fms, total=%.1fms", + LOG_STR_ARG(sorted[i]->get_component_log_str()), stats.get_total_count(), + stats.get_total_avg_time_us() / 1000.0f, stats.get_total_max_time_us() / 1000.0f, + stats.get_total_time_us() / 1000.0); } } diff --git a/esphome/components/runtime_stats/runtime_stats.h b/esphome/components/runtime_stats/runtime_stats.h index c7fea7474b..0847529720 100644 --- a/esphome/components/runtime_stats/runtime_stats.h +++ b/esphome/components/runtime_stats/runtime_stats.h @@ -22,58 +22,58 @@ class ComponentRuntimeStats { public: ComponentRuntimeStats() : period_count_(0), - period_time_ms_(0), - period_max_time_ms_(0), + period_time_us_(0), + period_max_time_us_(0), total_count_(0), - total_time_ms_(0), - total_max_time_ms_(0) {} + total_time_us_(0), + total_max_time_us_(0) {} - void record_time(uint32_t duration_ms) { + void record_time(uint32_t duration_us) { // Update period counters this->period_count_++; - this->period_time_ms_ += duration_ms; - if (duration_ms > this->period_max_time_ms_) - this->period_max_time_ms_ = duration_ms; + this->period_time_us_ += duration_us; + if (duration_us > this->period_max_time_us_) + this->period_max_time_us_ = duration_us; - // Update total counters + // Update total counters (uint64_t to avoid overflow — uint32_t would overflow after ~10 hours) this->total_count_++; - this->total_time_ms_ += duration_ms; - if (duration_ms > this->total_max_time_ms_) - this->total_max_time_ms_ = duration_ms; + this->total_time_us_ += duration_us; + if (duration_us > this->total_max_time_us_) + this->total_max_time_us_ = duration_us; } void reset_period_stats() { this->period_count_ = 0; - this->period_time_ms_ = 0; - this->period_max_time_ms_ = 0; + this->period_time_us_ = 0; + this->period_max_time_us_ = 0; } // Period stats (reset each logging interval) uint32_t get_period_count() const { return this->period_count_; } - uint32_t get_period_time_ms() const { return this->period_time_ms_; } - uint32_t get_period_max_time_ms() const { return this->period_max_time_ms_; } - float get_period_avg_time_ms() const { - return this->period_count_ > 0 ? this->period_time_ms_ / static_cast(this->period_count_) : 0.0f; + uint32_t get_period_time_us() const { return this->period_time_us_; } + uint32_t get_period_max_time_us() const { return this->period_max_time_us_; } + float get_period_avg_time_us() const { + return this->period_count_ > 0 ? this->period_time_us_ / static_cast(this->period_count_) : 0.0f; } - // Total stats (persistent until reboot) + // Total stats (persistent until reboot, uint64_t to avoid overflow) uint32_t get_total_count() const { return this->total_count_; } - uint32_t get_total_time_ms() const { return this->total_time_ms_; } - uint32_t get_total_max_time_ms() const { return this->total_max_time_ms_; } - float get_total_avg_time_ms() const { - return this->total_count_ > 0 ? this->total_time_ms_ / static_cast(this->total_count_) : 0.0f; + uint64_t get_total_time_us() const { return this->total_time_us_; } + uint32_t get_total_max_time_us() const { return this->total_max_time_us_; } + float get_total_avg_time_us() const { + return this->total_count_ > 0 ? this->total_time_us_ / static_cast(this->total_count_) : 0.0f; } protected: // Period stats (reset each logging interval) uint32_t period_count_; - uint32_t period_time_ms_; - uint32_t period_max_time_ms_; + uint32_t period_time_us_; + uint32_t period_max_time_us_; // Total stats (persistent until reboot) uint32_t total_count_; - uint32_t total_time_ms_; - uint32_t total_max_time_ms_; + uint64_t total_time_us_; + uint32_t total_max_time_us_; }; class RuntimeStatsCollector { @@ -83,7 +83,7 @@ class RuntimeStatsCollector { void set_log_interval(uint32_t log_interval) { this->log_interval_ = log_interval; } uint32_t get_log_interval() const { return this->log_interval_; } - void record_component_time(Component *component, uint32_t duration_ms, uint32_t current_time); + void record_component_time(Component *component, uint32_t duration_us, uint32_t current_time); // Process any pending stats printing (should be called after component loop) void process_pending_stats(uint32_t current_time); diff --git a/esphome/core/component.cpp b/esphome/core/component.cpp index 4ccc747819..8c2c8d38e8 100644 --- a/esphome/core/component.cpp +++ b/esphome/core/component.cpp @@ -529,9 +529,12 @@ uint32_t WarnIfComponentBlockingGuard::finish() { uint32_t curr_time = millis(); uint32_t blocking_time = curr_time - this->started_; #ifdef USE_RUNTIME_STATS - // Record component runtime stats + // Use micros() for accurate sub-millisecond timing. millis() has insufficient + // resolution — most components complete in microseconds but millis() only has + // 1ms granularity, so results were essentially random noise. if (global_runtime_stats != nullptr) { - global_runtime_stats->record_component_time(this->component_, blocking_time, curr_time); + uint32_t duration_us = micros() - this->started_us_; + global_runtime_stats->record_component_time(this->component_, duration_us, curr_time); } #endif if (blocking_time > WARN_IF_BLOCKING_OVER_MS) { diff --git a/esphome/core/component.h b/esphome/core/component.h index e5127b0c9f..59222dc4f4 100644 --- a/esphome/core/component.h +++ b/esphome/core/component.h @@ -563,10 +563,21 @@ class PollingComponent : public Component { uint32_t update_interval_; }; +#ifdef USE_RUNTIME_STATS +uint32_t micros(); // Forward declare for inline constructor +#endif + class WarnIfComponentBlockingGuard { public: WarnIfComponentBlockingGuard(Component *component, uint32_t start_time) - : started_(start_time), component_(component) {} + : started_(start_time), + component_(component) +#ifdef USE_RUNTIME_STATS + , + started_us_(micros()) +#endif + { + } // Finish the timing operation and return the current time uint32_t finish(); @@ -576,6 +587,9 @@ class WarnIfComponentBlockingGuard { protected: uint32_t started_; Component *component_; +#ifdef USE_RUNTIME_STATS + uint32_t started_us_; +#endif }; // Function to clear setup priority overrides after all components are set up