app_timer firing far too late, app_timer_cnt_get() gives weird results

[Alex Suzuki]

Hi,

I'm using the nRF51 dongle with nRF SDK 12.3.0 and the S130 2.0.1 SoftDevice to implement a BLE central. The dongle repeatedly connects to a BLE peripheral, performs some tests, then disconnects.

I am using the app_timer module to delay some actions in the tests to test different scenarios. In total I have three single-shot timers, for which I call app_timer_create at startup, and then app_timer_start/app_timer_stop repeatedly. During a test run, I do not always use all three of them, but at the end I call app_timer_stop on all of them.

err_code = app_timer_create(&m_timer1, APP_TIMER_MODE_SINGLE_SHOT, timer1_handler);
APP_ERROR_CHECK(err_code);
err_code = app_timer_create(&m_timer2, APP_TIMER_MODE_SINGLE_SHOT, timer2_handler);
APP_ERROR_CHECK(err_code);
err_code = app_timer_create(&m_timer3, APP_TIMER_MODE_SINGLE_SHOT, timer3_handler);
APP_ERROR_CHECK(err_code);
... later ...
NRF_LOG_DEBUG("Will wait %d ms before doing xxx\n", m_xxx_delay_ms);
err_code = app_timer_start(m_timer2,
                                   APP_TIMER_TICKS(m_xxx_delay_ms, APP_TIMER_PRESCALER), ctx);
APP_ERROR_CHECK(err_code);

For some reason, the timing is completely off. The timers take way too long to fire, in the order of seconds. I am new to nRF5 development, and started off using the heart rate sample. The app_timer module is initialized like so:

APP_TIMER_INIT(APP_TIMER_PRESCALER, APP_TIMER_OP_QUEUE_SIZE, NULL);

with APP_TIMER_OP_QUEUE_SIZE set to 5. Not sure if this is the right value. I saw that there was an config macro for profiling, but I am unsure what it does and how it would help me. At least I don't see any NRF_LOG output when I activate it.

Another thing I am observing and believe that it's probably related, is the following: i use app_timer_cnt_get() and app_timer_cnt_diff_compute() to compute the elapsed time since the BLE connection was established:

static int elapsed_ms_since_connected() {
    uint32_t ticks_since_connected;
    app_timer_cnt_diff_compute(app_timer_cnt_get(), m_connection_established_ticks, &ticks_since_connected);
    return (ticks_since_connected * 1000) / APP_TIMER_CLOCK_FREQ;
}

m_connection_established_ticks is set using app_timer_cnt_get() when the BLE_GAP_EVT_CONNECTED event is received. I then print these values out over NRF_LOG, and they are completely wrong too.

Have I misconfigured the timer somehow? How do I go about debugging this issue?

Many thanks in advance, Alex

[Alex Suzuki]

Hi Jørgen, thanks for taking the time to comment.

I use an APP_TIMER_PRESCALER value of 0, according to the docs this overflows after 512 seconds which is fine, I use timer timeouts between 100ms and 60s. It's a bit difficult to measure because my timestamp function also exhibits strange behavior.

The software I'm writing is a stress test for a BLE peripheral, which repeatedly connects/disconnects and performs some actions with random delays. I am starting/stopping the timers at the start / end of every test run, which is on average probably around every 10 seconds or so. Sometimes a timer will not be started, because zero delay is simulated, app_timer_stop is called nonetheless however, I read that this is fine too (calling stop on a not-started timer).

I did notice however that the return value of app_timer_cnt_get() overflows whenever wrong timestamps are printed. I was under the assumption that app_timer_cnt_diff_compute will handle overflow? NRF_LOG output of a "bad case", see timestamp at end.

APP:DEBUG:app_timer_cnt_get: 641293
APP:DEBUG:Services discovered after 602 ms
APP:DEBUG:app_timer_cnt_get: 647180
APP:DEBUG:Notifications enabled after 781 ms
APP:DEBUG:Will wait 100 ms before sending X
APP:DEBUG:Started timer1: 0
APP:DEBUG:app_timer_cnt_get: 650459
APP:DEBUG:Sending X after 881 ms
APP:DEBUG:Will wait 4000 ms before sending Y      
APP:DEBUG:Stopped timer1: 0 
APP:DEBUG:Stopped timer2: 0
APP:DEBUG:Stopped timer3 0
APP:DEBUG:Disconnected, evt conn handle: 0, our conn handle: 0
APP:DEBUG:app_timer_cnt_get: 1958
APP:DEBUG:Disconnected after 99875 ms

About the the higher interrupt context, how would I go about debugging this?