Add runtime_stats component for performance debugging and analysis (#9386)

Co-authored-by: Keith Burzinski <kbx81x@gmail.com>

CODEOWNERS

@@ -379,6 +379,7 @@ esphome/components/rp2040_pwm/* @jesserockz
 esphome/components/rpi_dpi_rgb/* @clydebarrow
 esphome/components/rtl87xx/* @kuba2k2
 esphome/components/rtttl/* @glmnet
+esphome/components/runtime_stats/* @bdraco
 esphome/components/safe_mode/* @jsuanet @kbx81 @paulmonigatti
 esphome/components/scd4x/* @martgras @sjtrny
 esphome/components/script/* @esphome/core

esphome/components/runtime_stats/__init__.py

@@ -0,0 +1,34 @@
+"""
+Runtime statistics component for ESPHome.
+"""
+
+import esphome.codegen as cg
+import esphome.config_validation as cv
+from esphome.const import CONF_ID
+
+CODEOWNERS = ["@bdraco"]
+
+CONF_LOG_INTERVAL = "log_interval"
+
+runtime_stats_ns = cg.esphome_ns.namespace("runtime_stats")
+RuntimeStatsCollector = runtime_stats_ns.class_("RuntimeStatsCollector")
+
+CONFIG_SCHEMA = cv.Schema(
+    {
+        cv.GenerateID(): cv.declare_id(RuntimeStatsCollector),
+        cv.Optional(
+            CONF_LOG_INTERVAL, default="60s"
+        ): cv.positive_time_period_milliseconds,
+    }
+)
+
+
+async def to_code(config):
+    """Generate code for the runtime statistics component."""
+    # Define USE_RUNTIME_STATS when this component is used
+    cg.add_define("USE_RUNTIME_STATS")
+
+    # Create the runtime stats instance (constructor sets global_runtime_stats)
+    var = cg.new_Pvariable(config[CONF_ID])
+
+    cg.add(var.set_log_interval(config[CONF_LOG_INTERVAL]))

esphome/components/runtime_stats/runtime_stats.cpp

@@ -0,0 +1,102 @@
+#include "runtime_stats.h"
+
+#ifdef USE_RUNTIME_STATS
+
+#include "esphome/core/component.h"
+#include <algorithm>
+
+namespace esphome {
+
+namespace runtime_stats {
+
+RuntimeStatsCollector::RuntimeStatsCollector() : log_interval_(60000), next_log_time_(0) {
+  global_runtime_stats = this;
+}
+
+void RuntimeStatsCollector::record_component_time(Component *component, uint32_t duration_ms, uint32_t current_time) {
+  if (component == nullptr)
+    return;
+
+  // Check if we have cached the name for this component
+  auto name_it = this->component_names_cache_.find(component);
+  if (name_it == this->component_names_cache_.end()) {
+    // First time seeing this component, cache its name
+    const char *source = component->get_component_source();
+    this->component_names_cache_[component] = source;
+    this->component_stats_[source].record_time(duration_ms);
+  } else {
+    this->component_stats_[name_it->second].record_time(duration_ms);
+  }
+
+  if (this->next_log_time_ == 0) {
+    this->next_log_time_ = current_time + this->log_interval_;
+    return;
+  }
+}
+
+void RuntimeStatsCollector::log_stats_() {
+  ESP_LOGI(TAG, "Component Runtime Statistics");
+  ESP_LOGI(TAG, "Period stats (last %" PRIu32 "ms):", this->log_interval_);
+
+  // First collect stats we want to display
+  std::vector<ComponentStatPair> stats_to_display;
+
+  for (const auto &it : this->component_stats_) {
+    const ComponentRuntimeStats &stats = it.second;
+    if (stats.get_period_count() > 0) {
+      ComponentStatPair pair = {it.first, &stats};
+      stats_to_display.push_back(pair);
+    }
+  }
+
+  // Sort by period runtime (descending)
+  std::sort(stats_to_display.begin(), stats_to_display.end(), std::greater<ComponentStatPair>());
+
+  // Log top components by period runtime
+  for (const auto &it : stats_to_display) {
+    const char *source = it.name;
+    const ComponentRuntimeStats *stats = it.stats;
+
+    ESP_LOGI(TAG, "  %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", source,
+             stats->get_period_count(), stats->get_period_avg_time_ms(), stats->get_period_max_time_ms(),
+             stats->get_period_time_ms());
+  }
+
+  // Log total stats since boot
+  ESP_LOGI(TAG, "Total stats (since boot):");
+
+  // Re-sort by total runtime for all-time stats
+  std::sort(stats_to_display.begin(), stats_to_display.end(),
+            [](const ComponentStatPair &a, const ComponentStatPair &b) {
+              return a.stats->get_total_time_ms() > b.stats->get_total_time_ms();
+            });
+
+  for (const auto &it : stats_to_display) {
+    const char *source = it.name;
+    const ComponentRuntimeStats *stats = it.stats;
+
+    ESP_LOGI(TAG, "  %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", source,
+             stats->get_total_count(), stats->get_total_avg_time_ms(), stats->get_total_max_time_ms(),
+             stats->get_total_time_ms());
+  }
+}
+
+void RuntimeStatsCollector::process_pending_stats(uint32_t current_time) {
+  if (this->next_log_time_ == 0)
+    return;
+
+  if (current_time >= this->next_log_time_) {
+    this->log_stats_();
+    this->reset_stats_();
+    this->next_log_time_ = current_time + this->log_interval_;
+  }
+}
+
+}  // namespace runtime_stats
+
+runtime_stats::RuntimeStatsCollector *global_runtime_stats =
+    nullptr;  // NOLINT(cppcoreguidelines-avoid-non-const-global-variables)
+
+}  // namespace esphome
+
+#endif  // USE_RUNTIME_STATS

esphome/components/runtime_stats/runtime_stats.h

@@ -0,0 +1,132 @@
+#pragma once
+
+#include "esphome/core/defines.h"
+
+#ifdef USE_RUNTIME_STATS
+
+#include <map>
+#include <vector>
+#include <cstdint>
+#include <cstring>
+#include "esphome/core/helpers.h"
+#include "esphome/core/log.h"
+
+namespace esphome {
+
+class Component;  // Forward declaration
+
+namespace runtime_stats {
+
+static const char *const TAG = "runtime_stats";
+
+class ComponentRuntimeStats {
+ public:
+  ComponentRuntimeStats()
+      : period_count_(0),
+        period_time_ms_(0),
+        period_max_time_ms_(0),
+        total_count_(0),
+        total_time_ms_(0),
+        total_max_time_ms_(0) {}
+
+  void record_time(uint32_t duration_ms) {
+    // 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;
+
+    // Update total counters
+    this->total_count_++;
+    this->total_time_ms_ += duration_ms;
+    if (duration_ms > this->total_max_time_ms_)
+      this->total_max_time_ms_ = duration_ms;
+  }
+
+  void reset_period_stats() {
+    this->period_count_ = 0;
+    this->period_time_ms_ = 0;
+    this->period_max_time_ms_ = 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;
+  }
+
+  // Total stats (persistent until reboot)
+  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;
+  }
+
+ protected:
+  // Period stats (reset each logging interval)
+  uint32_t period_count_;
+  uint32_t period_time_ms_;
+  uint32_t period_max_time_ms_;
+
+  // Total stats (persistent until reboot)
+  uint32_t total_count_;
+  uint32_t total_time_ms_;
+  uint32_t total_max_time_ms_;
+};
+
+// For sorting components by run time
+struct ComponentStatPair {
+  const char *name;
+  const ComponentRuntimeStats *stats;
+
+  bool operator>(const ComponentStatPair &other) const {
+    // Sort by period time as that's what we're displaying in the logs
+    return stats->get_period_time_ms() > other.stats->get_period_time_ms();
+  }
+};
+
+class RuntimeStatsCollector {
+ public:
+  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);
+
+  // Process any pending stats printing (should be called after component loop)
+  void process_pending_stats(uint32_t current_time);
+
+ protected:
+  void log_stats_();
+
+  void reset_stats_() {
+    for (auto &it : this->component_stats_) {
+      it.second.reset_period_stats();
+    }
+  }
+
+  // Use const char* keys for efficiency
+  // Custom comparator for const char* keys in map
+  // Without this, std::map would compare pointer addresses instead of string contents,
+  // causing identical component names at different addresses to be treated as different keys
+  struct CStrCompare {
+    bool operator()(const char *a, const char *b) const { return std::strcmp(a, b) < 0; }
+  };
+  std::map<const char *, ComponentRuntimeStats, CStrCompare> component_stats_;
+  std::map<Component *, const char *> component_names_cache_;
+  uint32_t log_interval_;
+  uint32_t next_log_time_;
+};
+
+}  // namespace runtime_stats
+
+extern runtime_stats::RuntimeStatsCollector
+    *global_runtime_stats;  // NOLINT(cppcoreguidelines-avoid-non-const-global-variables)
+
+}  // namespace esphome
+
+#endif  // USE_RUNTIME_STATS

esphome/core/application.cpp

@@ -4,6 +4,9 @@
 #include "esphome/core/hal.h"
 #include <algorithm>
 #include <ranges>
+#ifdef USE_RUNTIME_STATS
+#include "esphome/components/runtime_stats/runtime_stats.h"
+#endif
 
 #ifdef USE_STATUS_LED
 #include "esphome/components/status_led/status_led.h"
@@ -141,6 +144,14 @@ void Application::loop() {
   this->in_loop_ = false;
   this->app_state_ = new_app_state;
 
+#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->process_pending_stats(last_op_end_time);
+  }
+#endif
+
   // Use the last component's end time instead of calling millis() again
   auto elapsed = last_op_end_time - this->last_loop_;
   if (elapsed >= this->loop_interval_ || HighFrequencyLoopRequester::is_high_frequency()) {

esphome/core/component.cpp

@@ -9,6 +9,9 @@
 #include "esphome/core/hal.h"
 #include "esphome/core/helpers.h"
 #include "esphome/core/log.h"
+#ifdef USE_RUNTIME_STATS
+#include "esphome/components/runtime_stats/runtime_stats.h"
+#endif
 
 namespace esphome {
 
@@ -396,6 +399,13 @@ 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
+  if (global_runtime_stats != nullptr) {
+    global_runtime_stats->record_component_time(this->component_, blocking_time, curr_time);
+  }
+#endif
   bool should_warn;
   if (this->component_ != nullptr) {
     should_warn = this->component_->should_warn_of_blocking(blocking_time);

tests/components/runtime_stats/common.yaml

@@ -0,0 +1,2 @@
+# Test runtime_stats component with default configuration
+runtime_stats:

tests/components/runtime_stats/test.esp32-ard.yaml

@@ -0,0 +1 @@
+<<: !include common.yaml

tests/integration/fixtures/runtime_stats.yaml

@@ -0,0 +1,39 @@
+esphome:
+  name: runtime-stats-test
+
+host:
+
+api:
+
+logger:
+  level: DEBUG
+  logs:
+    runtime_stats: INFO
+
+runtime_stats:
+  log_interval: 1s
+
+# Add some components that will execute periodically to generate stats
+sensor:
+  - platform: template
+    name: "Test Sensor 1"
+    id: test_sensor_1
+    lambda: return 42.0;
+    update_interval: 0.1s
+
+  - platform: template
+    name: "Test Sensor 2"
+    id: test_sensor_2
+    lambda: return 24.0;
+    update_interval: 0.2s
+
+switch:
+  - platform: template
+    name: "Test Switch"
+    id: test_switch
+    optimistic: true
+
+interval:
+  - interval: 0.5s
+    then:
+      - switch.toggle: test_switch

tests/integration/test_runtime_stats.py

@@ -0,0 +1,88 @@
+"""Test runtime statistics component."""
+
+from __future__ import annotations
+
+import asyncio
+import re
+
+import pytest
+
+from .types import APIClientConnectedFactory, RunCompiledFunction
+
+
+@pytest.mark.asyncio
+async def test_runtime_stats(
+    yaml_config: str,
+    run_compiled: RunCompiledFunction,
+    api_client_connected: APIClientConnectedFactory,
+) -> None:
+    """Test runtime stats logs statistics at configured interval and tracks components."""
+    loop = asyncio.get_running_loop()
+
+    # Track how many times we see the total stats
+    stats_count = 0
+    first_stats_future = loop.create_future()
+    second_stats_future = loop.create_future()
+
+    # Track component stats
+    component_stats_found = set()
+
+    # Patterns to match - need to handle ANSI color codes and timestamps
+    # The log format is: [HH:MM:SS][color codes][I][tag]: message
+    total_stats_pattern = re.compile(r"Total stats \(since boot\):")
+    # Match component names that may include dots (e.g., template.sensor)
+    component_pattern = re.compile(
+        r"^\[[^\]]+\].*?\s+([\w.]+):\s+count=(\d+),\s+avg=([\d.]+)ms"
+    )
+
+    def check_output(line: str) -> None:
+        """Check log output for runtime stats messages."""
+        nonlocal stats_count
+
+        # Check for total stats line
+        if total_stats_pattern.search(line):
+            stats_count += 1
+
+            if stats_count == 1 and not first_stats_future.done():
+                first_stats_future.set_result(True)
+            elif stats_count == 2 and not second_stats_future.done():
+                second_stats_future.set_result(True)
+
+        # Check for component stats
+        match = component_pattern.match(line)
+        if match:
+            component_name = match.group(1)
+            component_stats_found.add(component_name)
+
+    async with (
+        run_compiled(yaml_config, line_callback=check_output),
+        api_client_connected() as client,
+    ):
+        # Verify device is connected
+        device_info = await client.device_info()
+        assert device_info is not None
+
+        # Wait for first "Total stats" log (should happen at 1s)
+        try:
+            await asyncio.wait_for(first_stats_future, timeout=5.0)
+        except asyncio.TimeoutError:
+            pytest.fail("First 'Total stats' log not seen within 5 seconds")
+
+        # Wait for second "Total stats" log (should happen at 2s)
+        try:
+            await asyncio.wait_for(second_stats_future, timeout=5.0)
+        except asyncio.TimeoutError:
+            pytest.fail(f"Second 'Total stats' log not seen. Total seen: {stats_count}")
+
+        # Verify we got at least 2 stats logs
+        assert stats_count >= 2, (
+            f"Expected at least 2 'Total stats' logs, got {stats_count}"
+        )
+
+        # Verify we found stats for our components
+        assert "template.sensor" in component_stats_found, (
+            f"Expected template.sensor stats, found: {component_stats_found}"
+        )
+        assert "template.switch" in component_stats_found, (
+            f"Expected template.switch stats, found: {component_stats_found}"
+        )