Lag in RPi reading HID

[Renate]

I'm probably lacking some important understanding here, so correct me where I'm wrong, please.

I've done a bunch of HIDs using ATMega32u4 and they all work fine on Windows and Android.
My latest HID input device is generating 11 bytes of status on 1, 10, or 20 bIntervals interrupts (I've tried them all separately).
Reading the device on Windows happens instantaneously.
(OTOH, I only ever get 11 bytes per synchronous read no matter how big the buffer is and how long a user polling interval, a separate question.)
On the Raspberry Pi a read is usually <10 ms but about 10% of the time it is a random time less than 1 second.
Running "time" on a program that does open, read, close always shows negligible user and kernel time and up to 1 second real time.
It's always the first open/read/close in a while that gives a problem.
That is, wait 10 seconds, hit it, it could be slow.
Get past this point and hammer it repeatedly (with a new executable) and it responds quickly.
Switching to the newer quad core RPi gives the exact same performance.
It is always the read function call, not the open or close that is taking all this time.
What's going on here?

Edit: Hmm, could this be related to different implementations/interpretations of GET_IDLE/SET_IDLE?
I'm not doing anything with these, I believe that I am STALL-ing.

[Jan Axelson]

If the device returns STALL in response to Set Idle, the device should send data always regardless of whether it's changed.

Is there a reason why you need to open and close a handle repeatedly? Why not leave the handle open?

[Renate]

Why not leave the handle open?

Well, I could, of course.
I'm just saying that the simple test is an open/read/close in a simple program in a shell.
There never is any delay in returning from the open call, just a delay from the read call.
I will try a single open then a loop with random delays and reads to see if I can narrow this down.

[Jan Axelson]

A protocol analyzer will show if the host is requesting data and the device is returning NAK, or if the host is delaying in starting to send IN token packets though it sounds like it's the latter.

If the delay is only on startup and doesn't impact the use of the device, I wouldn't worry about it.

Windows doesn't make any guarantees about how long it will take to get started, only how often it will poll once it gets going.

[Renate]

I use Snoopy on Windows and the data comes pouring through continuously.
It's just that I don't know anything for Raspbian on the RPi and I'm not particularly using a GUI on that.
I'll try the above mentioned experiment later.

[Renate]

(Ok, let's try this the right way now. This was posted earlier with a few inaccuracies.)

Well, I have a real mystery here.
The performance delay is on the first read after opening the /dev/hidraw2

I wrote a short program in C. Here's the pseudo-code:

Code: [Select]

for(;;)
{
   delay a random amount of microseconds between 0 and about 4 seconds
   open hidraw
   get start time
   read hidraw
   get stop time
   close hidraw
}
You'd probably expect some sort of random small values, right?
This is the plot of looping 1000 times.
The X axis is the amount of time delay between the last closing of the hidraw and the next opening.
The Y axis is how long just the read call takes to complete.

http://i.imgur.com/6D7pJB9.png

This seems to me to be something sloppy in the RPi Raspbian kernel.

[Jan Axelson]

So if the delay is between 1 and 2 seconds or between 3 and 4 seconds, there is a larger delay, with the greatest delays at 1 and 3 seconds and decreasing delays for 1 second after those numbers? With quick response after delays of 0-1, 2-3, or 4-5 seconds? Or am I reading the graph wrong?

There is still a question of whether the host is delaying in sending IN token packets or whether the device is delaying in sending data in response to received token packets.

[Renate]

Yes, the graph verifies what I have been experiencing.
1/2 the time you get instantaneous response.
1/2 the time you get delays of up to slightly over one second.
dmesg does not report anything unusual.

I don't have any tools for snooping on the RPi.
Do you have any suggestions for a command line tool?
All I can say is that I get the same results for a write instead of a read.

I extended this out to 20 seconds and the pattern repeats itself.
15.571 delay gives 0.814 read.
16.706 delay gives 0.001 read.
I wrote a model for this periodic ramp and it always agrees within a millisecond or so to the observed.
The actual periodicity is 2.048 seconds, definitely not 2.000 seconds.
I hope that this number will tell somebody exactly what is going on.

Yes, I could write a server to keep the HID open.
It just seemed easier to open/read/close it as needed instead.
In any case there really appears to be something strange going on here.

[Jan Axelson]

For any device, not just this one, I would leave the handle open unless there is a compelling reason not to.