DISCO-L475VG-IOT01A lp_timeout test fails CI on IAR

[Tharazi97]

Description

Nightly CI test fails on DISCO-L475VG-IOT01A on lp_timeout test only when compiled on IAR.

It started to fail after this commit: 9858b16

[1569184789.85][CONN][RXD] >>> Running case #1: 'Callback called once (attach)'...
[1569184789.85][CONN][INF] found KV pair in stream: {{__testcase_name;1 s delay during deepsleep (attach_us)}}, queued...
mbedgt: :85::FAIL: Expected TRUE Was FALSE
[1569184789.95][CONN][RXD] :85::FAIL: Expected TRUE Was FALSE
[1569184789.95][CONN][INF] found KV pair in stream: {{__testcase_start;Callback called once (attach)}}, queued...
[1569184790.06][CONN][INF] found KV pair in stream: {{__testcase_finish;Callback called once (attach);0;1}}, queued...
[1569184790.16][CONN][RXD] >>> 'Callback called once (attach)': 0 passed, 1 failed with reason 'Assertion Failed'

@maciejbocianski @jamesbeyond @LMESTM

Issue request type

[ ] Question
[ ] Enhancement
[x] Bug

[0xc0170]

cc @ARMmbed/team-st-mcd

[LMESTM]

@Tharazi97 since the commit 9858b16 the target will automatically enter Deep sleep when there is nothing to do. I don't think that the lp_timeout test cases takes this into account.

When deep sleep is entered, it will induce latencies of several ms which are not considered in the test cases. By adding some more margin to the tests cases, I can run the tests okay. An alternative way forward could be that deep sleep needs to be disabled.

Snapshot of the quick diffs I made to have the test pass OK:

$ git diff TESTS/mbed_drivers/timeout/timeout_tests.h
diff --git a/TESTS/mbed_drivers/timeout/timeout_tests.h b/TESTS/mbed_drivers/timeout/timeout_tests.h
index 534901c1fb..e676b33fb4 100644
--- a/TESTS/mbed_drivers/timeout/timeout_tests.h
+++ b/TESTS/mbed_drivers/timeout/timeout_tests.h
@@ -81,10 +81,10 @@ void test_single_call(void)
     bool acquired = sem.try_acquire();
     TEST_ASSERT_FALSE(acquired);

-    acquired = sem.try_acquire_for(TEST_DELAY_MS + 2);
+    acquired = sem.try_acquire_for(TEST_DELAY_MS + 5);
     TEST_ASSERT_TRUE(acquired);

-    acquired = sem.try_acquire_for(TEST_DELAY_MS + 2);
+    acquired = sem.try_acquire_for(TEST_DELAY_MS + 5);
     TEST_ASSERT_FALSE(acquired);

     timeout.detach();
@@ -147,7 +147,7 @@ void test_override(void)
     TEST_ASSERT_FALSE(acquired);
     timeout.attach_callback(mbed::callback(sem_callback, &sem2), 2.0f * TEST_DELAY_US);

-    acquired = sem2.try_acquire_for(2 * TEST_DELAY_MS + 2);
+    acquired = sem2.try_acquire_for(2 * TEST_DELAY_MS + 6);
     TEST_ASSERT_TRUE(acquired);
     acquired = sem1.try_acquire();
     TEST_ASSERT_FALSE(acquired);

Team in charge of tests could propose the best way forward ...

[Tharazi97]

3 ms delay is quite a big change in case of 10 ms delay. I think disabling deep sleep is a good way to go.

[LMESTM]

@Tharazi97
The deep sleep latency is currently estimated to 3ms.
The System Timer takes this into account and program wake-up time in advance to ensure the precision of the system.

Now I don't think that the Low Power ticker or timeout drivers have implemented a similar safety mechanism, which mean that they will not cope with the deep sleep latency and risk of being unprecise ... but maybe I'm worng here, maybe @kjbracey-arm can correct me if I'm wrong ....

[ciarmcom]

Internal Jira reference: https://jira.arm.com/browse/MBOCUSTRIA-1804

[0xc0170]

@LMESTM what's the deep sleep wake up time for this target (I recall some targets have it defined as 1-3ms, we set this to 10ms to be sufficient for a target to wake up and app should not expect anything lower than that).

We are testing lp ticker in this test case, should it test both - deep sleep and also shallow sleep? If deep sleep involved, timeout (default is 10 + 2 = 12ms - might not be enough for some). I can't find the time reference in the power management header file at the moment (https://os.mbed.com/docs/mbed-os/v5.13/apis/power-management-sleep.html - does not provide this detail).

[LMESTM]

@0xc0170 I think that the exit time is about 3ms as defined in "deep-sleep-latency", that was the value last time I made measurements. Neverthless I need to increase the test delay to TEST_DELAY_MS + 5 be able to PASS the test. TEST_DELAY_MS + 4 wouldn't work.

I don't know how the semaphore timeouts are managed ...

[kjbracey]

The HAL specification for sleep permits wakeup time from deep sleep to be up to 10ms.

So if testing the lpticker API, if the system is being allowed to enter deep sleep, then extra 10ms delays on the timer wakeup are to be expected.

If you're only intending to test the lpticker itself, and its IRQ generation accuracy, and you do not want the potential added delay of deep sleep wake interfering with that, then the test could lock deep sleep. That seems the thing to do here.

A broader test might try checking whether the delay exceeds the specified target.deep_sleep_latency. Although that would be also revealed by a test of rtos::ThisThread::sleep_for or similar - that should enter deep sleep but compensate for the latency so that you get woken at the correct time. (If the target has specified a latency - default is 0, meaning no compensation).

[kjbracey]

I don't know how the semaphore timeouts are managed ...

I can see in that test_single_call there is going to be some juggling of the HAL timer programming. The manual LowPowerTimeout is going to be setting a timer for start + 10ms, and the semaphore wait is going to be wanting start + 12ms - latency.

If latency > 2, that means a couple of back-to-back programmings happening on the way into the sleep for the semaphore wait.

Still, when the timers go off, the semaphore acquire should not return until either the sem_callback has been run (meaning the HAL timer indicates time > start + 10ms) or the RTOS thinks time is up (meaning the HAL timer indicates time > start + 12ms).

It's a struggle to see how you could get !acquired on the semaphore read. If the OS thinks the 12ms is up, surely the sem_callback must have run?

I've walked through the code, and think I can see a failure mode.

Consider the sequence:

• We wake up at start + 13ms, so sem_callback and RTX timeout seem simultaneous
• sem_callback runs, releases semaphore
• Semaphore count incremented (isrRtxSemaphoreRelease)
• Post-processing entry added to ISR queue
• Kernel resumes from sleep (both because time elapsed and entry on ISR queue)
• Kernel updates ticks after sleep (svcKernelResume)
• Kernel decides semaphore acquire has timed out (osRtxThreadDelayTick)
• Kernel goes to return timeout error to thread
• Post-processing for ISR happens that would wake thread with "OK" - too late

So there's an effective race if due to wake latency issues, we see the 10ms IRQ and the 12ms wake simultaneously; the wake makes the semaphore return timeout, despite there being a semaphore available - the semaphore "release" is not fully processed until the next time we return to a thread, and at that point we're already returning "timeout".

I'm thinking that could potentially be called an RTX bug, although I'm not sure exactly how it might be resolved.

However, why does that situation arise here? What's the declared latency? How long might we be getting stuck inside timer reprogramming?

[kjbracey]

I guess that failure I describe above happens reliably if declared latency is 0, so no RTOS compensation, but the hardware actually takes >2ms to wake, so we program wake for "start + 10" (for the LowPowerTicker), and we only actually wake at "start + 13".

[LMESTM]

So if testing the lpticker API, if the system is being allowed to enter deep sleep, then extra 10ms delays on the timer wakeup are to be expected.

That might be argued don't you think ? lpticker driver could be aware of deep-sleep latency and compensate for it, it could even lock deep-sleep in case the next ticker in the pipe is too close ... ?
or maybe not ... I'm not sure whether this makes sense or not - this is really an open question.