From 8a5f735bba559cd0268b5e49f0686645899a66da Mon Sep 17 00:00:00 2001 From: mikecarper Date: Sat, 17 Oct 2026 02:25:37 -0700 Subject: [PATCH] Reuse active Sensor tracker wake deadlines --- docs/nrf52_sleep_event_validation.md | 27 ++- examples/simple_sensor/main.cpp | 26 ++- test/fixtures/sensor_tracker_wake_timer.cpp | 220 ++++++++++++++++++++ test/test_sensor_tracker_sleep.py | 42 +++- 4 files changed, 305 insertions(+), 10 deletions(-) create mode 100644 test/fixtures/sensor_tracker_wake_timer.cpp diff --git a/docs/nrf52_sleep_event_validation.md b/docs/nrf52_sleep_event_validation.md index e7e1e3bf5..03b97b83c 100644 --- a/docs/nrf52_sleep_event_validation.md +++ b/docs/nrf52_sleep_event_validation.md @@ -77,8 +77,8 @@ was added. The test device was a RAK3401/nRF52840 with an external RAK13302 SX1262 on Mercerwood. Tests used 908.5 MHz, BW250, SF9, CR5, power saving on, manual RXPS 30000/10000 us, AGC 0, TX power 2, no forwarding/adverts and USB watchdog -off. A single private benchmark binary allowed changes without reflashing -between the decisive controls. Benchmark controls are not production features. +off. Runtime switches in private benchmark binaries allowed same-binary paired +controls without reflashing. Benchmark controls are not production features. | Control | Capture | Time-weighted sleeping observations | | --- | --- | --- | @@ -89,7 +89,7 @@ between the decisive controls. Benchmark controls are not production features. | No late SVC, non-yielding USB poll, without early clear | 30 s | 0% | | Early clear, no late SVC, non-yielding USB poll | 90 s | 76.7% | | Never-DTR client held open, old empty USB poll | 30 s | 0% | -| Same client held open, non-yielding USB poll | 30 s | 82.8% | +| Same client held open, non-yielding USB poll | 30 s | 82.9% | The first production candidate restored sleeping observations with SoftDevice off (6522/8331 samples, about 78% over 90 s), but not with SoftDevice on @@ -120,8 +120,9 @@ The final frozen SDK-on diagnostics had 281272 completed late waits, only than the capture; those counters are not its sleep-residency measurement. All final samples had the same valid debugger/clock state described below. -The never-DTR client successfully issued `get powersaving` and held the same -file descriptor open across both captures. Early clearing and removal of the +In the controlled old/new USB-poll pair, the never-DTR client successfully +issued `get powersaving` and held the same file descriptor open across both +captures. Early clearing and removal of the late state SVC were held constant in that pair, isolating the USB poll change. A separate unsafe late-double-wait control also slept, but was rejected because of the lost-work race above. @@ -144,6 +145,22 @@ In particular the T096 FEM/LNA default differs from EasySkyMesh; this RAK cannot measure that board-specific load. No RF delivery or long battery-life claim follows from these captures. +## Sensor tracker wake timer + +A separate tracker-mode issue posted `xTimerChangePeriod()` on every eligible +loop. Waking the higher-priority timer daemon recreates a scheduler event just +before the late wait. The helper now reuses an active timer whose remaining +time is nonzero and no later than the requested wake. Its active/expiry/tick +snapshot is protected by a short FreeRTOS critical section. Dormant, expired +or too-late timers are rearmed outside that section; allocation/queue failure +still keeps the node polling. No late event clearing was added. + +Host tests execute the actual helper, including the original repeated-rearm +negative control, deadline changes, one-shot expiration, queue failures, tick +wrap and late IRQs. T1000e and RAK3401 Sensor builds pass. This timer follow-up +has not been physically qualified in GPS tracker mode; the RAK captures above +are repeater tests. + See [power-saving diagnostics](power_saving_diagnostics.md) for the permanent on-demand CLI counters. Counters remain off by default. Wait-call counters cover the late eligible wait, not the guaranteed-nonblocking early SDK diff --git a/examples/simple_sensor/main.cpp b/examples/simple_sensor/main.cpp index 68cdd9967..6db4925b5 100644 --- a/examples/simple_sensor/main.cpp +++ b/examples/simple_sensor/main.cpp @@ -19,12 +19,34 @@ static void trackerWakeCallback(TimerHandle_t) { } // SYSTEMON event sleep has no built-in deadline. Arm a real timer before // leaving the loop; allocation/queue failure keeps polling instead of hanging. static bool armTrackerSleepWake(uint32_t seconds) { + if (seconds == 0 || seconds > 30) return false; if (!tracker_wake_timer.getHandle()) { tracker_wake_timer.begin(1000, trackerWakeCallback, nullptr, false); } const TimerHandle_t handle = tracker_wake_timer.getHandle(); - if (!handle || seconds == 0 || seconds > 30) return false; - return xTimerChangePeriod(handle, pdMS_TO_TICKS(seconds * 1000UL), 0) == pdPASS; + if (!handle) return false; + const TickType_t requested_ticks = pdMS_TO_TICKS(seconds * 1000UL); + if (requested_ticks == 0) return false; + + // Reposting an unchanged timer command wakes the higher-priority timer task + // and leaves a scheduler event immediately before every CPU sleep attempt. + // An existing earlier wake is sufficient; do not keep postponing it. + bool wake_ready = false; + taskENTER_CRITICAL(); + if (xTimerIsTimerActive(handle) != pdFALSE) { + // The compound snapshot must not race the one-shot becoming dormant: + // xTimerGetExpiryTime() is defined only while the timer is active. + const TickType_t expiry = xTimerGetExpiryTime(handle); + const TickType_t now = xTaskGetTickCount(); + const TickType_t remaining = static_cast(expiry - now); + wake_ready = remaining != 0 && remaining <= requested_ticks; + } + taskEXIT_CRITICAL(); + if (wake_ready) return true; + + // Dormant/expired timers need a fresh command even when the period matches. + // A failed queue send cannot promise an earlier deadline; keep polling. + return xTimerChangePeriod(handle, requested_ticks, 0) == pdPASS; } #endif diff --git a/test/fixtures/sensor_tracker_wake_timer.cpp b/test/fixtures/sensor_tracker_wake_timer.cpp new file mode 100644 index 000000000..ede4bfbc8 --- /dev/null +++ b/test/fixtures/sensor_tracker_wake_timer.cpp @@ -0,0 +1,220 @@ +// Execute the real tracker wake helper against a one-shot timer daemon. +// A successful command wakes the higher-priority daemon and emits a scheduler +// event; merely reading the active deadline does not. No event-clear primitive +// is exposed to the extracted helper. +#include +#include +#include + +using TickType_t = uint32_t; +struct Timer; +using TimerHandle_t = Timer*; +struct Timer { + bool active = false; + TickType_t expiry = 0, period = 0; + void (*callback)(TimerHandle_t) = nullptr; +} timer; + +constexpr int pdPASS = 1, pdFALSE = 0; +static bool allocate_ok = true, queue_ok = true, event_latched = false; +static bool expire_after_active_read = false, deferred_expiry = false; +static bool app_irq_after_unlock = false, application_work = false; +static TickType_t now_ticks = 0; +static unsigned begins = 0, commands = 0, callbacks = 0, active_reads = 0; +static unsigned expiry_reads = 0, tick_reads = 0, sleeps = 0, short_returns = 0; +static unsigned critical_depth = 0, max_critical_depth = 0; + +static void expireTimer() { + assert(timer.active && critical_depth == 0); + timer.active = false; // One-shot becomes dormant before its no-op callback. + ++callbacks; + timer.callback(&timer); + event_latched = true; +} +static void taskENTER_CRITICAL() { + ++critical_depth; + if (critical_depth > max_critical_depth) max_critical_depth = critical_depth; +} +static void taskEXIT_CRITICAL() { + assert(critical_depth); + if (--critical_depth == 0) { + if (deferred_expiry) { + deferred_expiry = false; + now_ticks = timer.expiry; // Pending RTC tick is delivered after unmask. + expireTimer(); + } + if (app_irq_after_unlock) { + app_irq_after_unlock = false; + application_work = event_latched = true; + } + } +} +static int xTimerIsTimerActive(TimerHandle_t handle) { + assert(handle == &timer && critical_depth == 1); + // The real API has its own nested critical section. + taskENTER_CRITICAL(); + ++active_reads; + const bool active = timer.active; + if (expire_after_active_read) { + assert(active); + expire_after_active_read = false; + deferred_expiry = true; // Daemon cannot invalidate the compound snapshot. + } + taskEXIT_CRITICAL(); + return active; +} +static TickType_t xTimerGetExpiryTime(TimerHandle_t handle) { + assert(handle == &timer && critical_depth == 1 && timer.active); + ++expiry_reads; + return timer.expiry; +} +static TickType_t xTaskGetTickCount() { + assert(critical_depth == 1); + ++tick_reads; + return now_ticks; +} +static TickType_t pdMS_TO_TICKS(uint32_t milliseconds) { + return static_cast((uint64_t(milliseconds) * 1024) / 1000); +} +static int xTimerChangePeriod(TimerHandle_t handle, TickType_t ticks, int wait) { + assert(handle == &timer && critical_depth == 0 && ticks && wait == 0); + ++commands; + if (!queue_ok) return 0; + timer.period = ticks; + timer.expiry = static_cast(now_ticks + ticks); + timer.active = true; + event_latched = true; // Queue unblocks timer-priority2 above loop-priority1. + return pdPASS; +} +class SoftwareTimer { + TimerHandle_t handle_ = nullptr; + public: + TimerHandle_t getHandle() { return handle_; } + void begin(uint32_t period, void (*callback)(TimerHandle_t), void* id, bool repeat) { + assert(period == 1000 && callback && !id && !repeat); + ++begins; + if (allocate_ok) { + handle_ = &timer; + timer.callback = callback; + } + } +}; +static SoftwareTimer tracker_wake_timer; +static void trackerWakeCallback(TimerHandle_t) {} + +@ARM@ + +static bool attempt(uint32_t seconds) { + const bool ready = armTrackerSleepWake(seconds); + assert(critical_depth == 0); + if (ready) { + if (event_latched) { event_latched = false; ++short_returns; } + else { assert(timer.active && !application_work); ++sleeps; } + } + return ready; +} +static void reset() { + tracker_wake_timer = SoftwareTimer(); + timer = Timer(); + allocate_ok = queue_ok = true; + event_latched = expire_after_active_read = deferred_expiry = false; + app_irq_after_unlock = application_work = false; + now_ticks = 100; + begins = commands = callbacks = active_reads = expiry_reads = tick_reads = 0; + sleeps = short_returns = critical_depth = max_critical_depth = 0; +} + +static void idleReuse() { + reset(); + assert(attempt(30) && commands == 1 && short_returns == 1); + const TickType_t deadline = timer.expiry; + for (unsigned i = 0; i < 1000; ++i) { + ++now_ticks; + assert(attempt(30)); + assert(commands == 1 && "idle timer poll must not requeue and relatch scheduler event"); + assert(timer.expiry == deadline && !event_latched); + } + assert(sleeps == 1000 && begins == 1 && max_critical_depth == 2); +} +static void changedDeadlines() { + reset(); + assert(attempt(30)); + ++now_ticks; + assert(attempt(7) && commands == 2 && timer.period == pdMS_TO_TICKS(7000)); + const TickType_t earlier = timer.expiry; + assert(attempt(30) && commands == 2 && timer.expiry == earlier); + assert(attempt(7) && commands == 2); + assert(attempt(3) && commands == 3 && timer.period == pdMS_TO_TICKS(3000)); + now_ticks = timer.expiry - 1; + assert(attempt(1) && commands == 3); // Existing earlier wake is sufficient. +} +static void expiryAndRearm() { + reset(); + assert(attempt(1)); + now_ticks = timer.expiry; + expireTimer(); + event_latched = false; // Next loop entry acknowledges the completed callback. + assert(attempt(1) && commands == 2 && timer.active && callbacks == 1); + now_ticks = timer.expiry; // Due but daemon has not removed it yet. + assert(attempt(1) && commands == 3); + now_ticks = timer.expiry + 1; // An overdue active deadline is not reusable. + assert(attempt(1) && commands == 4); +} +static void failureAndRecovery() { + reset(); + assert(!attempt(0) && !attempt(31) && begins == 0 && commands == 0); + allocate_ok = false; + assert(!attempt(30) && commands == 0 && critical_depth == 0); + allocate_ok = true; queue_ok = false; + assert(!attempt(30) && commands == 1 && !timer.active); + queue_ok = true; + assert(attempt(30) && commands == 2); + const TickType_t old_deadline = timer.expiry; + queue_ok = false; + assert(!attempt(3) && commands == 3 && timer.expiry == old_deadline); + queue_ok = true; + assert(attempt(3) && commands == 4); + queue_ok = false; + assert(attempt(30) && commands == 4); // Reuse needs no free command-queue slot. +} +static void tickWrap() { + reset(); + now_ticks = std::numeric_limits::max() - 500; + assert(attempt(1) && timer.expiry == 523); + now_ticks = std::numeric_limits::max() - 100; + assert(attempt(1) && commands == 1); + now_ticks = 500; + assert(attempt(1) && commands == 1); + now_ticks = 523; + assert(attempt(1) && commands == 2); + now_ticks = timer.expiry + 1; + assert(attempt(1) && commands == 3); +} +static void expiryAfterSnapshot() { + reset(); + assert(attempt(30)); + now_ticks = timer.expiry - 1; + expire_after_active_read = true; + assert(attempt(30)); + assert(callbacks == 1 && !timer.active && short_returns == 2 && commands == 1); + assert(attempt(30) && timer.active && commands == 2); // Same period still rearms. + assert(attempt(30) && sleeps == 1 && commands == 2); +} +static void applicationIrqAfterSnapshot() { + reset(); + assert(attempt(30)); + app_irq_after_unlock = true; + assert(attempt(30) && application_work && short_returns == 2 && commands == 1); + application_work = false; // Following service pass handles the late IRQ. + assert(attempt(30) && sleeps == 1 && commands == 1); +} + +int main() { + idleReuse(); + changedDeadlines(); + expiryAndRearm(); + failureAndRecovery(); + tickWrap(); + expiryAfterSnapshot(); + applicationIrqAfterSnapshot(); +} diff --git a/test/test_sensor_tracker_sleep.py b/test/test_sensor_tracker_sleep.py index a9c048435..b1631e174 100644 --- a/test/test_sensor_tracker_sleep.py +++ b/test/test_sensor_tracker_sleep.py @@ -127,12 +127,21 @@ TIMER = r''' #include #include using TimerHandle_t=void*; -bool allocate=true,queue_ok=true; +using TickType_t=uint32_t; +bool allocate=true,queue_ok=true,active=false; +TickType_t timer_now=0,expiry=0; unsigned period_ms=0,begin_calls=0,queue_calls=0; -constexpr int pdPASS=1; +constexpr int pdPASS=1,pdFALSE=0; +void taskENTER_CRITICAL(){} +void taskEXIT_CRITICAL(){} +int xTimerIsTimerActive(TimerHandle_t){return active;} +TickType_t xTimerGetExpiryTime(TimerHandle_t){assert(active);return expiry;} +TickType_t xTaskGetTickCount(){return timer_now;} uint32_t pdMS_TO_TICKS(uint32_t value){return value/10;} int xTimerChangePeriod(TimerHandle_t handle,uint32_t ticks,int wait){ - assert(handle&&wait==0);++queue_calls;period_ms=ticks*10;return queue_ok?pdPASS:0; + assert(handle&&wait==0);++queue_calls; + if(!queue_ok)return 0; + period_ms=ticks*10;expiry=timer_now+ticks;active=true;return pdPASS; } class SoftwareTimer { TimerHandle_t handle=nullptr; @@ -292,6 +301,33 @@ class SensorTrackerSleepTest(unittest.TestCase): with self.subTest(defines=defines): self.compile_run(source, defines) + def test_actual_wake_timer_reuse_rearm_failures_wrap_and_late_irqs(self): + main = (ROOT / "examples/simple_sensor/main.cpp").read_text(encoding="ascii") + arm = body(main, "static bool armTrackerSleepWake(") + fixture = (ROOT / "test/fixtures/sensor_tracker_wake_timer.cpp").read_text(encoding="ascii") + self.compile_run(fixture.replace("@ARM@", arm)) + + def test_negative_control_reposting_timer_command_prevents_idle_sleep(self): + main = (ROOT / "examples/simple_sensor/main.cpp").read_text(encoding="ascii") + arm = body(main, "static bool armTrackerSleepWake(") + start = arm.index(" // Reposting an unchanged timer command") + end = arm.index(" // Dormant/expired timers", start) + old = arm[:start] + arm[end:] + fixture = (ROOT / "test/fixtures/sensor_tracker_wake_timer.cpp").read_text(encoding="ascii") + with self.assertRaisesRegex(AssertionError, + "idle timer poll must not requeue and relatch scheduler event"): + self.compile_run(fixture.replace("@ARM@", old)) + + def test_wake_timer_has_no_dependency_when_tracker_or_platform_is_disabled(self): + main = (ROOT / "examples/simple_sensor/main.cpp").read_text(encoding="ascii") + start = main.index("#if defined(NRF52_PLATFORM) && MESH_ENABLE_SENSOR_TRACKER\n") + end = main.index("\n#endif", start) + len("\n#endif") + source = main[start:end] + "\nint main() {}\n" + for defines in (("NRF52_PLATFORM=1", "MESH_ENABLE_SENSOR_TRACKER=0"), + ("ESP32_PLATFORM=1", "MESH_ENABLE_SENSOR_TRACKER=1")): + with self.subTest(defines=defines): + self.compile_run(source, defines) + def test_actual_radio_warm_sleep_and_dispatcher_watchdog_reanchor(self): radio = (ROOT / "src/helpers/radiolib/RadioLibWrappers.cpp").read_text() dispatcher = (ROOT / "src/Dispatcher.cpp").read_text()