From 9988a2bec8fd61e77231744e25c603c7058f809e Mon Sep 17 00:00:00 2001 From: cjkas Date: Mon, 12 Oct 2026 18:35:42 +0200 Subject: [PATCH] fix: don't wait on a log lock holder that can't run The log lock is a binary semaphore, so when the radio task preempted loop() mid-log every log from async_tcp waited the full 20ms for a holder that couldn't let go until the radio job ended. Waiting now stops as soon as the holder is preempted on another core. The rule lives in LogLockPolicy.h with unit tests. Co-Authored-By: Claude Opus 5.5 --- src/LogLock.cpp | 36 ++++++++++++++++++++++++++-- src/LogLockPolicy.h | 21 +++++++++++++++++ test/test_logging/test_logging.cpp | 38 ++++++++++++++++++++++++++++++ 3 files changed, 93 insertions(+), 2 deletions(-) create mode 100644 src/LogLockPolicy.h create mode 100644 test/test_logging/test_logging.cpp diff --git a/src/LogLock.cpp b/src/LogLock.cpp index 381c58d..8c68d63 100644 --- a/src/LogLock.cpp +++ b/src/LogLock.cpp @@ -12,12 +12,17 @@ // // The lock is a binary semaphore, not a mutex. A mutex passes its waiter's // priority to the holder, so async_tcp waiting on loop() would lift loop() -// above the radio task and let it break into a frame on the air. +// above the radio task and let it break into a frame on the air. Without that +// boost a holder preempted on the other core (loop() while the radio task sends +// a whole job) can't let go, so a waiter only waits while the holder can make +// progress (see LogLockPolicy.h). #include #include +#include "esp_idf_version.h" #include "freertos/FreeRTOS.h" #include "freertos/semphr.h" #include "freertos/task.h" +#include "LogLockPolicy.h" extern "C" int __real_log_printfv(const char *format, va_list arg); @@ -36,11 +41,38 @@ static volatile TaskHandle_t logOwner = nullptr; // line takes about 20ms at 115200 baud. #define LOG_LOCK_WAIT_MS 20 +#if ESP_IDF_VERSION_MAJOR >= 5 +#define taskOnCore(core) xTaskGetCurrentTaskHandleForCore(core) +#define taskCore(task) xTaskGetCoreID(task) +#else +#define taskOnCore(core) xTaskGetCurrentTaskHandleForCPU(core) +#define taskCore(task) xTaskGetAffinity(task) +#endif +static LogHolder logHolder(TaskHandle_t owner) { + if(!owner) return LogHolder::unknown; + for(BaseType_t core = 0; core < portNUM_PROCESSORS; core++) + if(taskOnCore(core) == owner) return LogHolder::running; + // A task pinned elsewhere only runs once whatever preempted it there is done. + const BaseType_t core = taskCore(owner); + if(core == tskNO_AFFINITY || core == xPortGetCoreID()) return LogHolder::preemptedHere; + return LogHolder::preemptedElsewhere; +} +// Takes the lock, waiting in one tick slices for as long as the holder can let +// go of it. False when the line has to be printed without it. +static bool takeLogLock() { + uint32_t waitedMs = 0; + while(xSemaphoreTake(logLock, 1) != pdTRUE) { + waitedMs += portTICK_PERIOD_MS; + if(!keepWaitingForLogLock(logHolder(logOwner), waitedMs, LOG_LOCK_WAIT_MS)) return false; + } + return true; +} + extern "C" int __wrap_log_printfv(const char *format, va_list arg) { // No blocking before the scheduler runs, in an ISR or in a critical section. const bool canLock = logLock && xTaskGetSchedulerState() == taskSCHEDULER_RUNNING && xPortCanYield() && logOwner != xTaskGetCurrentTaskHandle(); - const bool locked = canLock && xSemaphoreTake(logLock, pdMS_TO_TICKS(LOG_LOCK_WAIT_MS)) == pdTRUE; + const bool locked = canLock && takeLogLock(); if(locked) logOwner = xTaskGetCurrentTaskHandle(); int len = __real_log_printfv(format, arg); if(locked) { diff --git a/src/LogLockPolicy.h b/src/LogLockPolicy.h new file mode 100644 index 0000000..a7d783a --- /dev/null +++ b/src/LogLockPolicy.h @@ -0,0 +1,21 @@ +#ifndef LOG_LOCK_POLICY_H +#define LOG_LOCK_POLICY_H +#include + +// When a log call stops waiting for the log lock (src/LogLock.cpp). Kept free +// of FreeRTOS so it can be unit tested on the PC (pio test -e native). + +// What the task holding the log lock is doing. +enum class LogHolder { + unknown, // Just took the lock and hasn't recorded itself yet. + running, // Running on a core, so it lets go within a line. + preemptedHere, // Waiting for this core, so blocking lets it finish. + preemptedElsewhere // Preempted on another core (the radio task during a + // whole transmission), so waiting gets nowhere. +}; +// Whether to keep waiting after waitedMs. Never past maxMs. +inline bool keepWaitingForLogLock(LogHolder holder, uint32_t waitedMs, uint32_t maxMs) { + if(waitedMs >= maxMs) return false; + return holder != LogHolder::preemptedElsewhere; +} +#endif diff --git a/test/test_logging/test_logging.cpp b/test/test_logging/test_logging.cpp new file mode 100644 index 0000000..3cfda43 --- /dev/null +++ b/test/test_logging/test_logging.cpp @@ -0,0 +1,38 @@ +#include +#include "LogLockPolicy.h" + +void setUp() {} +void tearDown() {} + +/********************************************************************* + * keepWaitingForLogLock + ********************************************************************/ +static void assertWaitsUntilMax(LogHolder holder) { + TEST_ASSERT_TRUE(keepWaitingForLogLock(holder, 0, 20)); + TEST_ASSERT_TRUE(keepWaitingForLogLock(holder, 19, 20)); + TEST_ASSERT_FALSE(keepWaitingForLogLock(holder, 20, 20)); + TEST_ASSERT_FALSE(keepWaitingForLogLock(holder, 1000, 20)); +} +static void test_logLock_waits_for_a_running_holder() { assertWaitsUntilMax(LogHolder::running); } +static void test_logLock_waits_for_a_holder_just_taking_it() { assertWaitsUntilMax(LogHolder::unknown); } +static void test_logLock_waits_for_a_holder_preempted_here() { assertWaitsUntilMax(LogHolder::preemptedHere); } +static void test_logLock_gives_up_on_a_holder_preempted_elsewhere() { + // loop() preempted by the radio task can't let go until the job is done. + TEST_ASSERT_FALSE(keepWaitingForLogLock(LogHolder::preemptedElsewhere, 0, 20)); + TEST_ASSERT_FALSE(keepWaitingForLogLock(LogHolder::preemptedElsewhere, 1, 20)); +} +static void test_logLock_no_wait_allowed() { + TEST_ASSERT_FALSE(keepWaitingForLogLock(LogHolder::running, 0, 0)); +} + +int main(int argc, char **argv) { + (void)argc; + (void)argv; + UNITY_BEGIN(); + RUN_TEST(test_logLock_waits_for_a_running_holder); + RUN_TEST(test_logLock_waits_for_a_holder_just_taking_it); + RUN_TEST(test_logLock_waits_for_a_holder_preempted_here); + RUN_TEST(test_logLock_gives_up_on_a_holder_preempted_elsewhere); + RUN_TEST(test_logLock_no_wait_allowed); + return UNITY_END(); +}