USB IRQ Latency

[Vagner Landskron]

Hello,

We're working with nRF52833 & nRF52840 and I'm trying to figure out why we've ~0.3ms IRQ Latency from the moment I call the function "uart_irq_tx_enable(dev);" until I actually get to the callback I've registered at "uart_irq_callback_set".

To be honest, I see no reason for this latency to not be close to zero.

Here a diagram that tries to explain our benchmark timeline. I'm trying to understand from where the red bar (IRQ Latency) comes and how to reduce it. 

Note: communication between "HOST" and "nRF528xx Dongle" is via USB, "nRF528xx Dongle" and ""ITU nRF528xx" is wifi (ESB).

Thanks in advance!

[Håkon Alseth]

Hi,

 

It is submitting an item to the workqueue, and then calling the callback function:

https://github.com/nrfconnect/sdk-zephyr/blob/v3.0.99-ncs1/subsys/usb/device/class/cdc_acm.c#L553

Depending on what else is happening in your system, it will take a bit of time for switching context.

What is the accuracy of your timing diagram? It is a bit hard to understand your graphs directly.

 

Kind regards,

Håkon

[Vagner Landskron]

Hi Hakon, thanks for your reply.

Oh, I see it now. Is there a way to increase priority or reduce this latency somehow?

The units are:

axis-Y (milliseconds)
axis-X (iterations)

For now, this latency is around ~0.3ms (measured by the board itself, so I could use higher resolutions).

[Håkon Alseth]

Hi,

 

Vagner Landskron said:

The units are:

axis-Y (milliseconds)
axis-X (iterations)

thank you for explaining. I see that its between 200 - 500 us, depending on the iteration, based on your graph.

It is a scheduled operation within the kernel, where it executes based on what else is running in your application, it will take a bit of time.

 

Do you see the same timing if you run the zephyr/samples/subsys/usb/cdc_acm example as well? I see a delay of approx. 28 us when setting a GPIO, calling uart_irq_tx_enable(), then clearing it again in the handler.

 

Kind regards,

Håkon

[Vagner Landskron]

Interesting, I'm also getting ~30us using cdc_acm example.

What is different in my scenario (which takes ~300us) is that the interruption is "enabled" in the end of an esb callback (set in esb_config.event_handler at "esb_init()").

So it seems that as you stated, the scheduler is busy on something else right after it exits this callback function.

(pseudo) Code:

void event_handler(struct esb_evt const *event)
{
	switch (event->evt_id) {
	case ESB_EVENT_TX_SUCCESS:
	    // ...
		break;
	case ESB_EVENT_TX_FAILED:
	    // ...
		break;
	case ESB_EVENT_RX_RECEIVED:
		// ...
		break;
	}
	startMeasurement = Timestamp_us();
	uart_irq_tx_enable(dev);
	(void)uart_fifo_fill(dev, " ", 1);
}

// ...

static void serial_interrupt_handler(const struct device *dev, void *user_data)
{	
	// ...
	if (uart_irq_tx_ready(dev)) 
	{
		long long now = Timestamp_us();
	    serial_response_offset += sprintf(&serial_response[serial_response_offset], 
    		", t_irq: %llu###",
    		(now - startMeasurement)
    		);			
		(void)uart_fifo_fill(dev, serial_response, serial_response_offset);
		serial_response[serial_response_offset] = 0;
		serial_response_offset = 0;
		// mark we've concluded the sending, otherwise it will remain stuck here
		uart_irq_tx_disable(dev);		
	}
    // ...
}

This is the scenario's big picture (I've omitted the details).

Let me know if there is some trick to increase the UART priority.

[Håkon Alseth]

The ESB event handler is running in an interrupt context, which will block the cdc_acm event until you leave the function.

Re-schedule the logic to run in thread priority instead of directly in the ESB event handler.

 

Kind regards,

Håkon