diff --git a/.gitignore b/.gitignore index ad38e26fdd..cb14013de1 100644 --- a/.gitignore +++ b/.gitignore @@ -143,3 +143,5 @@ sdkconfig.* /components /managed_components + +**/.claude/settings.local.json diff --git a/esphome/components/runtime_stats/__init__.py b/esphome/components/runtime_stats/__init__.py new file mode 100644 index 0000000000..966503202a --- /dev/null +++ b/esphome/components/runtime_stats/__init__.py @@ -0,0 +1,26 @@ +""" +Runtime statistics component for ESPHome. +""" + +import esphome.codegen as cg +import esphome.config_validation as cv + +DEPENDENCIES = [] + +CONF_ENABLED = "enabled" +CONF_LOG_INTERVAL = "log_interval" + +CONFIG_SCHEMA = cv.Schema( + { + cv.Optional(CONF_ENABLED, default=True): cv.boolean, + cv.Optional( + CONF_LOG_INTERVAL, default=60000 + ): cv.positive_time_period_milliseconds, + } +) + + +async def to_code(config): + """Generate code for the runtime statistics component.""" + cg.add(cg.App.set_runtime_stats_enabled(config[CONF_ENABLED])) + cg.add(cg.App.set_runtime_stats_log_interval(config[CONF_LOG_INTERVAL])) diff --git a/esphome/core/application.h b/esphome/core/application.h index e64e2b7655..441acdcb41 100644 --- a/esphome/core/application.h +++ b/esphome/core/application.h @@ -7,6 +7,7 @@ #include "esphome/core/hal.h" #include "esphome/core/helpers.h" #include "esphome/core/preferences.h" +#include "esphome/core/runtime_stats.h" #include "esphome/core/scheduler.h" #ifdef USE_BINARY_SENSOR @@ -234,6 +235,18 @@ class Application { uint32_t get_loop_interval() const { return this->loop_interval_; } + /** Enable or disable runtime statistics collection. + * + * @param enable Whether to enable runtime statistics collection. + */ + void set_runtime_stats_enabled(bool enable) { runtime_stats.set_enabled(enable); } + + /** Set the interval at which runtime statistics are logged. + * + * @param interval The interval in milliseconds between logging of runtime statistics. + */ + void set_runtime_stats_log_interval(uint32_t interval) { runtime_stats.set_log_interval(interval); } + void schedule_dump_config() { this->dump_config_at_ = 0; } void feed_wdt(); diff --git a/esphome/core/component.cpp b/esphome/core/component.cpp index a7e451b93d..6470ed7f1c 100644 --- a/esphome/core/component.cpp +++ b/esphome/core/component.cpp @@ -243,7 +243,13 @@ void PollingComponent::set_update_interval(uint32_t update_interval) { this->upd WarnIfComponentBlockingGuard::WarnIfComponentBlockingGuard(Component *component) : started_(millis()), component_(component) {} WarnIfComponentBlockingGuard::~WarnIfComponentBlockingGuard() { - uint32_t blocking_time = millis() - this->started_; + uint32_t current_time = millis(); + uint32_t blocking_time = current_time - this->started_; + + // Record component runtime stats + runtime_stats.record_component_time(this->component_, blocking_time, current_time); + + // Original blocking check logic bool should_warn; if (this->component_ != nullptr) { should_warn = this->component_->should_warn_of_blocking(blocking_time); @@ -254,7 +260,6 @@ WarnIfComponentBlockingGuard::~WarnIfComponentBlockingGuard() { const char *src = component_ == nullptr ? "" : component_->get_component_source(); ESP_LOGW(TAG, "Component %s took a long time for an operation (%" PRIu32 " ms).", src, blocking_time); ESP_LOGW(TAG, "Components should block for at most 30 ms."); - ; } } diff --git a/esphome/core/component.h b/esphome/core/component.h index 412074282d..fd4cce0370 100644 --- a/esphome/core/component.h +++ b/esphome/core/component.h @@ -6,6 +6,7 @@ #include #include "esphome/core/optional.h" +#include "esphome/core/runtime_stats.h" namespace esphome { diff --git a/esphome/core/runtime_stats.cpp b/esphome/core/runtime_stats.cpp new file mode 100644 index 0000000000..893f056856 --- /dev/null +++ b/esphome/core/runtime_stats.cpp @@ -0,0 +1,28 @@ +#include "esphome/core/runtime_stats.h" +#include "esphome/core/component.h" + +namespace esphome { + +RuntimeStatsCollector runtime_stats; + +void RuntimeStatsCollector::record_component_time(Component *component, uint32_t duration_ms, uint32_t current_time) { + if (!this->enabled_ || component == nullptr) + return; + + const char *component_source = component->get_component_source(); + this->component_stats_[component_source].record_time(duration_ms); + + // If next_log_time_ is 0, initialize it + if (this->next_log_time_ == 0) { + this->next_log_time_ = current_time + this->log_interval_; + return; + } + + if (current_time >= this->next_log_time_) { + this->log_stats_(); + this->reset_stats_(); + this->next_log_time_ = current_time + this->log_interval_; + } +} + +} // namespace esphome \ No newline at end of file diff --git a/esphome/core/runtime_stats.h b/esphome/core/runtime_stats.h new file mode 100644 index 0000000000..19d975c613 --- /dev/null +++ b/esphome/core/runtime_stats.h @@ -0,0 +1,114 @@ +#pragma once + +#include +#include +#include +#include +#include +#include "esphome/core/helpers.h" +#include "esphome/core/log.h" + +namespace esphome { + +static const char *const RUNTIME_TAG = "runtime"; + +class Component; // Forward declaration + +class ComponentRuntimeStats { + public: + ComponentRuntimeStats() : count_(0), total_time_ms_(0), max_time_ms_(0) {} + + void record_time(uint32_t duration_ms) { + this->count_++; + this->total_time_ms_ += duration_ms; + + if (duration_ms > this->max_time_ms_) + this->max_time_ms_ = duration_ms; + } + + void reset() { + this->count_ = 0; + this->total_time_ms_ = 0; + this->max_time_ms_ = 0; + } + + uint32_t get_count() const { return this->count_; } + uint32_t get_total_time_ms() const { return this->total_time_ms_; } + uint32_t get_max_time_ms() const { return this->max_time_ms_; } + float get_avg_time_ms() const { + return this->count_ > 0 ? this->total_time_ms_ / static_cast(this->count_) : 0.0f; + } + + protected: + uint32_t count_; + uint32_t total_time_ms_; + uint32_t max_time_ms_; +}; + +// For sorting components by total run time +struct ComponentStatPair { + std::string name; + const ComponentRuntimeStats *stats; + + bool operator>(const ComponentStatPair &other) const { + return stats->get_total_time_ms() > other.stats->get_total_time_ms(); + } +}; + +class RuntimeStatsCollector { + public: + RuntimeStatsCollector() : log_interval_(60000), next_log_time_(0), enabled_(true) {} + + void set_log_interval(uint32_t log_interval) { this->log_interval_ = log_interval; } + uint32_t get_log_interval() const { return this->log_interval_; } + + void set_enabled(bool enabled) { this->enabled_ = enabled; } + bool is_enabled() const { return this->enabled_; } + + void record_component_time(Component *component, uint32_t duration_ms, uint32_t current_time); + + protected: + void log_stats_() { + ESP_LOGI(RUNTIME_TAG, "Component Runtime Statistics (over 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_count() > 0) { + ComponentStatPair pair = {it.first, &stats}; + stats_to_display.push_back(pair); + } + } + + // Sort by total runtime (descending) + std::sort(stats_to_display.begin(), stats_to_display.end(), std::greater()); + + // Log top components by runtime + for (const auto &it : stats_to_display) { + const std::string &source = it.name; + const ComponentRuntimeStats *stats = it.stats; + + ESP_LOGI(RUNTIME_TAG, " %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", + source.c_str(), stats->get_count(), stats->get_avg_time_ms(), stats->get_max_time_ms(), + stats->get_total_time_ms()); + } + } + + void reset_stats_() { + for (auto &it : this->component_stats_) { + it.second.reset(); + } + } + + std::map component_stats_; + uint32_t log_interval_; + uint32_t next_log_time_; + bool enabled_; +}; + +// Global instance for runtime stats collection +extern RuntimeStatsCollector runtime_stats; + +} // namespace esphome \ No newline at end of file