Timer handler mess up application flow

[Hieu]

I have a working application with TIMER1 setup to fire handler every 10us. I would like to add a 560us periodic event to enable/disable a PWM, so I add a little more code to my timer handler:

static uint16_t                         m_10us_cntr2= 0;
void timer_event_handler(nrf_timer_event_t event_type, void* p_context)
{
    // TROUBLESOME_CODE  -----------------------------------------
    m_10us_cntr2++;
    if (m_10us_cntr2>= 56)
    {
//        NOT EVEN DOING ANYTHING HERE YET
        m_10us_cntr2= 0;
    }
    // /TROUBLESOME_CODE  ----------------------------------
    
    m_10us_cntr++;
    if (m_10us_cntr>= 100000)
    {
        m_second_counter++;
        m_10us_cntr= 0;
    }
    //m_second_counter++;
    if (m_second_counter == PERIODIC_TASKS_PERIOD)
    {
        m_periodic_flag = true;
        m_second_counter = 0;
    }
}

To my surprise, just the presence of the if block make the app crash completely during TIMER1 initialization. The debug printf() statement "end of timer_init\n" I had after my TIMER1 initialization function calls could only push out "end" or "end o" before the app crashes.

What is causing this? Is there a way to fix it?

Update: for reference, here is my timer_init() code:

void timer_init()
{
    DEBUG_PRINT(("timer_init\n"));
    
    uint32_t                err_code = NRF_SUCCESS;
    uint32_t                time_us = 10; //Time (in microseconds) between consecutive compare events.
    uint32_t                time_ticks;    

    nrf_drv_timer_config_t  timer_config = NRF_DRV_TIMER_DEFAULT_CONFIG(1);
    timer_config.frequency  = NRF_TIMER_FREQ_16MHz;


    err_code = nrf_drv_timer_init(&m_timer, &timer_config, timer_event_handler);
    if (err_code != NRF_SUCCESS)
    {
       // The only error possible for this function is NRF_ERROR_INVALID_PARAM	according to SDK v10 documentation
       // TODO: handling error
    }

    time_ticks = nrf_drv_timer_us_to_ticks(&m_timer, time_us);
    DEBUG_PRINT(("time_ticks = %d\n", time_ticks));

    nrf_drv_timer_extended_compare(
        &m_timer, NRF_TIMER_CC_CHANNEL0, time_ticks, NRF_TIMER_SHORT_COMPARE0_CLEAR_MASK, true);

    nrf_drv_timer_enable(&m_timer);
    DEBUG_PRINT(("end of timer_init()\n"));
    
}

The app always failed while printing out the last debug print ("end of timer_init()").

Update Apr 20 2016: So I run a few more experiments, and the details bizarre me even more, so please bare with me.

1. I first tried to use uVision debug to look at what cause the app flow to hang. When I hit stop, I found the current-line-of-execution pointer sometimes points at nrf_timer_event_check(), sometimes at my timer_event_handler(), sometimes at nrf_timer_event_clear(). It feels like this is a case of interrupt handling taking too long and block the code flow.

   I also observed that the "end of timer_init()\n" print not only fails midway, but also sometimes have characters print out of order.

2. I tried to move the timer_init() call to the bottom of all of my initialization function calls. This moves the following two functions to be called before timer_init():

   a- i2c_slave_drv_init(): A function I used to read confirmation values and initialization values to an I2C slave peripheral. In case it matters, my I2C read and write implementation uses the following blocking wait to wait for TWI Driver events

       watchdog_counter = 0;
       while(!twi_drv_evt_received && watchdog_counter < 60000)
       {
           nrf_delay(1);
           watchdog_counter++;
       }
   

   b- ble_advertising_start()

   The app can now run without major issue after this change. The only minor issue is my 1s flag now takes a lot more than a second to fire. I assume this is due to timer_event_handler() processing delay

3. Now here comes the bizarre part: I tried to reproduce the issue by moving timer_init() back where it was. And the issue stop happening. However, that is only as long as I don't add another if block to timer_event_handler. If I change the TROUBLESOME_CODE into the following, I can then reproduce the issue:

   if (m_10us_cntr2 > 56)
   {
       if (m_pwm_toggle) {
           // TODO
       } else {
           // TODO
       }
       m_pwm_toggle = !m_pwm_toggle;
       m_10us_cntr2 = 0;
   }
   

4. At this point, I found out that the app did not actually got stuck entirely. Returning to the console after writing the above, I found that the issue is:

   a- While running initialization code, it just takes almost half a minute to print out a single characters. You can see in this screen record: uart_rate_init.avi (Please excuse the low quality. I need to do so due to the long duration of the process)

   b- While running main()'s super loop code, the app could only print 3-5 characters a second. You could see in this screen record: uart_rate_loop.avi

And that is the last of my observations. I hope somebody have an idea what is going on. This is really too strange for me to have any idea.

[Susheel Nuguru]

Vo Thanh Hieu, Could you please check if there is a stack overflow. It is easy to check by looking at the SP register after running your code for some time.

I am not 100% sure of how the stack is handled when the interrupt is pended while being serviced. I think what RK says makes sense but I would like to get the value of Stack Pointer just to be sure. RK, Congrats for being on the TOP of the devzone ranking. You are now most reputated user in this forum.

[RK]

Aryan - if an interrupt is raised when one is already in progress, only if it's higher priority will it be taken, then, yes that interrupt handler stacks, runs and returns to the original running one. If the interrupt is the same or lower priority (which it would be if it's the same interrupt), then only the pending flag in the NVIC is set for it.

When the current interrupt returns, the highest priority pended interrupt is taken and stacked at that point (actually it just tail calls it but same effect)

So on the M0 you can theoretically only get 4 on the stack at the same time and only if you had a priority 3, then a 2 then a 1 and then a 0 interrupt in that order, each one interrupting the last before completion.

I expect in this case the timers are so short the code just ping pongs between the TIMER interrupt and the timer handler interrupt and never goes to do anything else.

[Hieu]

@rols @aryan: Thanks for being so enthusiast about this case. I will get the application pointer for you when I get back to my office on Monday. @rols: You mentioned that a 10us interval is unfeasible. Could you please explain why you could tell that?

[RK]

For exactly the reason Aryan mentioned above, it's 160 cycles. The M0 interrupt latency is 16, the softdevice adds 49, so basically you have 100 cycles left. If you look at the app timer code it's going to work its way down a linked list, work out which timers to fire, fire them by calling your service routine, remove them, reschedule the next one, shuffle them back into the list. And it does the servicing by raising another interrupt, so that's another 60 cycles. And that's before you actually do any work in your handler. I'm fairly impressed that it even managed to call your timer handler every 10us, back when it was basically a do-nothing handler, add any code and all you do is service the timer.

And even if it did work it wouldn't work really because the softdevice is going to interrupt and put huge big random 20-500us gaps in the timing, so you will miss many ticks.

[Hieu]

@rols: I see now. Could you advise me where I could learn in-depth details like the number of cycles SoftDevice and Interrupt handling takes?