From 4a0839d27db43232de84dd801d33549347272734 Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Wed, 30 Sep 2026 11:53:24 +0200 Subject: [PATCH] Logger: don't overflow the deferred buffer at high priority. With the logging thread at high priority, thread-context producers now wait (bounded, 50ms) for the buffer to drain below 8 messages instead of overwriting old ones. ISR producers can't wait and may still drop. The wait sits outside the reentrancy guard. Co-Authored-By: Claude Fable 5.1 --- device/src/logger_priority.c | 3 +++ device/src/logger_priority.h | 3 +++ right/src/logger.c | 25 +++++++++++++++++++++++++ 3 files changed, 31 insertions(+) diff --git a/device/src/logger_priority.c b/device/src/logger_priority.c index 2cba2e5cf..9df6fcaad 100644 --- a/device/src/logger_priority.c +++ b/device/src/logger_priority.c @@ -62,7 +62,10 @@ int set_thread_priority_by_name(const char *thread_name, int new_priority) { #define LOG_THREAD_PRIORITY_HIGH K_PRIO_COOP(CONFIG_NUM_COOP_PRIORITIES - 1) #define LOG_THREAD_PRIORITY_LOW K_PRIO_PREEMPT(K_LOWEST_APPLICATION_THREAD_PRIO - 1) +bool Logger_PriorityHigh = false; + void Logger_SetPriority(bool high) { + Logger_PriorityHigh = high; set_thread_priority_by_name("logging", high ? LOG_THREAD_PRIORITY_HIGH : LOG_THREAD_PRIORITY_LOW); set_thread_priority_by_name("UhkShell", SHELL_THREAD_PRIORITY); set_thread_priority_by_name("shell_rtt", SHELL_THREAD_PRIORITY); diff --git a/device/src/logger_priority.h b/device/src/logger_priority.h index 03ff96248..7c7012021 100644 --- a/device/src/logger_priority.h +++ b/device/src/logger_priority.h @@ -15,6 +15,9 @@ // Functions: + // True while the logging thread runs at high priority (see Logger_SetPriority). + extern bool Logger_PriorityHigh; + void Logger_SetPriority(bool high); #endif // __MAIN_H__ diff --git a/right/src/logger.c b/right/src/logger.c index 82c4a2bf8..c078a81af 100644 --- a/right/src/logger.c +++ b/right/src/logger.c @@ -23,6 +23,7 @@ #include #include #include + #include "logger_priority.h" #if DEVICE_IS_KEYBOARD #include "keyboard/uart_bridge.h" #ifdef DEVICE_HAS_OLED @@ -47,6 +48,24 @@ char BUFFER[MAX_LOG_LENGTH]; \ BUFFER[MAX_LOG_LENGTH-1] = '\0'; \ } +#ifdef __ZEPHYR__ +// With the logging thread at high priority, thread-context producers wait for the deferred +// log buffer to drain instead of overflowing it (the buffer overwrites its oldest messages). +// ISR-context producers cannot wait and may still drop. Bounded, so a stalled log thread +// can't hang callers. Must not run inside a REENTRANCY_GUARD - it drops concurrent logs. +#define LOG_BACKPRESSURE_MAX_BUFFERED 8 +#define LOG_BACKPRESSURE_MAX_WAIT_MS 50 + +static void uartLogBackpressure(void) { + if (Logger_PriorityHigh && !k_is_in_isr()) { + for (uint8_t i = 0; i < LOG_BACKPRESSURE_MAX_WAIT_MS && log_buffered_cnt() > LOG_BACKPRESSURE_MAX_BUFFERED; i++) { + log_thread_trigger(); + k_msleep(1); + } + } +} +#endif + void Uart_LogConstant(const char* buffer) { #ifdef __ZEPHYR__ printk("%s", buffer); @@ -57,6 +76,7 @@ void Uart_Log(const char *fmt, ...) { #ifdef __ZEPHYR__ EXPAND_STRING(buffer); + uartLogBackpressure(); Uart_LogConstant(buffer); #endif } @@ -165,6 +185,11 @@ void LogUSDO(const char *fmt, ...) { } void LogConstantTo(device_id_t deviceId, log_target_t logMask, const char* buffer) { +#ifdef __ZEPHYR__ + if ((logMask & LogTarget_Uart) && DEBUG_LOG_UART && (DEVICE_IS_UHK60 || DEVICE_ID == deviceId)) { + uartLogBackpressure(); + } +#endif REENTRANCY_GUARD_BEGIN; if (DEVICE_IS_UHK60 || DEVICE_ID == deviceId) { #if DEVICE_HAS_OLED