This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

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

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

  • What is the value of APP_TIMER_PRESCALER? How often do you start/stop the timers? Could you measure the time between timeouts? Are you sure the application is not stuck in some higher interrupt context, delaying the handling of the timer timeout? What is the return value of app_timer_cnt_get etc.?

  • 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?

  • And here is the log output of a 'bad case', where a timer that is set to fire after 100ms does not fire. The peripheral disconnects after 4.1 seconds of inactivity, so this is the next event that occurs. Note also that timestamps are printed correctly here, app_timer_cnt_get does not overflow here.

    APP:DEBUG:app_timer_cnt_get: 123774
    APP:DEBUG:Services discovered after 602 ms
    APP:DEBUG:app_timer_cnt_get: 129660
    APP:DEBUG:Notifications enabled after 781 ms
    APP:DEBUG:Will wait 100 ms before sending challenge
    APP:DEBUG:Started timer1: 0
    // ... nothing happens for 3.3s ..., peripheral disconnects due to inactivity
    APP:DEBUG:disconnected, evt conn handle: 0, our conn handle: 0
    APP:DEBUG:app_timer_cnt_get: 239751
    APP:DEBUG:Disconnected after 4141 ms
    APP:DEBUG:Stopped timer1: 0
    APP:DEBUG:Stopped timer2: 0
    APP:DEBUG:Stopped timer3: 0
    
  • 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.

Related