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

Parents
  • 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
    
Reply
  • 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
    
Children
No Data
Related