From c84928aba5a7924fc14adebb91d02144a07e4f02 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Fri, 5 Sep 2025 17:08:11 -0500 Subject: [PATCH] [core] Store component source strings in flash on ESP8266 (breaking change) --- esphome/components/debug/debug_esp32.cpp | 2 +- .../runtime_stats/runtime_stats.cpp | 19 ++++------ .../components/runtime_stats/runtime_stats.h | 14 +++----- esphome/core/application.cpp | 8 ++--- esphome/core/component.cpp | 35 ++++++++++--------- esphome/core/component.h | 11 +++--- esphome/core/scheduler.cpp | 8 ++--- esphome/core/scheduler.h | 2 +- esphome/cpp_generator.py | 13 +++++++ esphome/cpp_helpers.py | 4 +-- 10 files changed, 59 insertions(+), 57 deletions(-) diff --git a/esphome/components/debug/debug_esp32.cpp b/esphome/components/debug/debug_esp32.cpp index 37990aeec5..b1dfe1bc9a 100644 --- a/esphome/components/debug/debug_esp32.cpp +++ b/esphome/components/debug/debug_esp32.cpp @@ -52,7 +52,7 @@ void DebugComponent::on_shutdown() { char buffer[REBOOT_MAX_LEN]{}; auto pref = global_preferences->make_preference(REBOOT_MAX_LEN, fnv1_hash(REBOOT_KEY + App.get_name())); 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'; } ESP_LOGD(TAG, "Storing reboot source: %s", buffer); diff --git a/esphome/components/runtime_stats/runtime_stats.cpp b/esphome/components/runtime_stats/runtime_stats.cpp index 8f5d5daf01..2da517b1f4 100644 --- a/esphome/components/runtime_stats/runtime_stats.cpp +++ b/esphome/components/runtime_stats/runtime_stats.cpp @@ -17,16 +17,8 @@ void RuntimeStatsCollector::record_component_time(Component *component, uint32_t if (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 { - this->component_stats_[name_it->second].record_time(duration_ms); - } + // Record stats using component pointer as key + this->component_stats_[component].record_time(duration_ms); if (this->next_log_time_ == 0) { this->next_log_time_ = current_time + this->log_interval_; @@ -42,9 +34,10 @@ void RuntimeStatsCollector::log_stats_() { std::vector stats_to_display; for (const auto &it : this->component_stats_) { + Component *component = it.first; const ComponentRuntimeStats &stats = it.second; if (stats.get_period_count() > 0) { - ComponentStatPair pair = {it.first, &stats}; + ComponentStatPair pair = {component, &stats}; stats_to_display.push_back(pair); } } @@ -54,7 +47,7 @@ void RuntimeStatsCollector::log_stats_() { // Log top components by period runtime 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; 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) { - const char *source = it.name; + const char *source = LOG_STR_ARG(it.component->get_component_log_str()); const ComponentRuntimeStats *stats = it.stats; ESP_LOGI(TAG, " %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", source, diff --git a/esphome/components/runtime_stats/runtime_stats.h b/esphome/components/runtime_stats/runtime_stats.h index e2f8bee563..56122364c2 100644 --- a/esphome/components/runtime_stats/runtime_stats.h +++ b/esphome/components/runtime_stats/runtime_stats.h @@ -79,7 +79,7 @@ class ComponentRuntimeStats { // For sorting components by run time struct ComponentStatPair { - const char *name; + Component *component; const ComponentRuntimeStats *stats; bool operator>(const ComponentStatPair &other) const { @@ -109,15 +109,9 @@ class RuntimeStatsCollector { } } - // Use const char* keys for efficiency - // Custom comparator for const char* keys in map - // Without this, std::map would compare pointer addresses instead of string contents, - // 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 component_stats_; - std::map component_names_cache_; + // Map from component to its stats + // We use Component* as the key since each component is unique + std::map component_stats_; uint32_t log_interval_; uint32_t next_log_time_; }; diff --git a/esphome/core/application.cpp b/esphome/core/application.cpp index dc745a2a46..b78f6fb903 100644 --- a/esphome/core/application.cpp +++ b/esphome/core/application.cpp @@ -80,7 +80,7 @@ void Application::register_component_(Component *comp) { for (auto *c : this->components_) { 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; } } @@ -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, // so this warning will only appear via serial rather than being transmitted to clients 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(), - timeout_ms); + ESP_LOGW(TAG, "%s did not complete teardown within %" PRIu32 " 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 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_LOOP; diff --git a/esphome/core/component.cpp b/esphome/core/component.cpp index 40cda17ca3..3f6beeb28e 100644 --- a/esphome/core/component.cpp +++ b/esphome/core/component.cpp @@ -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); } } @@ -154,14 +154,14 @@ void Component::call() { case COMPONENT_STATE_CONSTRUCTION: { // State Construction: Call setup and set state to 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 uint32_t start_time = millis(); #endif this->call_setup(); #if ESPHOME_LOG_LEVEL >= ESPHOME_LOG_LEVEL_DEBUG 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 break; } @@ -182,10 +182,8 @@ void Component::call() { break; } } -const char *Component::get_component_source() const { - if (this->component_source_ == nullptr) - return ""; - return this->component_source_; +const LogString *Component::get_component_log_str() const { + return this->component_source_ == nullptr ? LOG_STR("") : this->component_source_; } bool Component::should_warn_of_blocking(uint32_t blocking_time) { if (blocking_time > this->warn_if_blocking_over_) { @@ -201,7 +199,7 @@ bool Component::should_warn_of_blocking(uint32_t blocking_time) { return false; } 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->status_set_error(); // 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() { 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); App.disable_component_loop_(this); } } void Component::enable_loop() { 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); 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() { 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); // Clear error status when resetting this->status_clear_error(); @@ -286,14 +284,16 @@ void Component::status_set_warning(const char *message) { return; this->component_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) { if ((this->component_state_ & STATUS_LED_ERROR) != 0) return; this->component_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) { // Lazy allocate the error messages vector if needed if (!component_error_messages) { @@ -314,13 +314,13 @@ void Component::status_clear_warning() { if ((this->component_state_ & STATUS_LED_WARNING) == 0) return; 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() { if ((this->component_state_ & STATUS_LED_ERROR) == 0) return; 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) { this->status_set_warning(); @@ -419,8 +419,9 @@ uint32_t WarnIfComponentBlockingGuard::finish() { should_warn = blocking_time > WARN_IF_BLOCKING_OVER_MS; } if (should_warn) { - const char *src = component_ == nullptr ? "" : component_->get_component_source(); - ESP_LOGW(TAG, "%s took a long time for an operation (%" PRIu32 " ms)", src, blocking_time); + ESP_LOGW(TAG, "%s took a long time for an operation (%" PRIu32 " ms)", + component_ == nullptr ? LOG_STR_LITERAL("") : LOG_STR_ARG(component_->get_component_log_str()), + 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 096c6f9c69..9a7e442c5c 100644 --- a/esphome/core/component.h +++ b/esphome/core/component.h @@ -5,6 +5,7 @@ #include #include +#include "esphome/core/log.h" #include "esphome/core/optional.h" namespace esphome { @@ -220,12 +221,12 @@ class Component { * * This is set by the ESPHome core, and should not be called manually. */ - void set_component_source(const char *source) { component_source_ = source; } - /** Get the integration where this component was declared as a string. + void set_component_source(const LogString *source) { component_source_ = source; } + /** Get the integration where this component was declared as a LogString for logging. * - * Returns "" if source not set + * Returns LOG_STR("") 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); @@ -405,7 +406,7 @@ class Component { bool cancel_defer(const std::string &name); // NOLINT // 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) /// 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) diff --git a/esphome/core/scheduler.cpp b/esphome/core/scheduler.cpp index a907b89b02..1552ac8862 100644 --- a/esphome/core/scheduler.cpp +++ b/esphome/core/scheduler.cpp @@ -134,10 +134,10 @@ void HOT Scheduler::set_timer_common_(Component *component, SchedulerItem::Type // Debug logging const char *type_str = (type == SchedulerItem::TIMEOUT) ? "timeout" : "interval"; 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); } 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(item->next_execution_ - now)); } #endif /* ESPHOME_DEBUG_SCHEDULER */ @@ -353,7 +353,7 @@ void HOT Scheduler::call(uint32_t now) { const char *name = item->get_name(); 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_); old_items.push_back(std::move(item)); @@ -439,7 +439,7 @@ void HOT Scheduler::call(uint32_t now) { #ifdef ESPHOME_DEBUG_SCHEDULER const char *item_name = item->get_name(); 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); #endif /* ESPHOME_DEBUG_SCHEDULER */ diff --git a/esphome/core/scheduler.h b/esphome/core/scheduler.h index f469a60d5c..39141efcad 100644 --- a/esphome/core/scheduler.h +++ b/esphome/core/scheduler.h @@ -184,7 +184,7 @@ class Scheduler { static bool cmp(const std::unique_ptr &a, const std::unique_ptr &b); 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 diff --git a/esphome/cpp_generator.py b/esphome/cpp_generator.py index 34e4eec1ee..291592dd2b 100644 --- a/esphome/cpp_generator.py +++ b/esphome/cpp_generator.py @@ -253,6 +253,19 @@ class StringLiteral(Literal): 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): __slots__ = ("i",) diff --git a/esphome/cpp_helpers.py b/esphome/cpp_helpers.py index b61b215bdc..2698b9b3d5 100644 --- a/esphome/cpp_helpers.py +++ b/esphome/cpp_helpers.py @@ -9,7 +9,7 @@ from esphome.const import ( ) from esphome.core import CORE, ID, coroutine 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.types import ConfigFragmentType, ConfigType 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 ) if name is not None: - add(var.set_component_source(name)) + add(var.set_component_source(LogStringLiteral(name))) add(App.register_component(var)) return var