sascha/esphome
1
0
Fork 0
mirror of https://github.com/esphome/esphome.git synced 2025-09-07 05:42:20 +01:00
Code Issues Releases Wiki Activity

[core] Store component source strings in flash on ESP8266 (breaking change)

Browse Source
This commit is contained in:
J. Nick Koston
2025-09-05 17:08:11 -05:00
parent 09b40b882e
commit c84928aba5
10 changed files with 59 additions and 57 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
esphome/components/debug/debug_esp32.cpp
View File

@@ -52,7 +52,7 @@ void DebugComponent::on_shutdown() {
char buffer[REBOOT_MAX_LEN]{}; char buffer[REBOOT_MAX_LEN]{};
auto pref = global_preferences->make_preference(REBOOT_MAX_LEN, fnv1_hash(REBOOT_KEY + App.get_name())); auto pref = global_preferences->make_preference(REBOOT_MAX_LEN, fnv1_hash(REBOOT_KEY + App.get_name()));
if (component != nullptr) { if (component != nullptr) {
strncpy(buffer, component->get_component_source(), REBOOT_MAX_LEN - 1); strncpy(buffer, LOG_STR_ARG(component->get_component_log_str()), REBOOT_MAX_LEN - 1);
buffer[REBOOT_MAX_LEN - 1] = '\0'; buffer[REBOOT_MAX_LEN - 1] = '\0';
} }
ESP_LOGD(TAG, "Storing reboot source: %s", buffer); ESP_LOGD(TAG, "Storing reboot source: %s", buffer);

19
esphome/components/runtime_stats/runtime_stats.cpp
View File

@@ -17,16 +17,8 @@ void RuntimeStatsCollector::record_component_time(Component *component, uint32_t
if (component == nullptr) if (component == nullptr)
return; return;
// Check if we have cached the name for this component // Record stats using component pointer as key
auto name_it = this->component_names_cache_.find(component); this->component_stats_[component].record_time(duration_ms);
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) { if (this->next_log_time_ == 0) {
this->next_log_time_ = current_time + this->log_interval_; this->next_log_time_ = current_time + this->log_interval_;
@@ -42,9 +34,10 @@ void RuntimeStatsCollector::log_stats_() {
std::vector<ComponentStatPair> stats_to_display; std::vector<ComponentStatPair> stats_to_display;
for (const auto &it : this->component_stats_) { for (const auto &it : this->component_stats_) {
Component *component = it.first;
const ComponentRuntimeStats &stats = it.second; const ComponentRuntimeStats &stats = it.second;
if (stats.get_period_count() > 0) { if (stats.get_period_count() > 0) {
ComponentStatPair pair = {it.first, &stats}; ComponentStatPair pair = {component, &stats};
stats_to_display.push_back(pair); stats_to_display.push_back(pair);
} }
} }
@@ -54,7 +47,7 @@ void RuntimeStatsCollector::log_stats_() {
// Log top components by period runtime // Log top components by period runtime
for (const auto &it : stats_to_display) { for (const auto &it : stats_to_display) {
const char *source = it.name; const char *source = LOG_STR_ARG(it.component->get_component_log_str());
const ComponentRuntimeStats *stats = it.stats; const ComponentRuntimeStats *stats = it.stats;
ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", source, ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", source,
@@ -72,7 +65,7 @@ void RuntimeStatsCollector::log_stats_() {
}); });
for (const auto &it : stats_to_display) { for (const auto &it : stats_to_display) {
const char *source = it.name; const char *source = LOG_STR_ARG(it.component->get_component_log_str());
const ComponentRuntimeStats *stats = it.stats; const ComponentRuntimeStats *stats = it.stats;
ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", source, ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", source,

14
esphome/components/runtime_stats/runtime_stats.h
View File

@@ -79,7 +79,7 @@ class ComponentRuntimeStats {
// For sorting components by run time // For sorting components by run time
struct ComponentStatPair { struct ComponentStatPair {
const char *name; Component *component;
const ComponentRuntimeStats *stats; const ComponentRuntimeStats *stats;
bool operator>(const ComponentStatPair &other) const { bool operator>(const ComponentStatPair &other) const {
@@ -109,15 +109,9 @@ class RuntimeStatsCollector {
} }
} }
// Use const char* keys for efficiency // Map from component to its stats
// Custom comparator for const char* keys in map // We use Component* as the key since each component is unique
// Without this, std::map would compare pointer addresses instead of string contents, std::map<Component *, ComponentRuntimeStats> component_stats_;
// 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<const char *, ComponentRuntimeStats, CStrCompare> component_stats_;
std::map<Component *, const char *> component_names_cache_;
uint32_t log_interval_; uint32_t log_interval_;
uint32_t next_log_time_; uint32_t next_log_time_;
}; };

8
esphome/core/application.cpp
View File

@@ -80,7 +80,7 @@ void Application::register_component_(Component *comp) {
for (auto *c : this->components_) { for (auto *c : this->components_) {
if (comp == c) { if (comp == c) {
ESP_LOGW(TAG, "Component %s already registered! (%p)", c->get_component_source(), c); ESP_LOGW(TAG, "Component %s already registered! (%p)", LOG_STR_ARG(c->get_component_log_str()), c);
return; return;
} }
} }
@@ -340,8 +340,8 @@ void Application::teardown_components(uint32_t timeout_ms) {
// Note: At this point, connections are either disconnected or in a bad state, // Note: At this point, connections are either disconnected or in a bad state,
// so this warning will only appear via serial rather than being transmitted to clients // so this warning will only appear via serial rather than being transmitted to clients
for (size_t i = 0; i < pending_count; ++i) { for (size_t i = 0; i < pending_count; ++i) {
ESP_LOGW(TAG, "%s did not complete teardown within %" PRIu32 " ms", pending_components[i]->get_component_source(), ESP_LOGW(TAG, "%s did not complete teardown within %" PRIu32 " ms",
timeout_ms); LOG_STR_ARG(pending_components[i]->get_component_log_str()), timeout_ms);
} }
} }
} }
@@ -473,7 +473,7 @@ void Application::enable_pending_loops_() {
// Clear the pending flag and enable the loop // Clear the pending flag and enable the loop
component->pending_enable_loop_ = false; component->pending_enable_loop_ = false;
ESP_LOGVV(TAG, "%s loop enabled from ISR", component->get_component_source()); ESP_LOGVV(TAG, "%s loop enabled from ISR", LOG_STR_ARG(component->get_component_log_str()));
component->component_state_ &= ~COMPONENT_STATE_MASK; component->component_state_ &= ~COMPONENT_STATE_MASK;
component->component_state_ |= COMPONENT_STATE_LOOP; component->component_state_ |= COMPONENT_STATE_LOOP;

35
esphome/core/component.cpp
View File

@@ -142,7 +142,7 @@ void Component::call_dump_config() {
} }
} }
} }
ESP_LOGE(TAG, " %s is marked FAILED: %s", this->get_component_source(), ESP_LOGE(TAG, " %s is marked FAILED: %s", LOG_STR_ARG(this->get_component_log_str()),
error_msg ? error_msg : UNSPECIFIED_MESSAGE); error_msg ? error_msg : UNSPECIFIED_MESSAGE);
} }
} }
@@ -154,14 +154,14 @@ void Component::call() {
case COMPONENT_STATE_CONSTRUCTION: { case COMPONENT_STATE_CONSTRUCTION: {
// State Construction: Call setup and set state to setup // State Construction: Call setup and set state to setup
this->set_component_state_(COMPONENT_STATE_SETUP); this->set_component_state_(COMPONENT_STATE_SETUP);
ESP_LOGV(TAG, "Setup %s", this->get_component_source()); ESP_LOGV(TAG, "Setup %s", LOG_STR_ARG(this->get_component_log_str()));
#if ESPHOME_LOG_LEVEL >= ESPHOME_LOG_LEVEL_DEBUG #if ESPHOME_LOG_LEVEL >= ESPHOME_LOG_LEVEL_DEBUG
uint32_t start_time = millis(); uint32_t start_time = millis();
#endif #endif
this->call_setup(); this->call_setup();
#if ESPHOME_LOG_LEVEL >= ESPHOME_LOG_LEVEL_DEBUG #if ESPHOME_LOG_LEVEL >= ESPHOME_LOG_LEVEL_DEBUG
uint32_t setup_time = millis() - start_time; uint32_t setup_time = millis() - start_time;
ESP_LOGCONFIG(TAG, "Setup %s took %ums", this->get_component_source(), (unsigned) setup_time); ESP_LOGCONFIG(TAG, "Setup %s took %ums", LOG_STR_ARG(this->get_component_log_str()), (unsigned) setup_time);
#endif #endif
break; break;
} }
@@ -182,10 +182,8 @@ void Component::call() {
break; break;
} }
} }
const char *Component::get_component_source() const { const LogString *Component::get_component_log_str() const {
if (this->component_source_ == nullptr) return this->component_source_ == nullptr ? LOG_STR("<unknown>") : this->component_source_;
return "<unknown>";
return this->component_source_;
} }
bool Component::should_warn_of_blocking(uint32_t blocking_time) { bool Component::should_warn_of_blocking(uint32_t blocking_time) {
if (blocking_time > this->warn_if_blocking_over_) { if (blocking_time > this->warn_if_blocking_over_) {
@@ -201,7 +199,7 @@ bool Component::should_warn_of_blocking(uint32_t blocking_time) {
return false; return false;
} }
void Component::mark_failed() { void Component::mark_failed() {
ESP_LOGE(TAG, "%s was marked as failed", this->get_component_source()); ESP_LOGE(TAG, "%s was marked as failed", LOG_STR_ARG(this->get_component_log_str()));
this->set_component_state_(COMPONENT_STATE_FAILED); this->set_component_state_(COMPONENT_STATE_FAILED);
this->status_set_error(); this->status_set_error();
// Also remove from loop since failed components shouldn't loop // Also remove from loop since failed components shouldn't loop
@@ -213,14 +211,14 @@ void Component::set_component_state_(uint8_t state) {
} }
void Component::disable_loop() { void Component::disable_loop() {
if ((this->component_state_ & COMPONENT_STATE_MASK) != COMPONENT_STATE_LOOP_DONE) { if ((this->component_state_ & COMPONENT_STATE_MASK) != COMPONENT_STATE_LOOP_DONE) {
ESP_LOGVV(TAG, "%s loop disabled", this->get_component_source()); ESP_LOGVV(TAG, "%s loop disabled", LOG_STR_ARG(this->get_component_log_str()));
this->set_component_state_(COMPONENT_STATE_LOOP_DONE); this->set_component_state_(COMPONENT_STATE_LOOP_DONE);
App.disable_component_loop_(this); App.disable_component_loop_(this);
} }
} }
void Component::enable_loop() { void Component::enable_loop() {
if ((this->component_state_ & COMPONENT_STATE_MASK) == COMPONENT_STATE_LOOP_DONE) { if ((this->component_state_ & COMPONENT_STATE_MASK) == COMPONENT_STATE_LOOP_DONE) {
ESP_LOGVV(TAG, "%s loop enabled", this->get_component_source()); ESP_LOGVV(TAG, "%s loop enabled", LOG_STR_ARG(this->get_component_log_str()));
this->set_component_state_(COMPONENT_STATE_LOOP); this->set_component_state_(COMPONENT_STATE_LOOP);
App.enable_component_loop_(this); App.enable_component_loop_(this);
} }
@@ -240,7 +238,7 @@ void IRAM_ATTR HOT Component::enable_loop_soon_any_context() {
} }
void Component::reset_to_construction_state() { void Component::reset_to_construction_state() {
if ((this->component_state_ & COMPONENT_STATE_MASK) == COMPONENT_STATE_FAILED) { if ((this->component_state_ & COMPONENT_STATE_MASK) == COMPONENT_STATE_FAILED) {
ESP_LOGI(TAG, "%s is being reset to construction state", this->get_component_source()); ESP_LOGI(TAG, "%s is being reset to construction state", LOG_STR_ARG(this->get_component_log_str()));
this->set_component_state_(COMPONENT_STATE_CONSTRUCTION); this->set_component_state_(COMPONENT_STATE_CONSTRUCTION);
// Clear error status when resetting // Clear error status when resetting
this->status_clear_error(); this->status_clear_error();
@@ -286,14 +284,16 @@ void Component::status_set_warning(const char *message) {
return; return;
this->component_state_ |= STATUS_LED_WARNING; this->component_state_ |= STATUS_LED_WARNING;
App.app_state_ |= STATUS_LED_WARNING; App.app_state_ |= STATUS_LED_WARNING;
ESP_LOGW(TAG, "%s set Warning flag: %s", this->get_component_source(), message ? message : UNSPECIFIED_MESSAGE); ESP_LOGW(TAG, "%s set Warning flag: %s", LOG_STR_ARG(this->get_component_log_str()),
message ? message : UNSPECIFIED_MESSAGE);
} }
void Component::status_set_error(const char *message) { void Component::status_set_error(const char *message) {
if ((this->component_state_ & STATUS_LED_ERROR) != 0) if ((this->component_state_ & STATUS_LED_ERROR) != 0)
return; return;
this->component_state_ |= STATUS_LED_ERROR; this->component_state_ |= STATUS_LED_ERROR;
App.app_state_ |= STATUS_LED_ERROR; App.app_state_ |= STATUS_LED_ERROR;
ESP_LOGE(TAG, "%s set Error flag: %s", this->get_component_source(), message ? message : UNSPECIFIED_MESSAGE); ESP_LOGE(TAG, "%s set Error flag: %s", LOG_STR_ARG(this->get_component_log_str()),
message ? message : UNSPECIFIED_MESSAGE);
if (message != nullptr) { if (message != nullptr) {
// Lazy allocate the error messages vector if needed // Lazy allocate the error messages vector if needed
if (!component_error_messages) { if (!component_error_messages) {
@@ -314,13 +314,13 @@ void Component::status_clear_warning() {
if ((this->component_state_ & STATUS_LED_WARNING) == 0) if ((this->component_state_ & STATUS_LED_WARNING) == 0)
return; return;
this->component_state_ &= ~STATUS_LED_WARNING; this->component_state_ &= ~STATUS_LED_WARNING;
ESP_LOGW(TAG, "%s cleared Warning flag", this->get_component_source()); ESP_LOGW(TAG, "%s cleared Warning flag", LOG_STR_ARG(this->get_component_log_str()));
} }
void Component::status_clear_error() { void Component::status_clear_error() {
if ((this->component_state_ & STATUS_LED_ERROR) == 0) if ((this->component_state_ & STATUS_LED_ERROR) == 0)
return; return;
this->component_state_ &= ~STATUS_LED_ERROR; this->component_state_ &= ~STATUS_LED_ERROR;
ESP_LOGE(TAG, "%s cleared Error flag", this->get_component_source()); ESP_LOGE(TAG, "%s cleared Error flag", LOG_STR_ARG(this->get_component_log_str()));
} }
void Component::status_momentary_warning(const std::string &name, uint32_t length) { void Component::status_momentary_warning(const std::string &name, uint32_t length) {
this->status_set_warning(); this->status_set_warning();
@@ -419,8 +419,9 @@ uint32_t WarnIfComponentBlockingGuard::finish() {
should_warn = blocking_time > WARN_IF_BLOCKING_OVER_MS; should_warn = blocking_time > WARN_IF_BLOCKING_OVER_MS;
} }
if (should_warn) { if (should_warn) {
const char *src = component_ == nullptr ? "<null>" : component_->get_component_source(); ESP_LOGW(TAG, "%s took a long time for an operation (%" PRIu32 " ms)",
ESP_LOGW(TAG, "%s took a long time for an operation (%" PRIu32 " ms)", src, blocking_time); component_ == nullptr ? LOG_STR_LITERAL("<null>") : LOG_STR_ARG(component_->get_component_log_str()),
blocking_time);
ESP_LOGW(TAG, "Components should block for at most 30 ms"); ESP_LOGW(TAG, "Components should block for at most 30 ms");
} }

11
esphome/core/component.h
View File

@@ -5,6 +5,7 @@
#include <functional> #include <functional>
#include <string> #include <string>
#include "esphome/core/log.h"
#include "esphome/core/optional.h" #include "esphome/core/optional.h"
namespace esphome { namespace esphome {
@@ -220,12 +221,12 @@ class Component {
* *
* This is set by the ESPHome core, and should not be called manually. * This is set by the ESPHome core, and should not be called manually.
*/ */
void set_component_source(const char *source) { component_source_ = source; } void set_component_source(const LogString *source) { component_source_ = source; }
/** Get the integration where this component was declared as a string. /** Get the integration where this component was declared as a LogString for logging.
* *
* Returns "<unknown>" if source not set * Returns LOG_STR("<unknown>") if source not set
*/ */
const char *get_component_source() const; const LogString *get_component_log_str() const;
bool should_warn_of_blocking(uint32_t blocking_time); bool should_warn_of_blocking(uint32_t blocking_time);
@@ -405,7 +406,7 @@ class Component {
bool cancel_defer(const std::string &name); // NOLINT bool cancel_defer(const std::string &name); // NOLINT
// Ordered for optimal packing on 32-bit systems // Ordered for optimal packing on 32-bit systems
const char *component_source_{nullptr}; const LogString *component_source_{nullptr};
uint16_t warn_if_blocking_over_{WARN_IF_BLOCKING_OVER_MS}; ///< Warn if blocked for this many ms (max 65.5s) uint16_t warn_if_blocking_over_{WARN_IF_BLOCKING_OVER_MS}; ///< Warn if blocked for this many ms (max 65.5s)
/// State of this component - each bit has a purpose: /// State of this component - each bit has a purpose:
/// Bits 0-2: Component state (0x00=CONSTRUCTION, 0x01=SETUP, 0x02=LOOP, 0x03=FAILED, 0x04=LOOP_DONE) /// Bits 0-2: Component state (0x00=CONSTRUCTION, 0x01=SETUP, 0x02=LOOP, 0x03=FAILED, 0x04=LOOP_DONE)

8
esphome/core/scheduler.cpp
View File

@@ -134,10 +134,10 @@ void HOT Scheduler::set_timer_common_(Component *component, SchedulerItem::Type
// Debug logging // Debug logging
const char *type_str = (type == SchedulerItem::TIMEOUT) ? "timeout" : "interval"; const char *type_str = (type == SchedulerItem::TIMEOUT) ? "timeout" : "interval";
if (type == SchedulerItem::TIMEOUT) { if (type == SchedulerItem::TIMEOUT) {
ESP_LOGD(TAG, "set_%s(name='%s/%s', %s=%" PRIu32 ")", type_str, item->get_source(), ESP_LOGD(TAG, "set_%s(name='%s/%s', %s=%" PRIu32 ")", type_str, LOG_STR_ARG(item->get_source()),
name_cstr ? name_cstr : "(null)", type_str, delay); name_cstr ? name_cstr : "(null)", type_str, delay);
} else { } else {
ESP_LOGD(TAG, "set_%s(name='%s/%s', %s=%" PRIu32 ", offset=%" PRIu32 ")", type_str, item->get_source(), ESP_LOGD(TAG, "set_%s(name='%s/%s', %s=%" PRIu32 ", offset=%" PRIu32 ")", type_str, LOG_STR_ARG(item->get_source()),
name_cstr ? name_cstr : "(null)", type_str, delay, static_cast<uint32_t>(item->next_execution_ - now)); name_cstr ? name_cstr : "(null)", type_str, delay, static_cast<uint32_t>(item->next_execution_ - now));
} }
#endif /* ESPHOME_DEBUG_SCHEDULER */ #endif /* ESPHOME_DEBUG_SCHEDULER */
@@ -353,7 +353,7 @@ void HOT Scheduler::call(uint32_t now) {
const char *name = item->get_name(); const char *name = item->get_name();
ESP_LOGD(TAG, " %s '%s/%s' interval=%" PRIu32 " next_execution in %" PRIu64 "ms at %" PRIu64, ESP_LOGD(TAG, " %s '%s/%s' interval=%" PRIu32 " next_execution in %" PRIu64 "ms at %" PRIu64,
item->get_type_str(), item->get_source(), name ? name : "(null)", item->interval, item->get_type_str(), LOG_STR_ARG(item->get_source()), name ? name : "(null)", item->interval,
item->next_execution_ - now_64, item->next_execution_); item->next_execution_ - now_64, item->next_execution_);
old_items.push_back(std::move(item)); old_items.push_back(std::move(item));
@@ -439,7 +439,7 @@ void HOT Scheduler::call(uint32_t now) {
#ifdef ESPHOME_DEBUG_SCHEDULER #ifdef ESPHOME_DEBUG_SCHEDULER
const char *item_name = item->get_name(); const char *item_name = item->get_name();
ESP_LOGV(TAG, "Running %s '%s/%s' with interval=%" PRIu32 " next_execution=%" PRIu64 " (now=%" PRIu64 ")", ESP_LOGV(TAG, "Running %s '%s/%s' with interval=%" PRIu32 " next_execution=%" PRIu64 " (now=%" PRIu64 ")",
item->get_type_str(), item->get_source(), item_name ? item_name : "(null)", item->interval, item->get_type_str(), LOG_STR_ARG(item->get_source()), item_name ? item_name : "(null)", item->interval,
item->next_execution_, now_64); item->next_execution_, now_64);
#endif /* ESPHOME_DEBUG_SCHEDULER */ #endif /* ESPHOME_DEBUG_SCHEDULER */

2
esphome/core/scheduler.h
View File

@@ -184,7 +184,7 @@ class Scheduler {
static bool cmp(const std::unique_ptr<SchedulerItem> &a, const std::unique_ptr<SchedulerItem> &b); static bool cmp(const std::unique_ptr<SchedulerItem> &a, const std::unique_ptr<SchedulerItem> &b);
const char *get_type_str() const { return (type == TIMEOUT) ? "timeout" : "interval"; } const char *get_type_str() const { return (type == TIMEOUT) ? "timeout" : "interval"; }
const char *get_source() const { return component ? component->get_component_source() : "unknown"; } const LogString *get_source() const { return component ? component->get_component_log_str() : LOG_STR("unknown"); }
}; };
// Common implementation for both timeout and interval // Common implementation for both timeout and interval

13
esphome/cpp_generator.py
View File

@@ -253,6 +253,19 @@ class StringLiteral(Literal):
return cpp_string_escape(self.string) return cpp_string_escape(self.string)
class LogStringLiteral(Literal):
"""A string literal that uses LOG_STR() macro for flash storage on ESP8266."""
__slots__ = ("string",)
def __init__(self, string: str) -> None:
super().__init__()
self.string = string
def __str__(self) -> str:
return f"LOG_STR({cpp_string_escape(self.string)})"
class IntLiteral(Literal): class IntLiteral(Literal):
__slots__ = ("i",) __slots__ = ("i",)

4
esphome/cpp_helpers.py
View File

@@ -9,7 +9,7 @@ from esphome.const import (
) )
from esphome.core import CORE, ID, coroutine from esphome.core import CORE, ID, coroutine
from esphome.coroutine import FakeAwaitable from esphome.coroutine import FakeAwaitable
from esphome.cpp_generator import add, get_variable from esphome.cpp_generator import LogStringLiteral, add, get_variable
from esphome.cpp_types import App from esphome.cpp_types import App
from esphome.types import ConfigFragmentType, ConfigType from esphome.types import ConfigFragmentType, ConfigType
from esphome.util import Registry, RegistryEntry from esphome.util import Registry, RegistryEntry
@@ -76,7 +76,7 @@ async def register_component(var, config):
"Error while finding name of component, please report this", exc_info=e "Error while finding name of component, please report this", exc_info=e
) )
if name is not None: if name is not None:
add(var.set_component_source(name)) add(var.set_component_source(LogStringLiteral(name)))
add(App.register_component(var)) add(App.register_component(var))
return var return var