[runtime_stats] Use micros() for accurate per-component timing

The previous millis()-based timing had insufficient resolution. Most
components complete their loop() in microseconds, but millis() only
has 1ms granularity. Components taking <1ms would show either 0ms or
1ms depending on whether a millisecond boundary happened to tick over
during execution — essentially random noise rather than useful data.

Switch to self-timed micros() per guard (only when USE_RUNTIME_STATS
is compiled in — zero cost in production builds). Track internally in
microseconds, display in milliseconds with fractional precision.

Use uint64_t for total_time_us_ to avoid overflow (uint32_t would wrap
after ~10 hours at typical loop rates).

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);
   }
 }
 

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<float>(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<float>(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<float>(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<float>(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);

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) {

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