GPIOTE High-accuracy interrupt latency

[erik_fw]

Hello,

Our product is configured to use 3 total GPIOTE channels –– 2 sensors configured for "high accuracy" GPIOTE events, each around 10Hz refresh rate, and 1 using "low accuracy" at 1Hz rate. In our interrupt handlers for each respective sensor, we're simply setting a (volatile) data-ready flag.

We've been finding that, sporadically, we seem to be "missing" some of these interrupts. They are more heavily correlated during periods of BLE activity (which is about once per hour), but also happens even when BLE isn't active for minutes before or after. This can be broken into two main issues:

1. Latency between sensor pin being set and seeing our data ready flag get raised. As in, when we check the GPIO level for each of these sensors to test for this, we will sometimes find that the sensor's interrupt pin is set, but our data ready flag has not been set yet, meaning that somehow we are still executing non-interrupt application code in between the sensor raising its interrupt pin and the GPIOTE IRQ handler going off. Usually, the interrupt will still go off and our data ready flag  will still be set, but only after a few more lines of application code are run. Is this expected in any known scenarios? 

2. Interrupts missed completely, as in the IRQ handler for the given sensor will never actually be called as a result of the sensor interrupt pin being raised. In these instances, the sensor won't clear its interrupt pin until we retrieve data from the sensor, but since the IRQ didn't go off, we would be going an indefinite amount of time without getting sensor data if we didn't add safeguards to detect these "missed" interrupts. This happens with both the "high accuracy" and "low accuracy" GPIOTE configurations.

I've looked through the NRF52's relevant documentation to try to address these issues but haven't been able to find anything that would explain why we would be seeing the above issues. 

[Vidar Berg]

Hi,

Just to make sure, do you have separate 'data ready' flag for each input? The IRQs are not particularly high in frequency so I wouldn't expect it to be a problem with the Softdevice. It also sounds like your ISRs are kept short, so that helps as well. 

1. The GPIOTE IRQ will get blocked by the Softdevice interrupts from time to time, and I think it explains why the update of the flag gets delayed sometimes.  But the delay should only be in the micro-second range as long as you're not erasing flash pages. Are you doing any flash operations when this happens? Softdevice execution times inside ISRs are documented here: Bluetooth Low Energy processor usage patterns 

2. IRQs should become pending while blocked by other higher priority IRQs and should not become lost. Could it be possible that the GPIOTE IRQ gets processed but that there some race condition that causes the program to not properly de-assert the sensor IRQ line afterward? Do you have a way to verify that the GPIOTE IRQ is not triggered when the IRQ lines go from low to high?

Best regards,

Vidar 

[erik_fw]

Thank you for the response.

1. The issue isn't a matter of latency in terms of time but rather the fact that our own non-interrupt application code is running between polling the GPIO and seeing the ISR get triggered. I'll paste some example code below to show what I'm trying to describe (no need to set private, this is pretty generic and rudimentary):

// Sensor interrupt callback functions
static void imu_data_ready()
{
    s_imu_data_ready = true;
}


...


// Check if interrupt pin is active

// Interrupt active for this sensor is low logic level, so negate result
interrupt_active = !(nrf_gpio_pin_read(ACCEL_DATA_READY_1_PIN));

if(interrupt_active && !s_imu_data_ready)
{
    interrupt_test = s_imu_data_ready;
    APP_ERROR_HANDLER(ERROR_IMU_INTERRUPT_MISSED);
    
    // Uses segger RTT to minimize effect on program execution
    // Tells us the status of data ready flag immediately after the conditional
    PRINTF_RTT("data ready flag %d\r\n", interrupt_test);
}

So the issue I'm describing is that we can get into this conditional and 'interrupt_test' will immediately tell us that data ready flag is now set to 1. In line 14 of this snipped we will see that the sensor's interrupt pin is active, but then in line 16 we will see that data_ready flag is still 0, meaning that the ISR hasn't run yet even though we see that the pin is high.

In every test so far, 'interrupt_test', which is assigned in line 18, will be populated with a 1 when we go to RTT print it, meaning that the ISR was executed between the execution of the conditional (line 16) and the 'interrupt_test' assignment.

This shows conclusively that between our polling of the GPIO and seeing the ISR go off, the conditional is still being executed.

Is there any debouncing / trigger window on the GPIOTE_IRQHandler that would prevent the IRQ from going off as soon as the logic level on that GPIO line changes to what the GPIOTE interrupt channel is expecting?

I understand that the processor will still execute its current operation when a hardware interrupt arrives asynchronously, but seeing a full conditional execute in between the logic level change and ISR execution seems bizarre to us. Is it possible that some optimization is combining those operations and that's why we're seeing this?

Any ideas are welcome and appreciated. As for the #2 issue, I will be doing more testing to bring you more information on that scenario and what we know so far. Thank you!

[Turbo J]

Is the s_imu_data_ready variable declared volatile?

[erik_fw]

Yes

[Vidar Berg]

Hi,

Is only one of the sensors that set the s_imu_data_ready flag? 

erik_fw said:

I understand that the processor will still execute its current operation when a hardware interrupt arrives asynchronously, but seeing a full conditional execute in between the logic level change and ISR execution seems bizarre to us.

Agree. CPU should stop execution and fetching of new instructions immediately after an interrupt has been triggered.  And it should only return to the main context when there are no pending interrupts left. This makes me think that either the IN event is not triggered or the s_imu_data_ready flag is cleared before it's read by the if statement.

I think a logic analyzer/scope could help us understand the problem better if that's an option in your case. If you have enough IOs available, you could use PPI and configure a GPIOTE output task to toggle the output when an IN occurs. That way you could verify the time it takes from the sensor IRQ line is pulled low to the GPIOTE IN event and possibly detect missed IRQs.    

  

[erik_fw]

Yes, only one sensor is setting that particular flag, the other sensors use their own flags. The flag is only cleared when we, in a different section of code, check the flag and retrieve data from the sensor if it is set. 

Great point about using a logic analyzer to measure the latency, we have a logic analyzer and haven't tried that yet. I'll try that out and come back with more information!

[Vidar Berg]

erik_fw said:

Yes, only one sensor is setting that particular flag, the other sensors use their own flags. The flag is only cleared when we, in a different section of code, check the flag and retrieve data from the sensor if it is set. 

 Thanks for confirming. But if readout of the sensor is delayed, is it then possible that imu_data_ready() might be called just before the flag is cleared? For debugging, would it make sense to add a check for s_imu_data_ready to see if it's indeed '0' when you enter imu_data_ready()?

[erik_fw]

For all 3 sensors, the interrupt pin stays active until we retrieve the frame of data from the sensor. So we should never be seeing two interrupt triggers occur before data is retrieved.

[Vidar Berg]

Ok, thanks. I think I have a better understanding of your code now. Hope a logic trace will give us some more clues. 

[erik_fw]

Hi Vidar,

I have some test results and was able to capture this issue occurring while recording with a logic analyzer, the results are attached below.

In the top row (DIO 1), a GPIO is being set during the ISR that sets our data ready flag.

In the middle row (DIO 0) is the sensor's interrupt pin (active low).

The bottom row (DIO 6) follows a GPIO that is being set on the first line inside this conditional where the sensor's interrupt pin is active but data ready flag hasn't been set yet.

The latency between interrupt pin being active and ISR executing doesn't look concerning, it's around 8μs on average which seems like what we should be expecting. 

Do you see anything concerning here or does it seem like this is just a natural case of the processor completing its pipelined instructions before executing the ISR that we are hitting by coincidence some small % of the time?

Thanks again!

[Vidar Berg]

Hi,

Thanks for the logic trace. It's interesting that the IRQ is asserted but the flag ist still read as zero afterward from main the context. The timing looks as expected at least.

I think you can test the theory related to pipelined instructions by placing instruction barriers (__ISB()) and maybe __MSB for good measure. 

By the way, are you testing with or without compiler optimization, and is link-time optimization enabled? And could you verify if s_imu_data_ready is loaded from RAM in the conditional check?