nRF52 timer problem

[tbondar]

Description

I'm trying to get the BLE_Button example working with low power enabled. Based on the answer to this question I compiled the example code with RTOS disabled (by adding .mbedignore as suggested). Power consumption went down as expected but the LED stopped blinking after a couple of hours of running. This makes the BLE unusable on nRF52 for any practical purpose because either it has too high power consumption or stops working after a few hours.

• Type: Bug
• Related issues: Multiple tickers stop working #1533, multiple tickers stop working #1378 ?
• Priority: Blocker

---

Bug

Target
NRF52_DK

Toolchain:
GCC_ARM

Toolchain version:
gcc-arm-none-eabi-4_9-2015q3

mbed-cli version:
0.9.10

mbed-os sha:
5faf4b2 Merge pull request #3837 from ARMmbed/release-candidate

Expected behavior
BLE_Button example should keep working with low power enabled.

Actual behavior
After some time the LED stops blinking. The BLE interface still works, i.e. I can connect to the device and read characteristics correctly. When there is some BLE activity the LED blinks once or twice. It seems that the EventQueue stops calling the blinkCallback() function.

This happens after a couple of hours of running. It seems that the exact time required depends on the on the event dispatch frequency:

eventQueue.call_every(n, blinkCallback);

If n is 50, LED stops blinking after 8200 seconds, if n is 20, it stops after about 6670 seconds.

Steps to reproduce
Download the official BLE_Button example, disable RTOS by adding the following .mbedignore to the project and compile the code.

mbed-os/rtos/*
mbed-os/features/FEATURE_CLIENT/*
mbed-os/features/FEATURE_COMMON_PAL/*
mbed-os/features/FEATURE_UVISOR/*
mbed-os/features/frameworks/*
mbed-os/features/net/*
mbed-os/features/netsocket/*
mbed-os/features/storage/*

Additional Comments
I have been trying to make BLE examples work with low power for a few days now using various methods. I tried using waitForEvent() and Tickers with a very similar result. It seems that some low level code interfacing the nRF52 timer might be buggy in some way.

[pan-]

@tbondar Thanks for the detailed bug report.

After some time the LED stops blinking. The BLE interface still works, i.e. I can connect to the device and read characteristics correctly. When there is some BLE activity the LED blinks once or twice. It seems that the EventQueue stops calling the blinkCallback() function.

Did you observe the same behavior if the RTOS is enabled ?

[tbondar]

I couldn't reproduce the problem with RTOS enabled (i.e. the default .mbedignore file). I keep my test running just in case, but it seems this problem is related to when low power mode is enabled one way or another.

[pan-]

@nvlsianpu could you look into this ?

[tbondar]

@pan- @nvlsianpu Just wondering if there's a chance to get a fix for this soon or I'd better look for some workaround. Thanks.

[nvlsianpu]

I started with looking into. I encountered that this if was not fullfiled. After code had gone through "that if" it weren't generated periodical event requested by eventQueue.call_every method.

@tbondar could you confirm that it behaves similar on your desk? You can for example use printf for alternate condition of "this if".

[tbondar]

@nvlsianpu (Previous comment updated after further tests)

You are probably right. I made the following changes to equeue_mbed.cpp and let the application running. When it breaks, LED3 stops blinking and LED4 does not start blinking. LED 4 toggles occasionally when certain BLE events happen or the button is pressed. Apparently, variable ms is negative or zero.

--- a/events/equeue/equeue_mbed.cpp
+++ b/events/equeue/equeue_mbed.cpp
@@ -128,12 +128,17 @@ static void equeue_sema_timeout(equeue_sema_t *s) {
     *s = -1;
 }
 
+DigitalOut  led3(LED3);
+DigitalOut  led4(LED4);
+
 bool equeue_sema_wait(equeue_sema_t *s, int ms) {
     int signal = 0;
     Timeout timeout;
     if (ms > 0) {
         timeout.attach_us(callback(equeue_sema_timeout, s), ms*1000);
-    }
+        led3 = !led3;
+        led4 = 1;
+    } else { led4 = !led4; }
 
     core_util_critical_section_enter();
     while (!*s) {

[nvlsianpu]

We encountered the same. Great! It looks like some code had been executing to long and therefore a event time to setup had been overdue and then expected new event didn't been requested anymore.

[tbondar]

It's interesting that it happens after exactly the same time (~ 8200 seconds) while the code is advertising only. I don't need to stress it in any way to reproduce it. Another comment is that a very similar thing happens with RTOS enabled, please see my comments at #3509 and here.

[nvlsianpu]

@pan- Why the creating evet-queue requests tick timer to start? here

[pan-]

Why the creating evet-queue requests tick timer to start? here

@nvlsianpu Do you think it should be started only when the tick timer is actually in use; when their is at least one event in the event queue to execute in N ticks ?

I think it is a commodity solution, the equeue_tick function is used by all event queues the system can create and is not tied to any instance so it is easier to think about it if the tick is always running.

@geky Am I correct ?

[nvlsianpu]

Do you think it should be started only when the tick timer is actually in use; when their is at least one event in the event queue to execute in N ticks ?

I think it could be kept as is for now - this is very rare tick and RTC consume a few uA. But it could be a case for ultra low power devices (like a flowmeter).

---

If the time is close to the period which was requested by creating of the evnt-queue it is possible the following code execution:

ev_dispatch -> next_evt_set

It looks like sometimes after that sequence, the expected periodic event (e.g. of 50 ms) is never requested again.

I discovered that RTC CC event were always being requested periodically: 1st by the ticker form RTC handler and very soon 2nd by the event dispatcher - until described sequence.

CC set twice                           CC set twice              CC set once
  1  2                                      1  2                           1
__|__|______________________________________|__|_______......______________|_.___________

I will back to investigation on monday.

[geky]

Ah, yeah, the event queue assumes the equeue_tick is always running.

The queue keeps track of the last tick a dispatch occured on. This is used to decide if a cancelled event is still in the queue (here). We also don't assume when the tick starts, so choosing 0 may happen in the near future.

We could add something that decides this tick lazily as @pan- suggests, but currently the queue simply loads from the timer during initialization.

---

Could it be that equeue_sema_wait is getting called with a wait of zero? This can happen if it takes enough time between dispatching events and going back to wait (here). It looks like the non-rtos equeue_sema_wait may not handle zero correctly (here).

 bool equeue_sema_wait(equeue_sema_t *s, int ms) {
     int signal = 0;
     Timeout timeout;
-    if (ms > 0) {
+    if (ms >= 0) {
         timeout.attach_us(callback(equeue_sema_timeout, s), ms*1000);
     }
 
     core_util_critical_section_enter();
     while (!*s) {
         sleep();
         core_util_critical_section_exit();
         core_util_critical_section_enter();
     }