From d06bab01ac8294d7cd431b15a101db12cf79cee6 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 8 Jul 2025 09:09:07 -0600 Subject: [PATCH] runtime_stats --- esphome/components/runtime_stats/__init__.py | 26 ++++ esphome/core/application.cpp | 4 + esphome/core/application.h | 13 ++ esphome/core/component.cpp | 3 + esphome/core/component.h | 1 + esphome/core/runtime_stats.cpp | 92 ++++++++++++++ esphome/core/runtime_stats.h | 121 +++++++++++++++++++ 7 files changed, 260 insertions(+) create mode 100644 esphome/components/runtime_stats/__init__.py create mode 100644 esphome/core/runtime_stats.cpp create mode 100644 esphome/core/runtime_stats.h 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.cpp b/esphome/core/application.cpp index d6fab018cc..4dd892dd66 100644 --- a/esphome/core/application.cpp +++ b/esphome/core/application.cpp @@ -141,6 +141,10 @@ void Application::loop() { this->in_loop_ = false; this->app_state_ = new_app_state; + // Process any pending runtime stats printing after all components have run + // This ensures stats printing doesn't affect component timing measurements + runtime_stats.process_pending_stats(last_op_end_time); + // 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/application.h b/esphome/core/application.h index f2b5cb5c89..ee3ddebf8d 100644 --- a/esphome/core/application.h +++ b/esphome/core/application.h @@ -9,6 +9,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_DEVICES @@ -348,6 +349,18 @@ class Application { uint32_t get_loop_interval() const { return static_cast(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 9d863e56cd..9ff85532bb 100644 --- a/esphome/core/component.cpp +++ b/esphome/core/component.cpp @@ -395,6 +395,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 3734473a02..8b51c14507 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..da19349537 --- /dev/null +++ b/esphome/core/runtime_stats.cpp @@ -0,0 +1,92 @@ +#include "esphome/core/runtime_stats.h" +#include "esphome/core/component.h" +#include + +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; + + // 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 { + // Use cached name - no string operations, just map lookup + this->component_stats_[name_it->second].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; + } + + // Don't print stats here anymore - let process_pending_stats handle it +} + +void RuntimeStatsCollector::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 RuntimeStatsCollector::process_pending_stats(uint32_t current_time) { + if (!this->enabled_ || 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 esphome diff --git a/esphome/core/runtime_stats.h b/esphome/core/runtime_stats.h new file mode 100644 index 0000000000..6ae80750a6 --- /dev/null +++ b/esphome/core/runtime_stats.h @@ -0,0 +1,121 @@ +#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); + + // 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(); + } + } + + // Back to string keys, but we'll cache the source name per component + std::map component_stats_; + std::map component_names_cache_; + 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