diff --git a/CODEOWNERS b/CODEOWNERS index b5037a6f9f..257f927fd9 100644 --- a/CODEOWNERS +++ b/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 diff --git a/esphome/components/runtime_stats/__init__.py b/esphome/components/runtime_stats/__init__.py new file mode 100644 index 0000000000..a36e8bfd28 --- /dev/null +++ b/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])) diff --git a/esphome/components/runtime_stats/runtime_stats.cpp b/esphome/components/runtime_stats/runtime_stats.cpp new file mode 100644 index 0000000000..8f5d5daf01 --- /dev/null +++ b/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 + +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 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()); + + // 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 diff --git a/esphome/components/runtime_stats/runtime_stats.h b/esphome/components/runtime_stats/runtime_stats.h new file mode 100644 index 0000000000..e2f8bee563 --- /dev/null +++ b/esphome/components/runtime_stats/runtime_stats.h @@ -0,0 +1,132 @@ +#pragma once + +#include "esphome/core/defines.h" + +#ifdef USE_RUNTIME_STATS + +#include +#include +#include +#include +#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(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(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 component_stats_; + std::map 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 diff --git a/esphome/core/application.cpp b/esphome/core/application.cpp index e19acd3ba6..123d6d01f4 100644 --- a/esphome/core/application.cpp +++ b/esphome/core/application.cpp @@ -4,6 +4,9 @@ #include "esphome/core/hal.h" #include #include +#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()) { diff --git a/esphome/core/component.cpp b/esphome/core/component.cpp index c47f16b5f7..623b521026 100644 --- a/esphome/core/component.cpp +++ b/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); diff --git a/tests/components/runtime_stats/common.yaml b/tests/components/runtime_stats/common.yaml new file mode 100644 index 0000000000..b434d1b5a7 --- /dev/null +++ b/tests/components/runtime_stats/common.yaml @@ -0,0 +1,2 @@ +# Test runtime_stats component with default configuration +runtime_stats: diff --git a/tests/components/runtime_stats/test.esp32-ard.yaml b/tests/components/runtime_stats/test.esp32-ard.yaml new file mode 100644 index 0000000000..dade44d145 --- /dev/null +++ b/tests/components/runtime_stats/test.esp32-ard.yaml @@ -0,0 +1 @@ +<<: !include common.yaml diff --git a/tests/integration/fixtures/runtime_stats.yaml b/tests/integration/fixtures/runtime_stats.yaml new file mode 100644 index 0000000000..aad1c275fb --- /dev/null +++ b/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 diff --git a/tests/integration/test_runtime_stats.py b/tests/integration/test_runtime_stats.py new file mode 100644 index 0000000000..cd8546facc --- /dev/null +++ b/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}" + )