runtime stats

This commit is contained in:
J. Nick Koston 2025-05-13 00:51:14 -05:00
parent a36e1aab8e
commit 3857cc9c83
No known key found for this signature in database
7 changed files with 191 additions and 2 deletions

2
.gitignore vendored
View File

@ -143,3 +143,5 @@ sdkconfig.*
/components
/managed_components
**/.claude/settings.local.json

View File

@ -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]))

View File

@ -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();

View File

@ -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 ? "<null>" : 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.");
;
}
}

View File

@ -6,6 +6,7 @@
#include <string>
#include "esphome/core/optional.h"
#include "esphome/core/runtime_stats.h"
namespace esphome {

View File

@ -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

View File

@ -0,0 +1,114 @@
#pragma once
#include <map>
#include <string>
#include <vector>
#include <cstdint>
#include <algorithm>
#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<float>(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<ComponentStatPair> 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<ComponentStatPair>());
// 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<std::string, ComponentRuntimeStats> 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