Missing APP_TIMER interrupts?

[jbmillard]

I am using nRF5 SDK 16 on a Rigado BMD-300 (nRF52832) series evaluation kit.  The application receives button presses and releases from a peripheral (characteristic change notifications).  I'm using an app timer to process button timing (e.g. single clicks, double clicks, long holds, etc).  Button activity is then sent to a host through the UART (using a FIFO).  Without the timer interrupt, there is no button activity and no UART activity.

The timer calls a routine in my button module:

static void buttons_timer_callback(void* p_context)
{
  if (buttons_data.timer_callback) buttons_data.timer_callback();
}

which calls a callback set when the button processing module is initialized.  It's never set again.

The callback just sets the flag:

void button_timer_callback(void)
{
  main_event_flags.do_buttons = true;
}

So short of the redirection of the callback, I'm doing just about the absolute minimum in the timer interrupt.

The problem is that the app timer seems to stop after a few seconds of activity and it's not consistent when it stops.  Sometimes it stops for up to 100 ms and when it resumes, it misses more than it makes.

In the app timer callback, I'm setting a global flag and processing the buttons in the main idle loop so it spends very little time in the interrupt.  The timer is set for 5 ms.  Here is my sdk_config.h setup;

/ <e> APP_TIMER_ENABLED - app_timer - Application timer functionality
//==========================================================
#ifndef APP_TIMER_ENABLED
#define APP_TIMER_ENABLED 1
#endif
// <o> APP_TIMER_CONFIG_RTC_FREQUENCY  - Configure RTC prescaler.
 
// <0=> 32768 Hz 
// <1=> 16384 Hz 
// <3=> 8192 Hz 
// <7=> 4096 Hz 
// <15=> 2048 Hz 
// <31=> 1024 Hz 

#ifndef APP_TIMER_CONFIG_RTC_FREQUENCY
#define APP_TIMER_CONFIG_RTC_FREQUENCY 1
#endif

[

In app_timer_start(), timeout_ticks is 82.  I calculate that to be 5ms.

  NRF_LOG_DEBUG("Starting button timer, ticks = %d", ticks);
  (void)app_timer_start(zrf_buttons_timer_id, ticks, NULL);

Here is the log message:

<debug> app: Starting button timer, ticks = 82

My question is, is there anything about processing app timer events/interrupts that you have to be careful of?  I saw a 6 year old post about using the app scheduler, to process app timer events, but don't see how that can be done -- does that still apply?  Could this be an interrupt priority issue?  If so, that would imply I'm doing a bunch of stuff in interrupts and I just don't see that.  Any suggestions on what to check?

[Edvin]

Hello,

To investigate whether the issue is related to the app_timer queue, you can see if you get the GPIOTE interrupts inside the button handler, i.e. the function that starts the timer:

  NRF_LOG_DEBUG("Starting button timer, ticks = %d", ticks);
  (void)app_timer_start(zrf_buttons_timer_id, ticks, NULL);

Since you see the log message, it would suggest that the interrupt is triggering. It may be that the app_timer call is not being successfully called. The app timer is scheduled, so the app_timer_start() call will not actually start the timer,  but schedule this call. Try to print the return value from the call using something like this:

  ret_code_t err_code = app_timer_start(zrf_buttons_timer_id, ticks, NULL);
  NRF_LOG_DEBUG("Starting button timer, ticks = %d, ret = %02x", ticks, err_code);

If app_timer_start() returns 0x00, then the app_timer_start() is successfully queued. However, in a button press, you may have a bit of bounce on the GPIOTE signal, which will start and stop the timer many times. If this happens too many times too frequently, it may fill the app_timer_scheduler, in which case app_timer_start() would return NRF_ERROR_NO_MEM (=0x04). The easiest workaround is probably to increase the app_timer sheduler queue by increasing APP_TIMER_CONFIG_OP_QUEUE_SIZE in sdk_config.h. Try this and see if it helps. (you can try to print some counter to see how many times app_timer_start()/app_timer_stop() calls you have on a typical button press. Note that both ..._start() and ..._stop() will be scheduled.

If that doesn't work, you will have to look into some other implementation that doesn't exhaust the app_timer scheduler in the same way as the current implementation.

Best regards,

Edvin

[jbmillard]

This is a different, custom button module.  It doesn't have much of anything in common with the Nordic button module.  The central is not responding to GPIO events -- it is processing button presses from the peripheral through a button state characteristic.

Debouncing is done in the peripheral, I'm not seeing any bouncing at the central where the timer is running.

The app timer (on the central) is started when the module is initialized and not turned off.  It runs all the time.  Yes it is being started because I get some timer events.  Again, it stops after a while for some, unknown to me, reason.

[jbmillard]

I haven't tried ble_app_blinky_c.  The timer doesn't behave this way in my peripheral code.  It works fine there.  Neither central or peripheral use a RTOS.

I'm sure it probably is something in my code.  I can't believe I've found an issue with the APP_TIMER after this long.

Yes, Segger IDE. There isn't much to see in the debugger on the app_timer that I know of.  My button data looks like it should when breaking.

[jbmillard]

Here's another log message snippet.  The "Processing button states" is logged after the 5 ms timer sets the processing flag.  It's logged from the main idle loop.  The "Got new button states..." messages are from the ble_evt_handler, BLE_GATTC_EVT_HVX event.  Because of the way the remote does debouncing, the two "Got new button states..." messages are at least 20 ms apart.

<debug> app: Processing buttons states
<debug> app: Processing buttons states
<debug> app: Processing buttons states
<debug> nrf_ble_gq: Processing the request queue...
<debug> app: Got new button states: 0000
<debug> nrf_ble_gq: Processing the request queue...
<debug> app: Got new button states: 0010
<debug> app: Processing buttons states
<debug> app: Processing buttons states
<debug> app: Processing buttons states
<debug> app: Processing buttons states

Note the lack of "Processing button states" log entries between the two.  I would expect at least three would have to be there.  Typically many more as I can't physically do a 20 ms button press and release.

The BLE_GATTC_EVT_HVX event calls a routine that does this:

  // Check if the event is on the link for this instance.
  if (m_conn_handle != evt->conn_handle) return;

  // Button characteristic is 16 bits - two bytes
  if (2 == evt->params.hvx.len)
  {
    uint16_t data = (evt->params.hvx.data[0] << 8) | (evt->params.hvx.data[1]);
    if (evt->params.hvx.handle == m_events_char_handle) buttons_set_new_button_states(data);
  }

The function buttons_set_new_button_states(data) just logs the message "Got new button states..." and writes the new button states to a global variable and then returns.  I think I posted this above.

Is there any reason the ble_evt_handler() would stop timer interrupts?

[Edvin]

the ble_evt_handler() would probably stop your timer interrupts, yes, depending on the timer priority. But the timer interrupt handler will be called after ble_evt_handler() is done. In fact, there are a few events in the softdevice that will block your application from time to time. But if there is an interrupt waiting it will always be handled after the softdevice interrupts. This is just the way interrupt handlers work. So unless you spend too long time (>5ms) in an interrupt handler, you will not loose any interrupts. If you spend e.g. 15ms in an interrupt handler, so that your timer has up to 3 timer interrupts, then you may not see 2 of them, because it will only see that a timer interrupt has occured, but not that it has occured 3 times.

As mentioned, the softdevice has a lot of interrupts, on different priorities, but none that takes up to 5ms. So unless you do so in the ble_evt_handler() or any of your other application interrupt handlers, it shouldn't break your timer.

Do you do anything that takes up very long time in your ble_evt_handler()? 

What is your timer interrupt priority? 

You can read about the softdevice priorities here.

BR,

Edvin

[jbmillard]

No I'm not doing anything in the BLE event handler that would take that long.  For the most part, the only thing that I'm seeing when this is happening is the BLE_GATTC_EVT_HVX event which I posted above.  I don't see how that can take 15 ms.

The interrupt priorty should be what I sent you in the sdk_config.h.  I haven't changed it other than when you requested I do so and then I put it back because it didn't make any difference.

I have read the documentation you linked.

[Edvin]

jbmillard said:

I have read the documentation you linked.

 Good stuff. 

Until I know how your application works, I don't know how to approach this issue then. If you can't share the project due to company policies, then I suggest that you try to replicate the issue in one of the SDK examples. It doesn't sound like much changes from the ble_app_blinky and ble_app_blinky_c examples. Perhaps these can be used as a starting point.