Ticker issue on NRF51822

[adamgreen]

I know that I am not the first person to bring up NRF51822 ticker issues here but I just thought I would open this issue to document what I discovered when investigating this issue report on the mbed site.

With this particular repro case, I was able to track down an issue caused by this line in the NRF51822 us_ticker_set_interrupt() routine.

    if (us_ticker_appTimerRunning) {
        return;
    }

The failing scenario was:

• The ticker fired and the first thing that Ticker::handler() does is attempt to insert the next tick into the queue here.
• This ends up calling the NRF51822 version of us_ticker_set_interrupt(). By the time this code completes its call to Nordic's app_timer_start() API, the desired time has already passed.
• You might think this is where the ticker gets orphaned but there is actually more to the story.
  • When us_ticker_set_interrupt() started this expired timer, it set the us_ticker_appTimerRunning global to true.
  • After the application's ticker handler completes, it ends up passing control back to us_ticker_irq_handler(). This function is actually smart enough to check for such expired events and execute them immediately so that they don't get lost.
  • At this point no expired events have been lost and everything is as it should be.
  • us_ticker_irq_handler() then finds the next future event and queues it up for execution.
  • It is that call to the NRF51822's version of us_ticker_set_interrupt() which leads to the problem. This call will just ignore the request to queue up this future ticker event because us_ticker_appTimerRunning is set to true.

I tried calling Nordic's app_timer_stop() API when us_ticker_appTimerRunning is already set to true. This is my updated version of the function with a bunch of instrumentation added for debugging purposes:

uint32_t g_tickerLastSetTime;
uint32_t g_tickerLastSetReturn;
uint32_t g_tickerLastStopTime;
uint32_t g_tickerLastStopReturn;
uint32_t g_tickerLastFailCreateTime;
uint32_t g_tickerLastFailSetTime;
uint32_t g_tickerLastSuccess;

void us_ticker_set_interrupt(timestamp_t timestamp)
{
    if (!us_ticker_inited) {
        us_ticker_init();
    }

    if (us_ticker_appTimerID == TIMER_NULL) {
        if (app_timer_create(&us_ticker_appTimerID, APP_TIMER_MODE_SINGLE_SHOT, us_ticker_app_timer_callback) != NRF_SUCCESS) {
            /* placeholder to do something to recover from error */
            g_tickerLastFailCreateTime = us_ticker_read();
            return;
        }
    }

    if (us_ticker_appTimerRunning) {
        g_tickerLastStopReturn = app_timer_stop(us_ticker_appTimerID);
        us_ticker_appTimerRunning = false;
        g_tickerLastStopTime = us_ticker_read();
        return;
    }

    timestamp_t currentCounter64;
    app_timer_cnt_get(&currentCounter64);
    uint32_t currentCounter = currentCounter64 & MAX_RTC_COUNTER_VAL;
    uint32_t targetCounter = ((uint32_t)((timestamp * (uint64_t)APP_TIMER_CLOCK_FREQ) / 1000000) + 1) & MAX_RTC_COUNTER_VAL;
    uint32_t ticksToCount = (targetCounter >= currentCounter) ?
                             (targetCounter - currentCounter) : (MAX_RTC_COUNTER_VAL + 1) - (currentCounter - targetCounter);
    if (ticksToCount < APP_TIMER_MIN_TIMEOUT_TICKS) { /* Honour the minimum value of the timeout_ticks parameter of app_timer_start() */
        ticksToCount = APP_TIMER_MIN_TIMEOUT_TICKS;
    }

    uint32_t rc;
    rc = app_timer_start(us_ticker_appTimerID, ticksToCount, NULL /*p_context*/);
    if (rc != NRF_SUCCESS) {
        /* placeholder to do something to recover from error */
        g_tickerLastFailSetTime = us_ticker_read();
        g_tickerLastSetReturn = rc;
        return;
    }
    us_ticker_appTimerRunning = true;
    g_tickerLastSetTime = (uint32_t)timestamp;
    g_tickerLastSuccess = us_ticker_read();
}

When I run this code under GDB, I find that the events only get orphaned when the Nordic app_timer_stop() and app_timer_start() APIs both fail with a NRF_ERROR_NO_MEM when attempting to clear out an older event to replace with the future event that occurs the soonest.

Here is the dump of the state of the above code once the ticker stops running:

    (gdb) p *'us_ticker_api.c'::head
    $1 = {
      timestamp = 3430256,
      id = 536879592,
      next = 0x0 <__fp_lock>
    }
    (gdb) p g_tickerLastSetTime
    $2 = 3429256
    (gdb) p g_tickerLastSetReturn
    $3 = 4
    (gdb) p g_tickerLastSuccess
    $4 = 3429382
    (gdb) p g_tickerLastFailSetTime
    $5 = 3429504
    (gdb) p g_tickerLastStopTime
    $6 = 3429412
    (gdb) p g_tickerLastStopReturn
    $7 = 4
        # Both the stop and the start fail with the same error of 4.
        # This is NRF_ERROR_NO_MEM

Since I don't have access to the Nordic code, this is as far as I can take this investigation. Hopefully someone else will be able to carry on where I have left off.

[adamgreen]

Hopefully there is a way to get the Nordic app_timer_stop() to successfully stop an existing timer (both ones to expire in the future and ones that have already expired and may be pending an interrupt) so that it can be rescheduled.

One other thing to consider is implementing high level C++ Ticker, Timeout, etc, like classes which use the Nordic app_timer* APIs directly. This bypasses the whole common/us_ticker_api.c scheduling code since a similar implementation must already exist down in the SoftDevice stack. It would be similar to RtosTimer. This does get rid of the nice hardware abstraction provided by the existing time related classes in the mbed SDK so it isn't ideal.

Maybe the mbed SDK could be refactored a bit so that a device's C based HAL could either provide its own scheduling APIs to the C++ layer or provide low level timer interrupt APIs (used by the existing common/us_ticker_api.c scheduler) as it does today.

[mbuddy]

This may or may not be related but in my initial mbed bug report I forgot to mention that the APP_TIMER_INIT call in us_ticker.c currently uses hardcoded and potentially inadequate values rather than the appropriate ones from projectconfig.h:

APP_TIMER_INIT(0 /*CFG_TIMER_PRESCALER*/ , 1 /*CFG_TIMER_MAX_INSTANCE*/, 1 /*CFG_TIMER_OPERATION_QUEUE_SIZE*/, false /*CFG_SCHEDULER_ENABLE*/);

Raising the values by itself did not fix the Ticker issue but limiting the max number of timers and max number of operations to 1 doesn't sound right, and may even be related to the NRF_ERROR_NO_MEM code reported above.

[0xc0170]

cc @rgrover

[0xc0170]

@adamgreen I merged the PR from Rohit, I believe it was addressing this issue. Can you test please?

[mbuddy]

My test code is still failing after updating all the libraries. I did confirm that the us_ticker code included the latest changes.

[rgrover]

I've got code to replace app_timer with a direct drive for RTC1. I'll be
away this week, but I'll test and commit this sometime towards the end of
next week. Thanks for your patience; and apologies for letting this issue
remain for so long.

On Sat, Jan 31, 2015 at 10:25 AM, orcguru notifications@github.com wrote:

The crappy app_timer.c is due to the design: using two interrupt handlers
to work together will face race conditions!

The only solution is a new design of app_timer.

—
Reply to this email directly or view it on GitHub
#832 (comment).

[mbuddy]

Any news on the app_timer replacement?

[rgrover]

testing it at the moment. Should be out shortly.

[robdobsn]

Any news on this? I'm finding that the BLE stack with any Ticker (even 1s duration) is unstable on both the MKIT and Arch BLE boards I have.

[rgrover]

#932

[0xc0170]

Can you @robdobsn test the 932 and report the result there in the pull request? Thanks

[robdobsn]

I'm taking a look at this. My test (basically the BLE heart rate example with an extra toggled digitalout in the Ticker function monitored by another mbed) was failing after about 3 hours. I've started the test so will report back when it has passed that amount of time - although I guess significantly longer testing would be needed to be sure.

[robdobsn]

I've realized this is more complex than I thought. What I have done is to change the three files related to this pull request (two changed files and one deletion) in my copy of the mbed-source using online IDE and recompile my code. But what I hadn't realized is that the (separate) nRF51822 library itself depends on the Nordic app_timer. Since this no longer exists I need to mod the code (assuming there isn't a matching pull request for the nRF51822 library) to remove this dependency. I notice that Rohit is the main author of nRF51822 as well so I wonder if he has already tackled this problem or if I'm missing something?

[mbuddy]

Like robdobsn, I'd love to test the new 932 code but I haven't been able to import a working copy into my mbed test project which is available at:
https://developer.mbed.org/users/mbuddy/code/nRF51822_Ticker_Bug/
The project fails within a couple of seconds when built with the old app_timer code so it should be a good way to verify the fix.