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

Missing APP_TIMER interrupts?

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?

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

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

  • I would agree since there are no buttons on the central.  It is a repeated 5 ms timer.  Again, it starts and then after a few seconds stops.  After it stops (for sometimes up to 100 ms) it starts again, but it's flaky - missing quite a few events.  sdk_config.h was sent via private message.

  • jbmillard said:
    After it stops (for sometimes up to 100 ms) it starts again, but it's flaky - missing quite a few events.

     I see. Do you have any other interrupts with higher priority that you spend a lot of time in? E.g. do you spend a lot of time (up to 100 ms) in any SD interrupts in your application?

     

    jbmillard said:
    sdk_config.h was sent via private message.

     I have not received any messages. Are you sure it was sent?

  • I don't spend a lot of time in any interrupt that I can tell.  UART processing (central talks to a host) is done through a FIFO and there is nothing to send if the timer isn't running.  I'll send it again.

  • Is there any way for me to reproduce your issues? 

    I suspect that you are waiting for something particular in an event?

    In case it is another peripheral blocking you, you can try to set APP_TIMER_CONFIG_IRQ_PRIORITY to 5, just to raise the priority a little. If it doesn't help, then it is probably a softdevice event blocking it. 

  • The remote is custom hardware.  I can't send you the code for either, unfortunately.

    I upped the priority, it didn't make any difference.  I also tried upping the queue size, that didn't matter either.

Reply Children
  • Can you try to replicate the issue in a stripped down example, then? Or one of the examples in the SDK that you modify to replicate the issue on a DK? It isn't really much I can do with the information that I already have. 

    But I guess I can try a few more shots in the dark:

    • Is there anything else using the app_timer?
    • What is your APP_TIMER_CONFIG_USE_SCHEDULER?
    • What is your APP_TIMER_KEEPS_RTC_ACTIVE? Can you try to set it to true?
    • Is there something else happening right before you start loosing the app_timer events? Does the log give any hints?

    BR,

    Edvin

  • There is a second app_timer instance used in the central's UART connection to the host.  It is used as a single shot timer to guard against partial messages (if it times out, it resets the receive state machine).  This is currently commented out so I could see if this is the problem.  It didn't make any difference.

    I don't know of any way to really do a stripped down version.  You have to have a connection to the peripheral so I need BLE, scanning, peer manager, discovery, etc.

    APP_TIMER_CONFIG_USE_SCHEDULER is 0.

    APP_TIMER_KEEPS_RTS_ACTIVE is 0.  I set this to 1 and it didn't make any difference.

    For the log messages, I get a message when I see the peripheral state change - that always happens.  When the state of the peripheral buttons change, I call a simple routine in the button module to set the new states and the new states are set the current states at the end of the button processing.  Since the button processing is kicked off by the timer, what I see is log messages for getting the new states and no log messages for setting the new states:

    <debug> app: Got new button states: 0010
    <info> app: Updating button states...
    <debug> nrf_ble_gq: Processing the request queue...
    <debug> app: Got new button states: 0000
    <info> app: Updating button states...
    <debug> nrf_ble_gq: Processing the request queue...
    <debug> app: Got new button states: 0010
    <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> 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> 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
    <info> app: Updating button states...
    <debug> nrf_ble_gq: Processing the request queue...
    <debug> app: Got new button states: 0000
    <info> app: Updating button states...

    You can see the two messages, "Got new button states" that is the result of a BLE GATTC event from me pushing and releasing the button on the remote.  The four digit hex value is the up/down state of all buttons.  It calls a routine that looks like this:

      NRF_LOG_DEBUG("Got new button states: %04X", new_button_states);
      buttons_data.new_button_states = new_button_states;

    That's all it does is save the new states to global data.

    When the timer interrupt happens, it sets a processing flag and the main idle loop calls a routine to process the button events when that flag is set.  At the end of that routine I set the new states to the current states.  I do it like this to make sure the states don't change in the middle of button processing:

      /* If it's changed, set it here.  This way we get every state and it doesn't change in 
         the middle of button processing */
      if (buttons_data.button_states != buttons_data.new_button_states)
      {
        NRF_LOG_INFO("Updating button states...");
        buttons_data.button_states = buttons_data.new_button_states;
      }

    So when the timer interrupts stop, the "Updating button states" message starts to disappear (there are no exits from that routine - if it starts, it has to finish).  It was the same as when I was processing button events in the APP_TIMER interrupt.

    I have put a log message at the beginning of the button processing routine and it isn't received either when the problem starts.  I don't keep that message in there because you get a bunch of them when it's running.

  • If you add an app_timer with 5ms timeout in the ble_app_blinky_c example, does it behave the same?

    Many examples use the app_timer together with BLE without this issue, so I am not sure why it happens, and it is difficult to tell whats going on without being able to reproduce it. Remember that I have no idea what your project looks like. Is it based on the examples? Do you use an RTOS? (FreeRTOS)

    Do you use an IDE to debug? Do you see anything particular when this occurs? Have you tried breaking when it isn't hit? 

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

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

Related