1
0
mirror of https://github.com/esphome/esphome.git synced 2026-02-08 00:31:58 +00:00

[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<char> for Host/Zephyr get_thread_name_ buffer parameter
- Document Zephyr single-task path thread safety limitation
This commit is contained in:
J. Nick Koston
2026-02-07 07:47:00 +01:00
parent eb7aa3420f
commit 30f9bfaf83
8 changed files with 93 additions and 89 deletions

View File

@@ -36,8 +36,9 @@ void HOT Logger::log_vprintf_(uint8_t level, const char *tag, int line, const ch
#endif #endif
// Fast path: main thread, no recursion (99.9% of all logs) // 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]] { 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; 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) // 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) #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 #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 #endif
this->log_vprintf_non_main_thread_(level, tag, line, format, args, thread_name);
} }
// Handles non-main thread logging only // Handles non-main thread logging only
// Kept separate from hot path to improve instruction cache performance // 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, 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) { const char *thread_name) {
#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 // Check if already in recursion for this non-main thread/task
if (this->is_non_main_task_recursive_()) { if (this->is_non_main_task_recursive_()) {
return; return;
@@ -73,12 +76,8 @@ void Logger::log_vprintf_non_main_thread_(uint8_t level, const char *tag, int li
bool message_sent = false; bool message_sent = false;
#ifdef USE_ESPHOME_TASK_LOG_BUFFER #ifdef USE_ESPHOME_TASK_LOG_BUFFER
// For non-main threads/tasks, queue the message for callbacks // For non-main threads/tasks, queue the message for callbacks
#if defined(USE_ESP32) || defined(USE_LIBRETINY)
message_sent = message_sent =
this->log_buffer_->send_message_thread_safe(level, tag, static_cast<uint16_t>(line), current_task, format, args); this->log_buffer_->send_message_thread_safe(level, tag, static_cast<uint16_t>(line), thread_name, format, args);
#else // USE_HOST
message_sent = this->log_buffer_->send_message_thread_safe(level, tag, static_cast<uint16_t>(line), format, args);
#endif
if (message_sent) { if (message_sent) {
// Enable logger loop to process the buffered message // Enable logger loop to process the buffered message
// This is safe to call from any context including ISRs // 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 #endif
char console_buffer[MAX_CONSOLE_LOG_MSG_SIZE]; // MUST be stack allocated for thread safety char console_buffer[MAX_CONSOLE_LOG_MSG_SIZE]; // MUST be stack allocated for thread safety
LogBuffer buf{console_buffer, MAX_CONSOLE_LOG_MSG_SIZE}; 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); this->write_to_console_(buf);
} }
// RAII guard automatically resets on return // RAII guard automatically resets on return
} }
#else #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 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_) if (level > this->level_for(tag) || global_recursion_guard_)
return; return;
#ifdef USE_ZEPHYR
this->log_message_to_buffer_and_send_(global_recursion_guard_, level, tag, line, format, args); 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 #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_) if (level > this->level_for(tag) || global_recursion_guard_)
return; 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 #endif // USE_STORE_LOG_STR_IN_FLASH

View File

@@ -2,6 +2,7 @@
#include <cstdarg> #include <cstdarg>
#include <map> #include <map>
#include <span>
#include <type_traits> #include <type_traits>
#if defined(USE_ESP32) || defined(USE_HOST) #if defined(USE_ESP32) || defined(USE_HOST)
#include <pthread.h> #include <pthread.h>
@@ -124,6 +125,10 @@ static constexpr uint16_t MAX_HEADER_SIZE = 128;
// "0x" + 2 hex digits per byte + '\0' // "0x" + 2 hex digits per byte + '\0'
static constexpr size_t MAX_POINTER_REPRESENTATION = 2 + sizeof(void *) * 2 + 1; 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 // Buffer wrapper for log formatting functions
struct LogBuffer { struct LogBuffer {
char *data; char *data;
@@ -408,34 +413,24 @@ class Logger : public Component {
#if defined(USE_ESP32) || defined(USE_HOST) || defined(USE_LIBRETINY) #if defined(USE_ESP32) || defined(USE_HOST) || defined(USE_LIBRETINY)
// Handles non-main thread logging only (~0.1% of calls) // Handles non-main thread logging only (~0.1% of calls)
#if defined(USE_ESP32) || defined(USE_LIBRETINY) // thread_name is resolved by the caller from the task handle, avoiding redundant lookups
// 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, void log_vprintf_non_main_thread_(uint8_t level, const char *tag, int line, const char *format, va_list args,
TaskHandle_t current_task); const char *thread_name);
#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 #endif
void process_messages_(); void process_messages_();
void write_msg_(const char *msg, uint16_t len); 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 // 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, 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) { va_list args, LogBuffer &buf, const char *thread_name) {
#if defined(USE_ESP32) || defined(USE_LIBRETINY) || defined(USE_HOST) buf.write_header(level, tag, line, thread_name);
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
buf.format_body(format, args); buf.format_body(format, args);
} }
#ifdef USE_STORE_LOG_STR_IN_FLASH #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 // 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, inline void HOT format_log_to_buffer_with_terminator_P_(uint8_t level, const char *tag, int line,
const __FlashStringHelper *format, va_list args, const __FlashStringHelper *format, va_list args,
LogBuffer &buf) { LogBuffer &buf) {
@@ -466,9 +461,10 @@ class Logger : public Component {
// Helper to format and send a log message to both console and listeners // Helper to format and send a log message to both console and listeners
// Template handles both const char* (RAM) and __FlashStringHelper* (flash) format strings // 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<typename FormatType> template<typename FormatType>
inline void HOT log_message_to_buffer_and_send_(bool &recursion_guard, uint8_t level, const char *tag, int line, 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); RecursionGuard guard(recursion_guard);
LogBuffer buf{this->tx_buffer_, this->tx_buffer_size_}; LogBuffer buf{this->tx_buffer_, this->tx_buffer_size_};
#ifdef USE_STORE_LOG_STR_IN_FLASH #ifdef USE_STORE_LOG_STR_IN_FLASH
@@ -477,7 +473,7 @@ class Logger : public Component {
} else } else
#endif #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->notify_listeners_(level, tag, buf);
this->write_log_buffer_to_console_(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 bool global_recursion_guard_{false}; // Simple global recursion guard for single-task platforms
#endif #endif
#if defined(USE_ESP32) || defined(USE_LIBRETINY) || defined(USE_ZEPHYR) // --- get_thread_name_ overloads (per-platform) ---
const char *HOT get_thread_name_(
#ifdef USE_ZEPHYR #if defined(USE_ESP32) || defined(USE_LIBRETINY)
char *buff // 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 #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<char> 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<char> buff) {
k_tid_t current_task = k_current_get(); k_tid_t current_task = k_current_get();
#else
TaskHandle_t current_task = xTaskGetCurrentTaskHandle();
#endif
if (current_task == main_task_) { if (current_task == main_task_) {
return nullptr; // 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 #endif
// --- Non-main task recursion guards (per-platform) ---
#if defined(USE_ESP32) || defined(USE_HOST) #if defined(USE_ESP32) || defined(USE_HOST)
// RAII guard for non-main task recursion using pthread TLS // RAII guard for non-main task recursion using pthread TLS
class NonMainTaskRecursionGuard { class NonMainTaskRecursionGuard {
@@ -635,22 +651,6 @@ class Logger : public Component {
inline RecursionGuard make_non_main_task_guard_() { return RecursionGuard(non_main_task_recursion_guard_); } inline RecursionGuard make_non_main_task_guard_() { return RecursionGuard(non_main_task_recursion_guard_); }
#endif #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) #if defined(USE_ESP32) || defined(USE_LIBRETINY)
// Disable loop when task buffer is empty (with USB CDC check on ESP32) // Disable loop when task buffer is empty (with USB CDC check on ESP32)
inline void disable_loop_when_buffer_empty_() { inline void disable_loop_when_buffer_empty_() {

View File

@@ -59,7 +59,7 @@ void TaskLogBuffer::release_message_main_loop(void *token) {
last_processed_counter_ = message_counter_.load(std::memory_order_relaxed); 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) { const char *format, va_list args) {
// First, calculate the exact length needed using a null buffer (no actual writing) // First, calculate the exact length needed using a null buffer (no actual writing)
va_list args_copy; 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 // 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 // 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 // is enqueued and when it's processed by the main loop
const char *thread_name = pcTaskGetName(task_handle);
if (thread_name != nullptr) { if (thread_name != nullptr) {
strncpy(msg->thread_name, thread_name, sizeof(msg->thread_name) - 1); strncpy(msg->thread_name, thread_name, sizeof(msg->thread_name) - 1);
msg->thread_name[sizeof(msg->thread_name) - 1] = '\0'; // Ensure null termination msg->thread_name[sizeof(msg->thread_name) - 1] = '\0'; // Ensure null termination

View File

@@ -58,7 +58,7 @@ class TaskLogBuffer {
void release_message_main_loop(void *token); void release_message_main_loop(void *token);
// Thread-safe - send a message to the ring buffer from any thread // 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); const char *format, va_list args);
// Check if there are messages ready to be processed using an atomic counter for performance // Check if there are messages ready to be processed using an atomic counter for performance

View File

@@ -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, bool TaskLogBufferHost::send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, const char *thread_name,
va_list args) { const char *format, va_list args) {
// Acquire a slot // Acquire a slot
int slot_index = this->acquire_write_slot_(); int slot_index = this->acquire_write_slot_();
if (slot_index < 0) { if (slot_index < 0) {
@@ -85,11 +85,9 @@ bool TaskLogBufferHost::send_message_thread_safe(uint8_t level, const char *tag,
msg.tag = tag; msg.tag = tag;
msg.line = line; msg.line = line;
// Get thread name using pthread // Store the thread name now to avoid crashes if thread exits before processing
char thread_name_buf[LogMessage::MAX_THREAD_NAME_SIZE]; if (thread_name != nullptr) {
// pthread_getname_np works the same on Linux and macOS strncpy(msg.thread_name, thread_name, sizeof(msg.thread_name) - 1);
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);
msg.thread_name[sizeof(msg.thread_name) - 1] = '\0'; msg.thread_name[sizeof(msg.thread_name) - 1] = '\0';
} else { } else {
msg.thread_name[0] = '\0'; msg.thread_name[0] = '\0';

View File

@@ -86,7 +86,8 @@ class TaskLogBufferHost {
// Thread-safe - send a message to the buffer from any thread // Thread-safe - send a message to the buffer from any thread
// Returns true if message was queued, false if buffer is full // 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 // Check if there are messages ready to be processed
inline bool HOT has_messages() const { inline bool HOT has_messages() const {

View File

@@ -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, 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) // First, calculate the exact length needed using a null buffer (no actual writing)
va_list args_copy; va_list args_copy;
va_copy(args_copy, args); va_copy(args_copy, args);
@@ -162,7 +162,6 @@ bool TaskLogBufferLibreTiny::send_message_thread_safe(uint8_t level, const char
msg->line = line; msg->line = line;
// Store the thread name now to avoid crashes if task is deleted before processing // 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) { if (thread_name != nullptr) {
strncpy(msg->thread_name, thread_name, sizeof(msg->thread_name) - 1); strncpy(msg->thread_name, thread_name, sizeof(msg->thread_name) - 1);
msg->thread_name[sizeof(msg->thread_name) - 1] = '\0'; msg->thread_name[sizeof(msg->thread_name) - 1] = '\0';

View File

@@ -70,7 +70,7 @@ class TaskLogBufferLibreTiny {
void release_message_main_loop(); void release_message_main_loop();
// Thread-safe - send a message to the buffer from any thread // 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); const char *format, va_list args);
// Fast check using volatile counter - no lock needed // Fast check using volatile counter - no lock needed