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

Large delay when using app scheduler in GPIOTE interrupt

Hello,

I have an external chip in SPI slave mode and connected to 52840 through SPI interface. When data is ready it will notify 52840 through its dedicated IRQ pin (connected to one of GPIO of 52840), and then 52840 will read the data back through SPI bus., using SPIM driver.

the software is composed like this:

1. Setup GPIOTE to sense the GPIO/IRQ pin (low to high)

2. in GPIOTE interrupt handler, use app_scheduler to transfer execution to main context.

3. in main context, use SPIM driver to read data back to 52840's RAM.

the above process can run fine and the data read back are all correct. However, a problem is Step 2. has a large delay about 2ms. that is, after app_sched_event_put is called, the data event handler is executed only after 2ms. My application can not tolerant such big delay.

Is this delay normal? if not, what could be the possible reason why it happen?

Major code snippet:

Main.c

int main(void)
{
    bool erase_bonds;
    
    // Initialize.
    log_init();

    NRF_LOG_INFO("Starting nrf52840...");
    
    timers_init();
    buttons_leds_init(&erase_bonds);
    power_management_init();

    //init event scheduler;
    APP_SCHED_INIT(SCHED_MAX_EVENT_DATA_SIZE, SCHED_QUEUE_SIZE);
    
    
    // Enter main loop.
    for (;;)
    {
        //handle usbd event sperately;
        //app_usbd_event_queue_process();
        
        app_sched_execute();
        if (NRF_LOG_PROCESS() == false)
        {
			idle_state_handle();
            //power_manage();
        }
    }
}

GPIOTE init:

{
    ...
    ret_code_t err_code;
    UNUSED_VARIABLE(err_code);
    if(!nrf_drv_gpiote_is_init())
    {
        err_code = nrf_drv_gpiote_init();
        APP_ERROR_CHECK(err_code);
    }
    nrf_drv_gpiote_in_config_t in_config = GPIOTE_CONFIG_IN_SENSE_LOTOHI(true);
    //in_config.pull = NRF_GPIO_PIN_PULLUP;
    UNUSED_VARIABLE(in_config);
    err_code = nrf_drv_gpiote_in_init(EXT_DATA_IRQ_PIN, &in_config, gpiote_irq_handler);
    //APP_ERROR_CHECK(err_code);
    nrf_drv_gpiote_in_event_enable(EXT_DATA_IRQ_PIN, true);
    ...
}

GPIO interrupt handler

void gpiote_irq_handler(nrf_drv_gpiote_pin_t pin, nrf_gpiote_polarity_t action)
{
    
    if (pin == EXT_DATA_IRQ_PIN) {
     

        ex_data_event_t evt;
        //fill in data evt;
        ....
        app_sched_event_put(&evt, sizeof(evt), data_event_dispatch);

    }
    
}

app scheduler event hander:

void data_event_dispatch(void *p_event_data, uint16_t event_size) {
    ex_data_event_t* p_evt = (ex_data_event_t*)p_event_data;
    switch (p_evt->pa_ops) {
        case DATA_OPS_TYPE_EXT_PA_ON:
            //NRF_LOG_DEBUG("[ext]\tswitch PA on...");
            break;
    }
    ...

}

Parents Reply Children
  • Hi,

    I do not see how it should be related. How do you measure the time from you call app_sched_event_put() and app_sched_event_put() runs? Could it be a problem with your time measurement, rather than that it actually takes that long time?

  • Hi,

    I use following method, in GPIOTE IRQ handler, record the current ticks into data event,

    void gpiote_irq_handler(nrf_drv_gpiote_pin_t pin, nrf_gpiote_polarity_t action)
    {
        
        if (pin == EXT_DATA_IRQ_PIN) {
         
    
            ex_data_event_t evt;
            //fill in data evt with current ticks;
            evt.cur_ticks = app_timer_cnt_get();
            ....
            app_sched_event_put(&evt, sizeof(evt), data_event_dispatch);
    
        }
        
    }

    and then in scheduler event handler, calculate the delay,

    void data_event_dispatch(void *p_event_data, uint16_t event_size) {
        ex_data_event_t* p_evt = (ex_data_event_t*)p_event_data;
        ...
        case EXT_DATA_OPS_TYPE_IRQ:
            {
                //calc delay;
                uint32_t cur_ticks = app_timer_cnt_get();
                uint32_t elapsed = cur_ticks - p_evt->cur_ticks;
                float ms = elapsed / 32.768;
                NRFX_LOG_DEBUG("\t call IRQ handler....after "NRF_LOG_FLOAT_MARKER, NRF_LOG_FLOAT(ms));    
            }
            break;
        ...
    
    }

    The printed result varies between 1~2ms.

    Today I did more tests, basically disabled any irrelevant things, like timers, ble activities, other GPIOTE channels, but the result just remains the same :-(

    Any other thing I can try?

  • rolandash said:
    Any other thing I can try?

    I don't see why you get such a large number this way, but anyway, the LFCLK is very slow compared to the CPU clock, so you will not get an accurate measurement this way. Can you try simply toggling a GPIO in gpiote_irq_handler() and data_event_dispatch() and measure the time using a logic analyzer or an oscilloscope? That would give you a definitive answer about the time, removing any doubt about how it is measured.

  • Hi,

    As you suggested, I took some screenshots from a oscilloscope, toggling a GPIO pin.

    First one is taken when nrf_log is on (I use deferred log)

    Fig. 1

    Second one is taken when nrf_log is totally disabled. 

    Fig. 3

    As you can see when log is on, the delay is between 500us ~ 2.5ms,

    and when log is off, the delay is ~ 4us.

    I have to say that this result surprised me, as I did not expect logging can make such big difference, even in deferred mode. Is it normal? or did I miss some configuration to make it correct?

  • Maybe not directly relevant, but have a look at this nrf_log_frontend_dequeue-must-be-atomically-protected-against-re-entry-from-interrupt-context issue, where I just posted some code following the suggestions by the reporter

Related