From 30f9bfaf83719bd941a316057e89bc4481090ac0 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sat, 7 Feb 2026 07:47:00 +0100 Subject: [PATCH] [logger] Resolve thread name once and pass through logging chain Eliminate redundant xTaskGetCurrentTaskHandle() and pcTaskGetName() calls on the hot path by resolving the thread name once in log_vprintf_ and passing it through as const char* to all downstream functions. - Main task fast path passes nullptr (no task handle lookup needed) - Non-main thread path resolves name once, passes to both ring buffer and emergency console fallback - Unify log_vprintf_non_main_thread_ to single signature across platforms - Change send_message_thread_safe() on all platforms from TaskHandle_t to const char* thread_name - Add TaskHandle_t overload for get_thread_name_ as primary on ESP32/LibreTiny, with no-arg convenience wrapper - Use std::span for Host/Zephyr get_thread_name_ buffer parameter - Document Zephyr single-task path thread safety limitation --- esphome/components/logger/logger.cpp | 43 ++++--- esphome/components/logger/logger.h | 114 +++++++++--------- .../logger/task_log_buffer_esp32.cpp | 3 +- .../components/logger/task_log_buffer_esp32.h | 2 +- .../logger/task_log_buffer_host.cpp | 12 +- .../components/logger/task_log_buffer_host.h | 3 +- .../logger/task_log_buffer_libretiny.cpp | 3 +- .../logger/task_log_buffer_libretiny.h | 2 +- 8 files changed, 93 insertions(+), 89 deletions(-) diff --git a/esphome/components/logger/logger.cpp b/esphome/components/logger/logger.cpp index 4cbd4f1bf1..bb20c403e5 100644 --- a/esphome/components/logger/logger.cpp +++ b/esphome/components/logger/logger.cpp @@ -36,8 +36,9 @@ void HOT Logger::log_vprintf_(uint8_t level, const char *tag, int line, const ch #endif // Fast path: main thread, no recursion (99.9% of all logs) + // Pass nullptr for thread_name since we already know this is the main task if (is_main_task && !this->main_task_recursion_guard_) [[likely]] { - this->log_message_to_buffer_and_send_(this->main_task_recursion_guard_, level, tag, line, format, args); + this->log_message_to_buffer_and_send_(this->main_task_recursion_guard_, level, tag, line, format, args, nullptr); return; } @@ -47,21 +48,23 @@ void HOT Logger::log_vprintf_(uint8_t level, const char *tag, int line, const ch } // Non-main thread handling (~0.1% of logs) + // Resolve thread name once and pass it through the logging chain. + // ESP32/LibreTiny: use TaskHandle_t overload to avoid redundant xTaskGetCurrentTaskHandle() + // (we already have the handle from the main task check above). + // Host: pass a stack buffer for pthread_getname_np to write into. #if defined(USE_ESP32) || defined(USE_LIBRETINY) - this->log_vprintf_non_main_thread_(level, tag, line, format, args, current_task); + const char *thread_name = get_thread_name_(current_task); #else // USE_HOST - this->log_vprintf_non_main_thread_(level, tag, line, format, args); + char thread_name_buf[THREAD_NAME_BUF_SIZE]; + const char *thread_name = this->get_thread_name_(thread_name_buf); #endif + this->log_vprintf_non_main_thread_(level, tag, line, format, args, thread_name); } // 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 + const char *thread_name) { // Check if already in recursion for this non-main thread/task if (this->is_non_main_task_recursive_()) { return; @@ -73,12 +76,8 @@ void Logger::log_vprintf_non_main_thread_(uint8_t level, const char *tag, int li bool message_sent = false; #ifdef USE_ESPHOME_TASK_LOG_BUFFER // For non-main threads/tasks, queue the message for callbacks -#if defined(USE_ESP32) || defined(USE_LIBRETINY) message_sent = - this->log_buffer_->send_message_thread_safe(level, tag, static_cast(line), current_task, format, args); -#else // USE_HOST - message_sent = this->log_buffer_->send_message_thread_safe(level, tag, static_cast(line), format, args); -#endif + this->log_buffer_->send_message_thread_safe(level, tag, static_cast(line), thread_name, format, args); if (message_sent) { // Enable logger loop to process the buffered message // This is safe to call from any context including ISRs @@ -101,19 +100,27 @@ void Logger::log_vprintf_non_main_thread_(uint8_t level, const char *tag, int li #endif char console_buffer[MAX_CONSOLE_LOG_MSG_SIZE]; // MUST be stack allocated for thread safety LogBuffer buf{console_buffer, MAX_CONSOLE_LOG_MSG_SIZE}; - this->format_log_to_buffer_with_terminator_(level, tag, line, format, args, buf); + this->format_log_to_buffer_with_terminator_(level, tag, line, format, args, buf, thread_name); this->write_to_console_(buf); } // RAII guard automatically resets on return } #else -// Implementation for all other platforms (single-task, no threading) +// Implementation for single-task platforms (ESP8266, RP2040, Zephyr) +// TODO: Zephyr may have multiple threads (work queues, etc.) but uses this single-task path. +// Logging calls are NOT thread-safe: global_recursion_guard_ is a plain bool and tx_buffer_ has no locking. +// Not a problem in practice yet since Zephyr has no API support (logs are console-only). 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; - - this->log_message_to_buffer_and_send_(global_recursion_guard_, level, tag, line, format, args); +#ifdef USE_ZEPHYR + char tmp[MAX_POINTER_REPRESENTATION]; + this->log_message_to_buffer_and_send_(global_recursion_guard_, level, tag, line, format, args, + this->get_thread_name_(tmp)); +#else // Other single-task platforms don't have thread names, so pass nullptr + this->log_message_to_buffer_and_send_(global_recursion_guard_, level, tag, line, format, args, nullptr); +#endif } #endif // USE_ESP32 / USE_HOST / USE_LIBRETINY @@ -129,7 +136,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; - this->log_message_to_buffer_and_send_(global_recursion_guard_, level, tag, line, format, args); + this->log_message_to_buffer_and_send_(global_recursion_guard_, level, tag, line, format, args, nullptr); } #endif // USE_STORE_LOG_STR_IN_FLASH diff --git a/esphome/components/logger/logger.h b/esphome/components/logger/logger.h index 1678fed5f5..ecf032ee0e 100644 --- a/esphome/components/logger/logger.h +++ b/esphome/components/logger/logger.h @@ -2,6 +2,7 @@ #include #include +#include #include #if defined(USE_ESP32) || defined(USE_HOST) #include @@ -124,6 +125,10 @@ static constexpr uint16_t MAX_HEADER_SIZE = 128; // "0x" + 2 hex digits per byte + '\0' static constexpr size_t MAX_POINTER_REPRESENTATION = 2 + sizeof(void *) * 2 + 1; +// Stack buffer size for retrieving thread/task names from the OS +// macOS allows up to 64 bytes, Linux up to 16 +static constexpr size_t THREAD_NAME_BUF_SIZE = 64; + // Buffer wrapper for log formatting functions struct LogBuffer { char *data; @@ -408,34 +413,24 @@ class Logger : public Component { #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 + // thread_name is resolved by the caller from the task handle, avoiding redundant lookups 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 + const char *thread_name); #endif void process_messages_(); void write_msg_(const char *msg, uint16_t len); // Format a log message with printf-style arguments and write it to a buffer with header, footer, and null terminator + // thread_name: name of the calling thread/task, or nullptr for main task (callers already know which task they're on) inline void HOT format_log_to_buffer_with_terminator_(uint8_t level, const char *tag, int line, const char *format, - va_list args, LogBuffer &buf) { -#if defined(USE_ESP32) || defined(USE_LIBRETINY) || defined(USE_HOST) - buf.write_header(level, tag, line, this->get_thread_name_()); -#elif defined(USE_ZEPHYR) - char tmp[MAX_POINTER_REPRESENTATION]; - buf.write_header(level, tag, line, this->get_thread_name_(tmp)); -#else - buf.write_header(level, tag, line, nullptr); -#endif + va_list args, LogBuffer &buf, const char *thread_name) { + buf.write_header(level, tag, line, thread_name); buf.format_body(format, args); } #ifdef USE_STORE_LOG_STR_IN_FLASH // Format a log message with flash string format and write it to a buffer with header, footer, and null terminator + // ESP8266-only (single-task), thread_name is always nullptr inline void HOT format_log_to_buffer_with_terminator_P_(uint8_t level, const char *tag, int line, const __FlashStringHelper *format, va_list args, LogBuffer &buf) { @@ -466,9 +461,10 @@ class Logger : public Component { // Helper to format and send a log message to both console and listeners // Template handles both const char* (RAM) and __FlashStringHelper* (flash) format strings + // thread_name: name of the calling thread/task, or nullptr for main task template inline void HOT log_message_to_buffer_and_send_(bool &recursion_guard, uint8_t level, const char *tag, int line, - FormatType format, va_list args) { + FormatType format, va_list args, const char *thread_name) { RecursionGuard guard(recursion_guard); LogBuffer buf{this->tx_buffer_, this->tx_buffer_size_}; #ifdef USE_STORE_LOG_STR_IN_FLASH @@ -477,7 +473,7 @@ class Logger : public Component { } else #endif { - this->format_log_to_buffer_with_terminator_(level, tag, line, format, args, buf); + this->format_log_to_buffer_with_terminator_(level, tag, line, format, args, buf, thread_name); } this->notify_listeners_(level, tag, buf); this->write_log_buffer_to_console_(buf); @@ -565,37 +561,57 @@ class Logger : public Component { bool global_recursion_guard_{false}; // Simple global recursion guard for single-task platforms #endif -#if defined(USE_ESP32) || defined(USE_LIBRETINY) || defined(USE_ZEPHYR) - const char *HOT get_thread_name_( -#ifdef USE_ZEPHYR - char *buff + // --- get_thread_name_ overloads (per-platform) --- + +#if defined(USE_ESP32) || defined(USE_LIBRETINY) + // Primary overload - takes a task handle directly to avoid redundant xTaskGetCurrentTaskHandle() calls + // when the caller already has the handle (e.g. from the main task check in log_vprintf_) + const char *get_thread_name_(TaskHandle_t task) { + if (task == this->main_task_) { + return nullptr; // Main task + } +#if defined(USE_ESP32) + return pcTaskGetName(task); +#elif defined(USE_LIBRETINY) + return pcTaskGetTaskName(task); #endif - ) { -#ifdef USE_ZEPHYR + } + + // Convenience overload - gets the current task handle and delegates + const char *HOT get_thread_name_() { return this->get_thread_name_(xTaskGetCurrentTaskHandle()); } + +#elif defined(USE_HOST) + // Takes a caller-provided buffer for the thread name (stack-allocated for thread safety) + const char *HOT get_thread_name_(std::span buff) { + pthread_t current_thread = pthread_self(); + if (pthread_equal(current_thread, main_thread_)) { + return nullptr; // Main thread + } + // For non-main threads, get the thread name into the caller-provided buffer + if (pthread_getname_np(current_thread, buff.data(), buff.size()) == 0) { + return buff.data(); + } + return nullptr; + } + +#elif defined(USE_ZEPHYR) + const char *HOT get_thread_name_(std::span buff) { k_tid_t current_task = k_current_get(); -#else - TaskHandle_t current_task = xTaskGetCurrentTaskHandle(); -#endif if (current_task == main_task_) { return nullptr; // Main task - } else { -#if defined(USE_ESP32) - return pcTaskGetName(current_task); -#elif defined(USE_LIBRETINY) - return pcTaskGetTaskName(current_task); -#elif defined(USE_ZEPHYR) - const char *name = k_thread_name_get(current_task); - if (name) { - // zephyr print task names only if debug component is present - return name; - } - std::snprintf(buff, MAX_POINTER_REPRESENTATION, "%p", current_task); - return buff; -#endif } + const char *name = k_thread_name_get(current_task); + if (name) { + // zephyr print task names only if debug component is present + return name; + } + std::snprintf(buff.data(), buff.size(), "%p", current_task); + return buff.data(); } #endif + // --- Non-main task recursion guards (per-platform) --- + #if defined(USE_ESP32) || defined(USE_HOST) // RAII guard for non-main task recursion using pthread TLS class NonMainTaskRecursionGuard { @@ -635,22 +651,6 @@ class Logger : public Component { inline RecursionGuard make_non_main_task_guard_() { return RecursionGuard(non_main_task_recursion_guard_); } #endif -#ifdef USE_HOST - const char *HOT get_thread_name_() { - pthread_t current_thread = pthread_self(); - if (pthread_equal(current_thread, main_thread_)) { - return nullptr; // Main thread - } - // For non-main threads, return the thread name - // We store it in thread-local storage to avoid allocation - static thread_local char thread_name_buf[32]; - if (pthread_getname_np(current_thread, thread_name_buf, sizeof(thread_name_buf)) == 0) { - return thread_name_buf; - } - return nullptr; - } -#endif - #if defined(USE_ESP32) || defined(USE_LIBRETINY) // Disable loop when task buffer is empty (with USB CDC check on ESP32) inline void disable_loop_when_buffer_empty_() { diff --git a/esphome/components/logger/task_log_buffer_esp32.cpp b/esphome/components/logger/task_log_buffer_esp32.cpp index b9dfe45b7f..56c0a4ae2d 100644 --- a/esphome/components/logger/task_log_buffer_esp32.cpp +++ b/esphome/components/logger/task_log_buffer_esp32.cpp @@ -59,7 +59,7 @@ void TaskLogBuffer::release_message_main_loop(void *token) { last_processed_counter_ = message_counter_.load(std::memory_order_relaxed); } -bool TaskLogBuffer::send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, TaskHandle_t task_handle, +bool TaskLogBuffer::send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, const char *thread_name, const char *format, va_list args) { // First, calculate the exact length needed using a null buffer (no actual writing) va_list args_copy; @@ -95,7 +95,6 @@ bool TaskLogBuffer::send_message_thread_safe(uint8_t level, const char *tag, uin // Store the thread name now instead of waiting until main loop processing // This avoids crashes if the task completes or is deleted between when this message // is enqueued and when it's processed by the main loop - const char *thread_name = pcTaskGetName(task_handle); if (thread_name != nullptr) { strncpy(msg->thread_name, thread_name, sizeof(msg->thread_name) - 1); msg->thread_name[sizeof(msg->thread_name) - 1] = '\0'; // Ensure null termination diff --git a/esphome/components/logger/task_log_buffer_esp32.h b/esphome/components/logger/task_log_buffer_esp32.h index fde9bd60d5..6c1bafaeba 100644 --- a/esphome/components/logger/task_log_buffer_esp32.h +++ b/esphome/components/logger/task_log_buffer_esp32.h @@ -58,7 +58,7 @@ class TaskLogBuffer { void release_message_main_loop(void *token); // Thread-safe - send a message to the ring buffer from any thread - bool send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, TaskHandle_t task_handle, + bool send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, const char *thread_name, const char *format, va_list args); // Check if there are messages ready to be processed using an atomic counter for performance diff --git a/esphome/components/logger/task_log_buffer_host.cpp b/esphome/components/logger/task_log_buffer_host.cpp index 0660aeb061..676686304a 100644 --- a/esphome/components/logger/task_log_buffer_host.cpp +++ b/esphome/components/logger/task_log_buffer_host.cpp @@ -70,8 +70,8 @@ void TaskLogBufferHost::commit_write_slot_(int slot_index) { } } -bool TaskLogBufferHost::send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, const char *format, - va_list args) { +bool TaskLogBufferHost::send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, const char *thread_name, + const char *format, va_list args) { // Acquire a slot int slot_index = this->acquire_write_slot_(); if (slot_index < 0) { @@ -85,11 +85,9 @@ bool TaskLogBufferHost::send_message_thread_safe(uint8_t level, const char *tag, msg.tag = tag; msg.line = line; - // Get thread name using pthread - char thread_name_buf[LogMessage::MAX_THREAD_NAME_SIZE]; - // pthread_getname_np works the same on Linux and macOS - if (pthread_getname_np(pthread_self(), thread_name_buf, sizeof(thread_name_buf)) == 0) { - strncpy(msg.thread_name, thread_name_buf, sizeof(msg.thread_name) - 1); + // Store the thread name now to avoid crashes if thread exits before processing + if (thread_name != nullptr) { + strncpy(msg.thread_name, thread_name, sizeof(msg.thread_name) - 1); msg.thread_name[sizeof(msg.thread_name) - 1] = '\0'; } else { msg.thread_name[0] = '\0'; diff --git a/esphome/components/logger/task_log_buffer_host.h b/esphome/components/logger/task_log_buffer_host.h index d421d50ec6..f8e4ee7bee 100644 --- a/esphome/components/logger/task_log_buffer_host.h +++ b/esphome/components/logger/task_log_buffer_host.h @@ -86,7 +86,8 @@ class TaskLogBufferHost { // Thread-safe - send a message to the buffer from any thread // Returns true if message was queued, false if buffer is full - bool send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, const char *format, va_list args); + bool send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, const char *thread_name, + const char *format, va_list args); // Check if there are messages ready to be processed inline bool HOT has_messages() const { diff --git a/esphome/components/logger/task_log_buffer_libretiny.cpp b/esphome/components/logger/task_log_buffer_libretiny.cpp index 580066e621..5a22857dcb 100644 --- a/esphome/components/logger/task_log_buffer_libretiny.cpp +++ b/esphome/components/logger/task_log_buffer_libretiny.cpp @@ -101,7 +101,7 @@ void TaskLogBufferLibreTiny::release_message_main_loop() { } bool TaskLogBufferLibreTiny::send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, - TaskHandle_t task_handle, const char *format, va_list args) { + const char *thread_name, const char *format, va_list args) { // First, calculate the exact length needed using a null buffer (no actual writing) va_list args_copy; va_copy(args_copy, args); @@ -162,7 +162,6 @@ bool TaskLogBufferLibreTiny::send_message_thread_safe(uint8_t level, const char msg->line = line; // Store the thread name now to avoid crashes if task is deleted before processing - const char *thread_name = pcTaskGetTaskName(task_handle); if (thread_name != nullptr) { strncpy(msg->thread_name, thread_name, sizeof(msg->thread_name) - 1); msg->thread_name[sizeof(msg->thread_name) - 1] = '\0'; diff --git a/esphome/components/logger/task_log_buffer_libretiny.h b/esphome/components/logger/task_log_buffer_libretiny.h index bf6b2d2fa4..bf315e828a 100644 --- a/esphome/components/logger/task_log_buffer_libretiny.h +++ b/esphome/components/logger/task_log_buffer_libretiny.h @@ -70,7 +70,7 @@ class TaskLogBufferLibreTiny { void release_message_main_loop(); // Thread-safe - send a message to the buffer from any thread - bool send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, TaskHandle_t task_handle, + bool send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, const char *thread_name, const char *format, va_list args); // Fast check using volatile counter - no lock needed