Zephyr: USB HID mouse sample high input delay

[mschwan-phytec]

Describe the bug
Using the USB HID mouse sample there is some significant input delay. The delay between an input (button press on HID) and the actual output on a computer screen is roughly 60 - 90 ms, which seems quite high.

For measuring the delay I used a regular camera and counted the frames between the LED toggling (indicating a button press) and the output on the computer screen. With a 30 fps video there is about 2 - 3 frames delay.

This is with a USB polling interval CONFIG_USB_HID_POLL_INTERVAL_MS=9 (the default). Setting a polling interval of 1 ms slightly reduced the delay (as expected), but does not seem to be the actual issue here.

Additionally I did some reaction tests using my regular mouse (Logitech MX518, polling rate 125 Hz) and a reel board (polling rate 125 Hz and 1000 Hz). With 20 samples I got the following results:

• Logitech MX518 (125 Hz): 254 ms
• reel board (1000 Hz): 305 ms

To Reproduce
Steps to reproduce the behavior:

1. cd samples/subsys/usb/hid-mouse/
2. west build -b reel_board
3. west flash
4. Connect USB device port to a computer
5. Measure delay between button pressed (LED toggles) and actual output on computer screen using a camera and counting the frames

Expected behavior
The expected input delay of USB HID devices should be in the range of 10 - 40 ms (also depending on the polling rate).

Environment:

• OS: Archlinux with Kernel 5.6.10
• Toolchain: Zephyr SDK 0.11.2
• Zephyr master b78c9dca52c506af3446c0dd3025ac0c9f6dcea2

[carlescufi]

@pdunaj could you please comment on this issue?

[pdunaj]

@carlescufi The hid-mouse sample is actually very simple. There is nothing suspicious there that would delay the transfer this much.

@mschwan-phytec I suspect there is a problem with how you measure the delay. LED will change almost instantly after the report is send to the USB. On the other hand there will be a significant processing delay on the host. You need to take into account the frame rendering and presentation process. You will loose 3 frames (I expect there is triple buffering) on the GPU plus I expect 1 more frame on the monitor. That should be 4 frames in total. If your monitor rate is 60 Hz that will give you 66 ms delay. With 5 frames delay you would get 83 ms. So what you observe is about right.
Unless you wish to use high end monitor and GPU for the HID tests, I suggest routing raw USB input to the GPIO on some simple Linux board. You will get better result of what you actually try to profile.

Even if you have a high end monitor you will measure the monitor delay in your test. Note that in this sample LED toggles after the data is given to the USB. Normally you have a sensor delay in mouse which adds a lag. Check the video below. These guys use 240 Hz monitor. 4 frames delay gives in this case around 16ms presentation delay. Add a 1 ms delay on the mice they measure and they get 17 ms overall delay. In their test only the normal desktop mouse has a lag of additional 17 ms, which I expect comes mostly from sensor wake up.
https://youtu.be/orhb7Njj3h8?t=510

Zephyr is capable of reaching the 1 ms polling interval on the USB. We use it and we also sync sensor reading to the transfer speed so we would instantly notice any unusually high delay.
You can play with our mouse ref design BTW. There is a configuration for a Nordic's DK.
https://github.com/NordicPlayground/fw-nrfconnect-nrf/tree/master/applications/nrf_desktop

[mschwan-phytec]

@pdunaj Thanks for the feedback! I am fully aware of the implications you explained. That is why I did some testing with the reaction time to show that there may be still some delay. But things are not as easy as it seems. At first I thought the button of the eval board may not allow for such fast presses as a light mouse button does. Luckily, I had an old disassembled MX518 lying around that I could use the case and hook up a switch to the nrf52840 eval board to eliminate the factor of different buttons and pressing speed. And this reduced the delay in a reaction test a little bit. But the numbers are quite inconsistent (sometimes shorter, sometimes longer delay) and I still cannot reach the times I achieved with an MX518. This is all using the sample that comes with Zephyr.

I did not test the sample from nrf_desktop yet, but will do so as soon as possible, and report back then.

[pdunaj]

Hi @mschwan-phytec , it's really hard for me to tell what is wrong (if anything). I don't work with Zephyr samples. I can have a quick look there to make sure it works as intended.

So far I have not seen any problems with USB regarding the polling rate. It would be very important for us to know if there are any. With nrf_desktop we use 1 ms polling interval on the USB. When data is out we start sampling the sensor. On the rate measuring tool we get 1000 reports per second. That would be impossible to achieve if there would be any delay with delivery. We also use our profiler to see how application events propagate. Everything is according to the expectations. I can set the polling interval to the default value and check if anything changes.

[MarekPieta]

Hi @mschwan-phytec. @pdunaj

I measured delay from HID report sent on nrf_desktop device (int_in_ready callback from struct hid_ops for registered Zephyr USB HID device) to receiving HID data on the host (using Raspberry Pi as host).
nrf_desktop device toggled GPIO pin on callback, Raspberry Pi toggled GPIO pin when receiving raw HID report. I opened hidraw0 device and I read it in a loop. I read raw HID data to make sure that processing delay on host will not affect the measurements.
Then, using logic analyzer, I looked at time intervals between edges of signals generated by Zephyr USB device and Raspberry Pi to measure the delay. I don’t see any significant delay between the signals, I think everything looks fine (the delay was way lower than 1ms).

During the test I used nrf_desktop device with 1ms polling interval. I can make the same test with
Zephyr sample and polling interval selected by you to make sure it will also work fine (I will add GPIO debug in similar way as for nrf_desktop application).

[pdunaj]

Thanks @MarekPieta .
Just for the record, the delay measured was below 200 us. And I bet this is mostly the propagation time from kernel to user land on the host.

[pdunaj]

Hi @mschwan-phytec , I don't think there is anything wrong in the driver. The delays indicated in the description can be explained with the measurement method used. Checking the delay using logic analyzer shows driver does not stall the data anywhere (as expected as there is no space where it could stall it). If it is stalled somewhere by your host it's hard to tell but I recommend using the GPIO for testing the latency.
The nrf_desktop app is using the same subsystem and driver as the sample. We are not responsible for this sample so it won't be checked by us but there is no reason to suspect that it should behave differently.
BTW - usb mouse sample does not handle errors on ep write (when driver is busy), which can lead to blink done without report being sent. There is also no synchronization between thread and interrupts. I don't think this causes the problem you see but I write it for the record.

[pdunaj]

Hi @carlescufi , I am unassigning myself as there is nothing else we can say. I am leaving the ticket open in case @jfischer-phytec-iot would like to add any comment.

[jfischer-no]

@pdunaj @MarekPieta Thanks for explanation and testing

[mschwan-phytec]

Thanks for the explanation and thorough testing. I guess then my testing method really seems to be flawed.

[carlescufi]

Hi @carlescufi , I am unassigning myself as there is nothing else we can say. I am leaving the ticket open in case @jfischer-phytec-iot would like to add any comment.

Of course. Thank you very much for all your input @pdunaj