USB IRQ Latency

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!

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

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

  • 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

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

Children
  • 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:

    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.

  • 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