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]

It seems the problem was that I was using the bsp library, and making liberal use of the LED indication routine bsp_led_indication. It seems internally the bsp library uses app_timer to do the blinking.

After driving the LEDs directly through the bsp_board_led_on/bsp_board_led_off functions my timing code seems to work stable for now.

[Jørgen Holmefjord]

Thank you for reporting back the issue!