From 5dfdd05122c58a3441c7e5237d03ba06763a5a91 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 13 Jan 2026 15:43:02 -1000 Subject: [PATCH 1/2] [logger] Use RAII guards for recursion protection and optimize hot path (#13194) Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> --- esphome/components/logger/logger.cpp | 66 +++++++++++++------- esphome/components/logger/logger.h | 90 +++++++++++++++------------- 2 files changed, 91 insertions(+), 65 deletions(-) diff --git a/esphome/components/logger/logger.cpp b/esphome/components/logger/logger.cpp index 1b41bc3d470..d7ed39c8e85 100644 --- a/esphome/components/logger/logger.cpp +++ b/esphome/components/logger/logger.cpp @@ -23,30 +23,57 @@ static const char *const TAG = "logger"; // - Messages are serialized through main loop for proper console output // - Fallback to emergency console logging only if ring buffer is full // - WITHOUT task log buffer: Only emergency console output, no callbacks +// +// Optimized for the common case: 99.9% of logs come from the main thread void HOT Logger::log_vprintf_(uint8_t level, const char *tag, int line, const char *format, va_list args) { // NOLINT if (level > this->level_for(tag)) return; #if defined(USE_ESP32) || defined(USE_LIBRETINY) + // Get task handle once - used for both main task check and passing to non-main thread handler TaskHandle_t current_task = xTaskGetCurrentTaskHandle(); - bool is_main_task = (current_task == main_task_); + const bool is_main_task = (current_task == this->main_task_); #else // USE_HOST - pthread_t current_thread = pthread_self(); - bool is_main_task = pthread_equal(current_thread, main_thread_); + const bool is_main_task = pthread_equal(pthread_self(), this->main_thread_); #endif - // Check and set recursion guard - uses pthread TLS for per-thread/task state - if (this->check_and_set_task_log_recursion_(is_main_task)) { - return; // Recursion detected - } - - // Main thread/task uses the shared buffer for efficiency - if (is_main_task) { + // Fast path: main thread, no recursion (99.9% of all logs) + if (is_main_task && !this->main_task_recursion_guard_) [[likely]] { + RecursionGuard guard(this->main_task_recursion_guard_); + // Format and send to both console and callbacks this->log_message_to_buffer_and_send_(level, tag, line, format, args); - this->reset_task_log_recursion_(is_main_task); return; } + // Main task with recursion - silently drop to prevent infinite loop + if (is_main_task) { + return; + } + + // Non-main thread handling (~0.1% of logs) +#if defined(USE_ESP32) || defined(USE_LIBRETINY) + this->log_vprintf_non_main_thread_(level, tag, line, format, args, current_task); +#else // USE_HOST + this->log_vprintf_non_main_thread_(level, tag, line, format, args); +#endif +} + +// Handles non-main thread logging only +// Kept separate from hot path to improve instruction cache performance +#if defined(USE_ESP32) || defined(USE_LIBRETINY) +void Logger::log_vprintf_non_main_thread_(uint8_t level, const char *tag, int line, const char *format, va_list args, + TaskHandle_t current_task) { +#else // USE_HOST +void Logger::log_vprintf_non_main_thread_(uint8_t level, const char *tag, int line, const char *format, va_list args) { +#endif + // Check if already in recursion for this non-main thread/task + if (this->is_non_main_task_recursive_()) { + return; + } + + // RAII guard - automatically resets on any return path + auto guard = this->make_non_main_task_guard_(); + bool message_sent = false; #ifdef USE_ESPHOME_TASK_LOG_BUFFER // For non-main threads/tasks, queue the message for callbacks @@ -85,21 +112,17 @@ void HOT Logger::log_vprintf_(uint8_t level, const char *tag, int line, const ch this->write_msg_(console_buffer, buffer_at); } - // Reset the recursion guard for this thread/task - this->reset_task_log_recursion_(is_main_task); + // RAII guard automatically resets on return } #else -// Implementation for all other platforms +// Implementation for all other platforms (single-task, no threading) void HOT Logger::log_vprintf_(uint8_t level, const char *tag, int line, const char *format, va_list args) { // NOLINT if (level > this->level_for(tag) || global_recursion_guard_) return; - global_recursion_guard_ = true; - + RecursionGuard guard(global_recursion_guard_); // Format and send to both console and callbacks this->log_message_to_buffer_and_send_(level, tag, line, format, args); - - global_recursion_guard_ = false; } #endif // USE_ESP32 / USE_HOST / USE_LIBRETINY @@ -130,7 +153,7 @@ void Logger::log_vprintf_(uint8_t level, const char *tag, int line, const __Flas if (level > this->level_for(tag) || global_recursion_guard_) return; - global_recursion_guard_ = true; + RecursionGuard guard(global_recursion_guard_); this->tx_buffer_at_ = 0; // Copy format string from progmem @@ -140,9 +163,8 @@ void Logger::log_vprintf_(uint8_t level, const char *tag, int line, const __Flas this->tx_buffer_[this->tx_buffer_at_++] = ch = (char) progmem_read_byte(format_pgm_p++); } - // Buffer full from copying format + // Buffer full from copying format - RAII guard handles cleanup on return if (this->tx_buffer_at_ >= this->tx_buffer_size_) { - global_recursion_guard_ = false; // Make sure to reset the recursion guard before returning return; } @@ -161,8 +183,6 @@ void Logger::log_vprintf_(uint8_t level, const char *tag, int line, const __Flas // Write to console starting at the msg_start this->write_tx_buffer_to_console_(msg_start, &msg_length); - - global_recursion_guard_ = false; } #endif // USE_STORE_LOG_STR_IN_FLASH diff --git a/esphome/components/logger/logger.h b/esphome/components/logger/logger.h index c58ca8ddce6..306bc9b1434 100644 --- a/esphome/components/logger/logger.h +++ b/esphome/components/logger/logger.h @@ -229,6 +229,31 @@ class Logger : public Component { #endif protected: + // RAII guard for recursion flags - sets flag on construction, clears on destruction + class RecursionGuard { + public: + explicit RecursionGuard(bool &flag) : flag_(flag) { flag_ = true; } + ~RecursionGuard() { flag_ = false; } + RecursionGuard(const RecursionGuard &) = delete; + RecursionGuard &operator=(const RecursionGuard &) = delete; + RecursionGuard(RecursionGuard &&) = delete; + RecursionGuard &operator=(RecursionGuard &&) = delete; + + private: + bool &flag_; + }; + +#if defined(USE_ESP32) || defined(USE_HOST) || defined(USE_LIBRETINY) + // Handles non-main thread logging only (~0.1% of calls) +#if defined(USE_ESP32) || defined(USE_LIBRETINY) + // ESP32/LibreTiny: Pass task handle to avoid calling xTaskGetCurrentTaskHandle() twice + void log_vprintf_non_main_thread_(uint8_t level, const char *tag, int line, const char *format, va_list args, + TaskHandle_t current_task); +#else // USE_HOST + // Host: No task handle parameter needed (not used in send_message_thread_safe) + void log_vprintf_non_main_thread_(uint8_t level, const char *tag, int line, const char *format, va_list args); +#endif +#endif void process_messages_(); void write_msg_(const char *msg, size_t len); @@ -348,10 +373,10 @@ class Logger : public Component { const device *uart_dev_{nullptr}; #endif #if defined(USE_ESP32) || defined(USE_LIBRETINY) || defined(USE_ZEPHYR) - void *main_task_ = nullptr; // Only used for thread name identification + void *main_task_{nullptr}; // Main thread/task for fast path comparison #endif #ifdef USE_HOST - pthread_t main_thread_{}; // Main thread for identification + pthread_t main_thread_{}; // Main thread for pthread_equal() comparison #endif #ifdef USE_ESP32 // Task-specific recursion guards: @@ -434,29 +459,28 @@ class Logger : public Component { #endif #if defined(USE_ESP32) || defined(USE_HOST) - inline bool HOT check_and_set_task_log_recursion_(bool is_main_task) { - if (is_main_task) { - const bool was_recursive = main_task_recursion_guard_; - main_task_recursion_guard_ = true; - return was_recursive; + // RAII guard for non-main task recursion using pthread TLS + class NonMainTaskRecursionGuard { + public: + explicit NonMainTaskRecursionGuard(pthread_key_t key) : key_(key) { + pthread_setspecific(key_, reinterpret_cast(1)); } + ~NonMainTaskRecursionGuard() { pthread_setspecific(key_, nullptr); } + NonMainTaskRecursionGuard(const NonMainTaskRecursionGuard &) = delete; + NonMainTaskRecursionGuard &operator=(const NonMainTaskRecursionGuard &) = delete; + NonMainTaskRecursionGuard(NonMainTaskRecursionGuard &&) = delete; + NonMainTaskRecursionGuard &operator=(NonMainTaskRecursionGuard &&) = delete; - intptr_t current = (intptr_t) pthread_getspecific(log_recursion_key_); - if (current != 0) - return true; + private: + pthread_key_t key_; + }; - pthread_setspecific(log_recursion_key_, (void *) 1); - return false; - } + // Check if non-main task is already in recursion (via TLS) + inline bool HOT is_non_main_task_recursive_() const { return pthread_getspecific(log_recursion_key_) != nullptr; } - inline void HOT reset_task_log_recursion_(bool is_main_task) { - if (is_main_task) { - main_task_recursion_guard_ = false; - return; - } + // Create RAII guard for non-main task recursion + inline NonMainTaskRecursionGuard make_non_main_task_guard_() { return NonMainTaskRecursionGuard(log_recursion_key_); } - pthread_setspecific(log_recursion_key_, (void *) 0); - } #elif defined(USE_LIBRETINY) // LibreTiny doesn't have FreeRTOS TLS, so use a simple approach: // - Main task uses dedicated boolean (same as ESP32) @@ -466,29 +490,11 @@ class Logger : public Component { // - Cross-task "recursion" is prevented by the buffer mutex anyway // - Missing a recursive call from another task is acceptable (falls back to direct output) - inline bool HOT check_and_set_task_log_recursion_(bool is_main_task) { - if (is_main_task) { - const bool was_recursive = main_task_recursion_guard_; - main_task_recursion_guard_ = true; - return was_recursive; - } + // Check if non-main task is already in recursion + inline bool HOT is_non_main_task_recursive_() const { return non_main_task_recursion_guard_; } - // For non-main tasks, use a simple shared guard - // This may block legitimate concurrent logs from different tasks, - // but that's acceptable - they'll fall back to direct console output - const bool was_recursive = non_main_task_recursion_guard_; - non_main_task_recursion_guard_ = true; - return was_recursive; - } - - inline void HOT reset_task_log_recursion_(bool is_main_task) { - if (is_main_task) { - main_task_recursion_guard_ = false; - return; - } - - non_main_task_recursion_guard_ = false; - } + // Create RAII guard for non-main task recursion (uses shared boolean for all non-main tasks) + inline RecursionGuard make_non_main_task_guard_() { return RecursionGuard(non_main_task_recursion_guard_); } #endif #ifdef USE_HOST From 2793e33baf8bded6e0c68704caf2527891d777d4 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 13 Jan 2026 15:43:17 -1000 Subject: [PATCH 2/2] [logger] Use StaticVector for log listeners with compile-time sizing (#13196) Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> --- esphome/components/api/__init__.py | 4 ++++ esphome/components/ble_nus/__init__.py | 6 +++++- esphome/components/logger/__init__.py | 22 +++++++++++++++++++++- esphome/components/logger/logger.cpp | 2 ++ esphome/components/logger/logger.h | 14 +++++++++++++- esphome/components/mqtt/__init__.py | 3 +++ esphome/components/syslog/__init__.py | 3 ++- esphome/components/web_server/__init__.py | 3 +++ esphome/core/defines.h | 2 ++ 9 files changed, 55 insertions(+), 4 deletions(-) diff --git a/esphome/components/api/__init__.py b/esphome/components/api/__init__.py index 0e2c612279b..9bff9f56355 100644 --- a/esphome/components/api/__init__.py +++ b/esphome/components/api/__init__.py @@ -4,6 +4,7 @@ import logging from esphome import automation from esphome.automation import Condition import esphome.codegen as cg +from esphome.components.logger import request_log_listener from esphome.config_helpers import get_logger_level import esphome.config_validation as cv from esphome.const import ( @@ -326,6 +327,9 @@ async def to_code(config: ConfigType) -> None: # Track controller registration for StaticVector sizing CORE.register_controller() + # Request a log listener slot for API log streaming + request_log_listener() + cg.add(var.set_port(config[CONF_PORT])) cg.add(var.set_reboot_timeout(config[CONF_REBOOT_TIMEOUT])) cg.add(var.set_batch_delay(config[CONF_BATCH_DELAY])) diff --git a/esphome/components/ble_nus/__init__.py b/esphome/components/ble_nus/__init__.py index 9570005902a..6581ce1cfab 100644 --- a/esphome/components/ble_nus/__init__.py +++ b/esphome/components/ble_nus/__init__.py @@ -1,4 +1,5 @@ import esphome.codegen as cg +from esphome.components.logger import request_log_listener from esphome.components.zephyr import zephyr_add_prj_conf import esphome.config_validation as cv from esphome.const import CONF_ID, CONF_LOGS, CONF_TYPE @@ -25,5 +26,8 @@ CONFIG_SCHEMA = cv.All( async def to_code(config): var = cg.new_Pvariable(config[CONF_ID]) zephyr_add_prj_conf("BT_NUS", True) - cg.add(var.set_expose_log(config[CONF_TYPE] == CONF_LOGS)) + expose_log = config[CONF_TYPE] == CONF_LOGS + cg.add(var.set_expose_log(expose_log)) + if expose_log: + request_log_listener() # Request a log listener slot for BLE NUS log streaming await cg.register_component(var, config) diff --git a/esphome/components/logger/__init__.py b/esphome/components/logger/__init__.py index 7691458df50..cadd0a14ae9 100644 --- a/esphome/components/logger/__init__.py +++ b/esphome/components/logger/__init__.py @@ -421,6 +421,7 @@ async def to_code(config): await cg.register_component(log, config) for conf in config.get(CONF_ON_MESSAGE, []): + request_log_listener() # Each on_message trigger needs a listener slot trigger = cg.new_Pvariable( conf[CONF_TRIGGER_ID], log, LOG_LEVEL_SEVERITY.index(conf[CONF_LEVEL]) ) @@ -546,6 +547,7 @@ FILTER_SOURCE_FILES = filter_source_files_from_platform( # Keys for CORE.data storage DOMAIN = "logger" KEY_LEVEL_LISTENERS = "level_listeners" +KEY_LOG_LISTENERS = "log_listeners" def request_logger_level_listeners() -> None: @@ -558,8 +560,26 @@ def request_logger_level_listeners() -> None: CORE.data.setdefault(DOMAIN, {})[KEY_LEVEL_LISTENERS] = True +def request_log_listener() -> None: + """Request a log listener slot. + + Components that need to receive log messages should call this function + during their code generation. This increments the listener count used + to size the StaticVector. + """ + data = CORE.data.setdefault(DOMAIN, {}) + data[KEY_LOG_LISTENERS] = data.get(KEY_LOG_LISTENERS, 0) + 1 + + @coroutine_with_priority(CoroPriority.FINAL) async def final_step(): """Final code generation step to configure optional logger features.""" - if CORE.data.get(DOMAIN, {}).get(KEY_LEVEL_LISTENERS, False): + domain_data = CORE.data.get(DOMAIN, {}) + if domain_data.get(KEY_LEVEL_LISTENERS, False): cg.add_define("USE_LOGGER_LEVEL_LISTENERS") + + # Only generate log listener code if any component needs it + log_listener_count = domain_data.get(KEY_LOG_LISTENERS, 0) + if log_listener_count > 0: + cg.add_define("USE_LOG_LISTENERS") + cg.add_define("ESPHOME_LOG_MAX_LISTENERS", log_listener_count) diff --git a/esphome/components/logger/logger.cpp b/esphome/components/logger/logger.cpp index d7ed39c8e85..34430dbafaf 100644 --- a/esphome/components/logger/logger.cpp +++ b/esphome/components/logger/logger.cpp @@ -178,8 +178,10 @@ void Logger::log_vprintf_(uint8_t level, const char *tag, int line, const __Flas this->tx_buffer_at_ - msg_start; // Don't subtract 1 - tx_buffer_at_ is already at the null terminator position // Listeners get message first (before console write) +#ifdef USE_LOG_LISTENERS for (auto *listener : this->log_listeners_) listener->on_log(level, tag, this->tx_buffer_ + msg_start, msg_length); +#endif // Write to console starting at the msg_start this->write_tx_buffer_to_console_(msg_start, &msg_length); diff --git a/esphome/components/logger/logger.h b/esphome/components/logger/logger.h index 306bc9b1434..3e8538c2aee 100644 --- a/esphome/components/logger/logger.h +++ b/esphome/components/logger/logger.h @@ -212,8 +212,13 @@ class Logger : public Component { inline uint8_t level_for(const char *tag); +#ifdef USE_LOG_LISTENERS /// Register a log listener to receive log messages void add_log_listener(LogListener *listener) { this->log_listeners_.push_back(listener); } +#else + /// No-op when log listeners are disabled + void add_log_listener(LogListener *listener) {} +#endif #ifdef USE_LOGGER_LEVEL_LISTENERS /// Register a listener for log level changes @@ -318,8 +323,10 @@ class Logger : public Component { this->tx_buffer_size_); // Listeners get message WITHOUT newline (for API/MQTT/syslog) +#ifdef USE_LOG_LISTENERS for (auto *listener : this->log_listeners_) listener->on_log(level, tag, this->tx_buffer_, this->tx_buffer_at_); +#endif // Console gets message WITH newline (if platform needs it) this->write_tx_buffer_to_console_(); @@ -336,8 +343,10 @@ class Logger : public Component { this->write_body_to_buffer_(text, text_length, this->tx_buffer_, &this->tx_buffer_at_, this->tx_buffer_size_); this->write_footer_to_buffer_(this->tx_buffer_, &this->tx_buffer_at_, this->tx_buffer_size_); this->tx_buffer_[this->tx_buffer_at_] = '\0'; +#ifdef USE_LOG_LISTENERS for (auto *listener : this->log_listeners_) listener->on_log(level, tag, this->tx_buffer_, this->tx_buffer_at_); +#endif } #endif @@ -394,7 +403,10 @@ class Logger : public Component { #ifdef USE_LOGGER_RUNTIME_TAG_LEVELS std::map log_levels_{}; #endif - std::vector log_listeners_; // Log message listeners (API, MQTT, syslog, etc.) +#ifdef USE_LOG_LISTENERS + StaticVector + log_listeners_; // Log message listeners (API, MQTT, syslog, etc.) +#endif #ifdef USE_LOGGER_LEVEL_LISTENERS std::vector level_listeners_; // Log level change listeners #endif diff --git a/esphome/components/mqtt/__init__.py b/esphome/components/mqtt/__init__.py index f7518771d7a..f53df5564cd 100644 --- a/esphome/components/mqtt/__init__.py +++ b/esphome/components/mqtt/__init__.py @@ -350,6 +350,7 @@ def exp_mqtt_message(config): async def to_code(config): var = cg.new_Pvariable(config[CONF_ID]) await cg.register_component(var, config) + # Add required libraries for ESP8266 and LibreTiny if CORE.is_esp8266 or CORE.is_libretiny: # https://github.com/heman/async-mqtt-client/blob/master/library.json @@ -432,6 +433,8 @@ async def to_code(config): cg.add(var.disable_log_message()) else: cg.add(var.set_log_message_template(exp_mqtt_message(log_topic))) + # Request a log listener slot only when log topic is enabled + logger.request_log_listener() if CONF_LEVEL in log_topic: cg.add(var.set_log_level(logger.LOG_LEVELS[log_topic[CONF_LEVEL]])) diff --git a/esphome/components/syslog/__init__.py b/esphome/components/syslog/__init__.py index 80b79d20402..08626404f7e 100644 --- a/esphome/components/syslog/__init__.py +++ b/esphome/components/syslog/__init__.py @@ -1,6 +1,6 @@ import esphome.codegen as cg from esphome.components import udp -from esphome.components.logger import LOG_LEVELS, is_log_level +from esphome.components.logger import LOG_LEVELS, is_log_level, request_log_listener from esphome.components.time import RealTimeClock from esphome.components.udp import CONF_UDP_ID import esphome.config_validation as cv @@ -36,6 +36,7 @@ async def to_code(config): level = LOG_LEVELS[config[CONF_LEVEL]] var = cg.new_Pvariable(config[CONF_ID], level, time) await cg.register_component(var, config) + request_log_listener() # Request a log listener slot for syslog await cg.register_parented(var, parent) cg.add(var.set_strip(config[CONF_STRIP])) cg.add(var.set_facility(config[CONF_FACILITY])) diff --git a/esphome/components/web_server/__init__.py b/esphome/components/web_server/__init__.py index 7937e7a5403..16ac9d054cb 100644 --- a/esphome/components/web_server/__init__.py +++ b/esphome/components/web_server/__init__.py @@ -4,6 +4,7 @@ import gzip import esphome.codegen as cg from esphome.components import web_server_base +from esphome.components.logger import request_log_listener from esphome.components.web_server_base import CONF_WEB_SERVER_BASE_ID import esphome.config_validation as cv from esphome.const import ( @@ -313,6 +314,8 @@ async def to_code(config): if config.get(CONF_OTA) is False: cg.add_define("USE_WEBSERVER_OTA_DISABLED") cg.add(var.set_expose_log(config[CONF_LOG])) + if config[CONF_LOG]: + request_log_listener() # Request a log listener slot for web server log streaming if config[CONF_ENABLE_PRIVATE_NETWORK_ACCESS]: cg.add_define("USE_WEBSERVER_PRIVATE_NETWORK_ACCESS") if CONF_AUTH in config: diff --git a/esphome/core/defines.h b/esphome/core/defines.h index 633b0c6c5e4..3cc48c6008b 100644 --- a/esphome/core/defines.h +++ b/esphome/core/defines.h @@ -20,6 +20,8 @@ // logger #define ESPHOME_LOG_LEVEL ESPHOME_LOG_LEVEL_VERY_VERBOSE +#define USE_LOG_LISTENERS +#define ESPHOME_LOG_MAX_LISTENERS 8 // Feature flags #define USE_ALARM_CONTROL_PANEL