winebus.sys: Device reports coming in too fast, last report not read yet
Hello! I'm currently exploring the massive amounts of the following error messages I see when using my xbox controller: 002b:err:hid_report:process_hid_report Device reports coming in too fast, last report not read yet! 002b:err:hid_report:process_hid_report Device reports coming in too fast, last report not read yet! 002b:err:hid_report:process_hid_report Device reports coming in too fast, last report not read yet! [...] The code that generates this looks a bit problematic to me. First, it's definitely loosing HID reports here. I wonder if this also explains why my controller rarely sees missing button presses. But the issue seen here seems to mostly result from the controller generating lots and lots of axis events. So my first thought was: Hey, if there's a buffer overrun issue then why not just replace axis reports in the buffer with the most current report for the same axes so we do not easily overwrite button reports. But looking at the code I found that there is no buffering at all. It just unconditionally overwrites the last report (writing that error message if that report was not read yet), and then continues to a while loop I do not understand at all. @@@ void process_hid_report(DEVICE_OBJECT *device, BYTE *report, DWORD length)
if (!ext->last_report_read) ERR_(hid_report)("Device reports coming in too fast, last report not read yet!\n");
memcpy(ext->last_report, report, length); ext->last_report_size = length; ext->last_report_read = FALSE;
while ((entry = RemoveHeadList(&ext->irp_queue)) != &ext->irp_queue) { IO_STACK_LOCATION *irpsp; TRACE_(hid_report)("Processing Request\n"); irp = CONTAINING_RECORD(entry, IRP, Tail.Overlay.s.ListEntry); irpsp = IoGetCurrentIrpStackLocation(irp); irp->IoStatus.u.Status = deliver_last_report(ext, irpsp->Parameters.DeviceIoControl.OutputBufferLength, irp->UserBuffer, &irp->IoStatus.Information); ext->last_report_read = TRUE; IoCompleteRequest(irp, IO_NO_INCREMENT); }
Why doesn't the while loop run before replacing the last report so it has a chance to deliver the buffered report before overwriting it? Of course the while loop would still be needed after replacing the report so it would make sense to put it into a helper. Second, I also wonder: Doesn't the while loop potentially run more than one loop? Wouldn't it then deliver just the same last report multiple times? Where is the point in this? This would also conflict with my idea of trying to deliver the last report again before replacing it, doesn't it? What's the IRP queue anyway? Is it part of a consumer or producer? Thus, my current understanding it that first, it looses reports, and second, it duplicates reports if it lost some before. I see that process_hid_report() is called from the lower SDL layers in my case. Does it make sense to handle buffering there? Apparently, process_hid_report() doesn't return a result, so there's no feedback whether the HID report could deliver the report or not. Would it make sense to return the result of ext->last_report_read? That way, the SDL layer could buffer the report itself and maybe implement some logic to reduce the amount of axis reports generated. For axis reports from the joysticks, it doesn't matter if we overwrite reports as axis position is reported as an absolute value. So we could keep one buffer per axis and keep track of whether it was delivered or not, then retry next time. But this should probably go into some thread which keeps on trying to process such buffered hid reports. Thanks, Kai
Hello! Thank you very much for doing this analysis and really showing interest here. Most of that code is my work and I am happy to discuss my design decisions and help improving things is always greatly welcome! On 7/7/18 4:35 PM, Kai Krakow wrote:
Hello!
I'm currently exploring the massive amounts of the following error messages I see when using my xbox controller:
002b:err:hid_report:process_hid_report Device reports coming in too fast, last report not read yet! 002b:err:hid_report:process_hid_report Device reports coming in too fast, last report not read yet! 002b:err:hid_report:process_hid_report Device reports coming in too fast, last report not read yet! [...]
The code that generates this looks a bit problematic to me.
Yes it is a touch. But again it is pretty new so improvements are likely. I also apologize if my memory is rusty. Much of this code was done by me in 2016 and memory has dulled over the years. But I am very excited that someone is paying attention and things can move there.
First, it's definitely loosing HID reports here. I wonder if this also explains why my controller rarely sees missing button presses. But the issue seen here seems to mostly result from the controller generating lots and lots of axis events.
So my first thought was: Hey, if there's a buffer overrun issue then why not just replace axis reports in the buffer with the most current report for the same axes so we do not easily overwrite button reports. But looking at the code I found that there is no buffering at all. It just unconditionally overwrites the last report (writing that error message if that report was not read yet), and then continues to a while loop I do not understand at all.
So part of this is the concept of the driver stack. I am attaching a slide from a presentation I did several years ago that shows a simplified work flow for device reports. (Here is the whole slide deck from that presentation https://wiki.winehq.org/images/1/16/Wineconf-hid-2016.pdf) I have highlighted where I think the point of pain is, the trick is that in winebus we are single threaded and the goal was to get the reports into the report ring buffer as quickly as possible. We are in a callback from the device system, and clearly multiple callbacks can occur while we are still handling the first. I know I debated adding a queue there, but I read a few places on the Web that there is not a queue there on windows, and I worried that with a queue if you are getting into the case where reports are being generated faster than read, then under constant use your controller would start to drift from what you where doing. You would get progressive lag. So just arbitrarily, and because I was already doing so much work in so many other areas for simplicity, I opted to not have a queue there and instead drop messages. This worked for most of my logitech pads here as they don't have as fast of a sample rate. But the XBOX controller has a much faster sample rate and I can see that here also. I wondered if it would be an issue or not, but you are the first report that it is that I have heard. So I do not know what would be better.
@@@ void process_hid_report(DEVICE_OBJECT *device, BYTE *report, DWORD length)
if (!ext->last_report_read) ERR_(hid_report)("Device reports coming in too fast, last report not read yet!\n");
memcpy(ext->last_report, report, length); ext->last_report_size = length; ext->last_report_read = FALSE;
while ((entry = RemoveHeadList(&ext->irp_queue)) != &ext->irp_queue) { IO_STACK_LOCATION *irpsp; TRACE_(hid_report)("Processing Request\n"); irp = CONTAINING_RECORD(entry, IRP, Tail.Overlay.s.ListEntry); irpsp = IoGetCurrentIrpStackLocation(irp); irp->IoStatus.u.Status = deliver_last_report(ext, irpsp->Parameters.DeviceIoControl.OutputBufferLength, irp->UserBuffer, &irp->IoStatus.Information); ext->last_report_read = TRUE; IoCompleteRequest(irp, IO_NO_INCREMENT); }
Why doesn't the while loop run before replacing the last report so it has a chance to deliver the buffered report before overwriting it? Of course the while loop would still be needed after replacing the report so it would make sense to put it into a helper.
If I recall it is because IoCompleteRequest is where a bulk of the work is done and we need to make it so that our report buffer is not written out from under us. Thus a queue or something would work well if we go that route.
Second, I also wonder: Doesn't the while loop potentially run more than one loop? Wouldn't it then deliver just the same last report multiple times? Where is the point in this? This would also conflict with my idea of trying to deliver the last report again before replacing it, doesn't it? What's the IRP queue anyway? Is it part of a consumer or producer?
What there is is that the irp_queue are the read requests coming in from the drivers above this on in the stack. Right now there is likely only 1, however because of the driver architecture there could me more than 1 upper level driver with IRP requests into this driver wanting to read the device state. Each of those IRPs are blocked waiting on data, and they are unblocked here. The way the driver stack works is that is is not a deliver up, it is a read down. So driver above on the stack read data and if there is not data to read they block waiting for data to become available.
Thus, my current understanding it that first, it loozses reports, and second, it duplicates reports if it lost some before.
I see that process_hid_report() is called from the lower SDL layers in my case. Does it make sense to handle buffering there? Apparently, process_hid_report() doesn't return a result, so there's no feedback whether the HID report could deliver the report or not. Would it make sense to return the result of ext->last_report_read? That way, the SDL layer could buffer the report itself and maybe implement some logic to reduce the amount of axis reports generated. For axis reports from the joysticks, it doesn't matter if we overwrite reports as axis position is reported as an absolute value. So we could keep one buffer per axis and keep track of whether it was delivered or not, then retry next time. But this should probably go into some thread which keeps on trying to process such buffered hid reports.
There are likely many good ways to do that. If you are interesting in exploring this work then that would be great! I am sure I did not answer questions quite well enough, this whole driver stack thing is pretty complicated. But I am happy to help! -aric
participants (2)
-
Aric Stewart -
Kai Krakow