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(); +}