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 f04ea05d8e..29cf3ba533 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_SOCKET_SELECT_SUPPORT @@ -314,6 +315,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(uint32_t time = 0); diff --git a/esphome/core/component.cpp b/esphome/core/component.cpp index 0a4606074a..26304664c0 100644 --- a/esphome/core/component.cpp +++ b/esphome/core/component.cpp @@ -268,6 +268,9 @@ uint32_t WarnIfComponentBlockingGuard::finish() { uint32_t curr_time = millis(); uint32_t blocking_time = curr_time - this->started_; + + // Record component runtime stats + runtime_stats.record_component_time(this->component_, blocking_time, curr_time); bool should_warn; if (this->component_ != nullptr) { should_warn = this->component_->should_warn_of_blocking(blocking_time); diff --git a/esphome/core/component.h b/esphome/core/component.h index f77d40ae35..1846d22628 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..c0b82ef114 --- /dev/null +++ b/esphome/core/runtime_stats.h @@ -0,0 +1,161 @@ +#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() + : period_count_(0), + total_count_(0), + period_time_ms_(0), + total_time_ms_(0), + period_max_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 { + std::string 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() : 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"); + ESP_LOGI(RUNTIME_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 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_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(RUNTIME_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 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_total_count(), stats->get_total_avg_time_ms(), stats->get_total_max_time_ms(), + stats->get_total_time_ms()); + } + } + + void reset_stats_() { + for (auto &it : this->component_stats_) { + it.second.reset_period_stats(); + } + } + + 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