mirror of
				https://github.com/esphome/esphome.git
				synced 2025-10-30 22:53:59 +00:00 
			
		
		
		
	[core] Store component source strings in flash on ESP8266 (breaking change) (#10621)
This commit is contained in:
		| @@ -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); | ||||
|   | ||||
| @@ -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<ComponentStatPair> 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,12 +47,9 @@ void RuntimeStatsCollector::log_stats_() { | ||||
|  | ||||
|   // Log top components by period runtime | ||||
|   for (const auto &it : stats_to_display) { | ||||
|     const char *source = it.name; | ||||
|     const ComponentRuntimeStats *stats = it.stats; | ||||
|  | ||||
|     ESP_LOGI(TAG, "  %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", source, | ||||
|              stats->get_period_count(), stats->get_period_avg_time_ms(), stats->get_period_max_time_ms(), | ||||
|              stats->get_period_time_ms()); | ||||
|     ESP_LOGI(TAG, "  %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", | ||||
|              LOG_STR_ARG(it.component->get_component_log_str()), it.stats->get_period_count(), | ||||
|              it.stats->get_period_avg_time_ms(), it.stats->get_period_max_time_ms(), it.stats->get_period_time_ms()); | ||||
|   } | ||||
|  | ||||
|   // Log total stats since boot | ||||
| @@ -72,12 +62,9 @@ void RuntimeStatsCollector::log_stats_() { | ||||
|             }); | ||||
|  | ||||
|   for (const auto &it : stats_to_display) { | ||||
|     const char *source = it.name; | ||||
|     const ComponentRuntimeStats *stats = it.stats; | ||||
|  | ||||
|     ESP_LOGI(TAG, "  %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", source, | ||||
|              stats->get_total_count(), stats->get_total_avg_time_ms(), stats->get_total_max_time_ms(), | ||||
|              stats->get_total_time_ms()); | ||||
|     ESP_LOGI(TAG, "  %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms", | ||||
|              LOG_STR_ARG(it.component->get_component_log_str()), it.stats->get_total_count(), | ||||
|              it.stats->get_total_avg_time_ms(), it.stats->get_total_max_time_ms(), it.stats->get_total_time_ms()); | ||||
|   } | ||||
| } | ||||
|  | ||||
|   | ||||
| @@ -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<const char *, ComponentRuntimeStats, CStrCompare> component_stats_; | ||||
|   std::map<Component *, const char *> component_names_cache_; | ||||
|   // Map from component to its stats | ||||
|   // We use Component* as the key since each component is unique | ||||
|   std::map<Component *, ComponentRuntimeStats> component_stats_; | ||||
|   uint32_t log_interval_; | ||||
|   uint32_t next_log_time_; | ||||
| }; | ||||
|   | ||||
| @@ -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; | ||||
|  | ||||
|   | ||||
| @@ -141,7 +141,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 : LOG_STR_LITERAL("unspecified")); | ||||
|   } | ||||
| } | ||||
| @@ -153,14 +153,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; | ||||
|     } | ||||
| @@ -181,10 +181,8 @@ void Component::call() { | ||||
|       break; | ||||
|   } | ||||
| } | ||||
| const char *Component::get_component_source() const { | ||||
|   if (this->component_source_ == nullptr) | ||||
|     return "<unknown>"; | ||||
|   return this->component_source_; | ||||
| const LogString *Component::get_component_log_str() const { | ||||
|   return this->component_source_ == nullptr ? LOG_STR("<unknown>") : this->component_source_; | ||||
| } | ||||
| bool Component::should_warn_of_blocking(uint32_t blocking_time) { | ||||
|   if (blocking_time > this->warn_if_blocking_over_) { | ||||
| @@ -200,7 +198,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 | ||||
| @@ -212,14 +210,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); | ||||
|   } | ||||
| @@ -239,7 +237,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,7 +284,7 @@ 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(), | ||||
|   ESP_LOGW(TAG, "%s set Warning flag: %s", LOG_STR_ARG(this->get_component_log_str()), | ||||
|            message ? message : LOG_STR_LITERAL("unspecified")); | ||||
| } | ||||
| void Component::status_set_warning(const LogString *message) { | ||||
| @@ -295,7 +293,7 @@ void Component::status_set_warning(const LogString *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(), | ||||
|   ESP_LOGW(TAG, "%s set Warning flag: %s", LOG_STR_ARG(this->get_component_log_str()), | ||||
|            message ? LOG_STR_ARG(message) : LOG_STR_LITERAL("unspecified")); | ||||
| } | ||||
| void Component::status_set_error(const char *message) { | ||||
| @@ -303,7 +301,7 @@ void Component::status_set_error(const char *message) { | ||||
|     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(), | ||||
|   ESP_LOGE(TAG, "%s set Error flag: %s", LOG_STR_ARG(this->get_component_log_str()), | ||||
|            message ? message : LOG_STR_LITERAL("unspecified")); | ||||
|   if (message != nullptr) { | ||||
|     // Lazy allocate the error messages vector if needed | ||||
| @@ -325,13 +323,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(); | ||||
| @@ -442,8 +440,9 @@ uint32_t WarnIfComponentBlockingGuard::finish() { | ||||
|     should_warn = blocking_time > WARN_IF_BLOCKING_OVER_MS; | ||||
|   } | ||||
|   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)", src, blocking_time); | ||||
|     ESP_LOGW(TAG, "%s took a long time for an operation (%" PRIu32 " ms)", | ||||
|              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"); | ||||
|   } | ||||
|  | ||||
|   | ||||
| @@ -5,6 +5,7 @@ | ||||
| #include <functional> | ||||
| #include <string> | ||||
|  | ||||
| #include "esphome/core/log.h" | ||||
| #include "esphome/core/optional.h" | ||||
|  | ||||
| namespace esphome { | ||||
| @@ -223,12 +224,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 "<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); | ||||
|  | ||||
| @@ -408,7 +409,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) | ||||
|   | ||||
| @@ -162,10 +162,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<uint32_t>(item->get_next_execution() - now)); | ||||
|   } | ||||
| @@ -387,7 +387,7 @@ void HOT Scheduler::call(uint32_t now) { | ||||
|       const char *name = item->get_name(); | ||||
|       bool is_cancelled = is_item_removed_(item.get()); | ||||
|       ESP_LOGD(TAG, "  %s '%s/%s' interval=%" PRIu32 " next_execution in %" PRIu64 "ms at %" PRIu64 "%s", | ||||
|                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->get_next_execution() - now_64, item->get_next_execution(), is_cancelled ? " [CANCELLED]" : ""); | ||||
|  | ||||
|       old_items.push_back(std::move(item)); | ||||
| @@ -478,7 +478,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->get_next_execution(), now_64); | ||||
| #endif /* ESPHOME_DEBUG_SCHEDULER */ | ||||
|  | ||||
|   | ||||
| @@ -204,7 +204,7 @@ class Scheduler { | ||||
|       next_execution_high_ = static_cast<uint16_t>(value >> 32); | ||||
|     } | ||||
|     constexpr 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 | ||||
|   | ||||
| @@ -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",) | ||||
|  | ||||
|   | ||||
| @@ -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 | ||||
|   | ||||
		Reference in New Issue
	
	Block a user