Merge branch 'runtime-stats-micros-timing' into integration

esphome/__main__.py

@@ -23,6 +23,7 @@ import esphome.codegen as cg
 from esphome.config import iter_component_configs, read_config, strip_default_ids
 from esphome.const import (
     ALLOWED_NAME_CHARS,
+    ARGUMENT_HELP_DEVICE,
     CONF_API,
     CONF_BAUD_RATE,
     CONF_BROKER,
@@ -1367,7 +1368,7 @@ def parse_args(argv):
     parser_upload.add_argument(
         "--device",
         action="append",
-        help="Manually specify the serial port/address to use, for example /dev/ttyUSB0. Can be specified multiple times for fallback addresses.",
+        help=ARGUMENT_HELP_DEVICE,
     )
     parser_upload.add_argument(
         "--upload_speed",
@@ -1390,7 +1391,7 @@ def parse_args(argv):
     parser_logs.add_argument(
         "--device",
         action="append",
-        help="Manually specify the serial port/address to use, for example /dev/ttyUSB0. Can be specified multiple times for fallback addresses.",
+        help=ARGUMENT_HELP_DEVICE,
     )
     parser_logs.add_argument(
         "--reset",
@@ -1420,7 +1421,7 @@ def parse_args(argv):
     parser_run.add_argument(
         "--device",
         action="append",
-        help="Manually specify the serial port/address to use, for example /dev/ttyUSB0. Can be specified multiple times for fallback addresses.",
+        help=ARGUMENT_HELP_DEVICE,
     )
     parser_run.add_argument(
         "--upload_speed",

esphome/components/media_source/media_source.h

@@ -67,11 +67,13 @@ class MediaSource {
   /// @brief Start playing the given URI
   /// Sources should validate the URI and state, returning false if the source is busy.
   /// The orchestrator is responsible for stopping active sources before starting a new one.
+  /// @note Must only be called from the main loop.
   /// @param uri URI to play; e.g., "http://stream_url"
   /// @return true if playback started successfully, false otherwise
   virtual bool play_uri(const std::string &uri) = 0;
 
-  /// @brief Handle playback commands (pause, stop, next, etc.)
+  /// @brief Handle playback commands; e.g., pause, stop, next, etc.
+  /// @note Must only be called from the main loop.
   /// @param command Command to execute
   virtual void handle_command(MediaSourceCommand command) = 0;
 
@@ -81,7 +83,8 @@ class MediaSource {
 
   // === State Access ===
 
-  /// @brief Get current playback state (must only be called from the main loop)
+  /// @brief Get current playback state
+  /// @note Must only be called from the main loop.
   /// @return Current state of this source
   MediaSourceState get_state() const { return this->state_; }
 
@@ -136,9 +139,10 @@ class MediaSource {
   virtual void notify_audio_played(uint32_t frames, int64_t timestamp) {}
 
  protected:
-  /// @brief Update state and notify listener (must only be called from the main loop)
+  /// @brief Update state and notify listener
   /// This is the only way to change state_, ensuring listener notifications always fire.
   /// Sources running FreeRTOS tasks should signal via event groups and call this from loop().
+  /// @note Must only be called from the main loop.
   /// @param state New state to set
   void set_state_(MediaSourceState state) {
     if (this->state_ != state) {

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/const.py

@@ -11,6 +11,9 @@ VALID_SUBSTITUTIONS_CHARACTERS = (
     "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789_"
 )
 
+# CLI Help Text Constants
+ARGUMENT_HELP_DEVICE = "Manually specify the serial port/address to use, for example /dev/ttyUSB0. Can be specified multiple times for fallback addresses. Use 'OTA' for resolving from MQTT, DNS or mDNS and avoiding the interactive prompt."
+
 
 class Platform(StrEnum):
     """Platform identifiers for ESPHome."""

esphome/core/component.cpp

@@ -542,9 +542,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