What causes a 500Hz mouse to sometimes report at 250Hz or 125 Hz?

[MIETAS]

Now i am just super curious what is the cause of this and if its a normal behavior.
Nonetheless this is wholesome work, thank you for doing this.

[TooManyPixels]

Tonight (over the past 3-4 hours) I rigged-up my Windows 7 laptop from 2010, which has only USB 2.0 ports and (after much fiddling with xperf and logman) I was able to repeat the combined ETW and hardware USB trace as on my other affected machines. Remember that this laptop does not exhibit the temperamental "floaty" mouse problem...

...and the ETW trace of USB URB completions shows the exact same 2ms gaps between groups of 9 events.

That is not what I wanted to see. This tells me that I'm likely chasing a red-herring - or (hopefully!) this indicates problems with my testing methodology which I hope I'll be able to identify and resolve. I'm hoping it's something as simple (and stupid) as me using the wrong sleep/wait technique in my Arduino code.

I'm still convinced that the actual problem ("floaty" cursors) can be quantified using these low-level traces - and by consistently reproducing the same inputs and comparing the actual cursor movements on-screen I'll be able to understand why it "feels" different.

Below is a screenshot of the ETW trace in Windows 7's WPA, showing the same 1ms+2ms gaps between reports.

WPA screenshot showing 2ms gaps argh - 2.png (73.04 KiB) Viewed 5072 times

----

I"m going to sleep-on-it for a while. I'm kinda bummed-out right now.

[TooManyPixels]

I just quickly checked my Arduino program (which I haven't touched in over a month) and I think I see the problem...

...I was using

Code: Select all

delay(1);

to wait 1ms between outbound HID reports - which is a blocking call (which is a problem anyway), but the real bug/issue/flaw here is that Arduino's `delay(ms)` function always waits for at least a `ceil`-number of integral milliseconds (so `delay(1)` will return after either ~1.0ms or ~2.0ms - but not ~0.9ms (or less) or even ~1.1ms, which I think explains what is observed in my USB traces involving the Arduino.

...so this is embarrassing

------

When I next feel like it, I'll update the Arduino program to cooperatively yield, instead of blocking, and to use the higher-precision `micros()` timer, which should solve this SOF problem.

However this does not explain why the same +1ms delay issue is sometimes observed with my real mice, not just my Arduino mouse-emulator - so I there's still reason to believe something's going on in USB-land.

Today I also learned how much more anemic the ETW story is on Windows 7 - apparently it wasn't until the 2018 release of Windows 10 that ETW could trace Win32/User32 window-messages (like WM_INPUT), which makes me wonder how people did any kind of userland causality analysis back in the day.

[F1zus]

I would like to know what happens after switching the mouse dpi via a button.
I switch the DPI several times (press the button 3 times) and go back to my DPI (1600), but my mouse becomes much more responsive. It's like she's coming out of sleep mode. It's as if the processor state switches from c3 to c0. But c-state is turned off, the processor is overclocked and the frequency is fixed.
This happens on any mouse (razer, logi, zowie), on any cpu/gpu/mobo, on any Windows.
This happened even on an Android TV set-top box (it has a Snapdragon mobile processor installed).
PS:
Many people notice this, I even created a topic on this forum.
viewtopic.php?f=10&t=11370&p=92730#p92730

[TooManyPixels]

I would like to know what happens after switching the mouse dpi via a button.

Great idea!

I'm currently having trouble getting my (brand new...) Logitech G502 X to consistently switch between its DPI settings, and when using the Logitech OMM (Onboard Memory Manager) program it doesn't seem to have any effect (as-in, my mouse pointer movement felt roughly the same even when I set it to 400dpi vs. 3200dpi).

But even-so, I did do a software-only (ETW) trace of kernel and user-mode events and looked at the data in-detail and again, saw no difference when I moved my mouse sufficiently fast over my mousepad (just moving it back-and-forth rapidly about 3-4cm total displacement)

400dpi on the left, 3200dpi on the right:

400dpi vs 3200dpi.png (588.71 KiB) Viewed 4833 times

Ultimately, the data/information in the screenshot above isn't particularly interesting from a troubleshooting perspective, all it does is confirm that (my mouse, at least) will report at 1000Hz at both 400dpi and 3200dpi - which is what I expected.

I haven't looked at this in detail too much, and ETW/software traces are heavily dependent on the the system's own timekeeping so this data alone won't be too useful without an independent timing source (such as the one used by a hardware USB trace from my Beagle), and the USB events don't seem to include any of the raw HID report data (despite using the "FullDataBusTrace" keyword) so I can't see the raw traffic (which is what we both wanted to see, sorry!).

But don't worry, I will repeat a comparison of different DPI settings (and with a hardware USB trace) once I've resolved the other known problems with my data-collection methodology.

----

What is interesting is that the traces show there's some disk activity happening with each mouse event - but it could be because I was recording the trace to-disk (rather than keeping it in-memory). Also, after I made the traces I learned that I need to use a different trace-provider to get CPU power information (i.e. C-states, etc) so I'll include that next time.

The unsettling things about this whole adventure is that the more I learn (about how USB, Windows, profiling, and computer hardware in general) the more uncertainty and questions I have, instead of answers, argh

[F1zus]

I would like to know what happens after switching the mouse dpi via a button.

Great idea!

To be honest, I didn’t quite understand what was happening. Judging by the graph, they are approximately the same.
I would be interested in what happens to the system when the DPI is switched.
I tried to analyze it myself and all I noticed was that the Windows system timer sometimes changed (which is 15.6ms by default, and 1ms in games). So, after pressing the DPI button, the timer increased and then decreased.
But I don't think this is related to the processor or video card. This is due to the mouse or mobo itself.
Perhaps power saving is disabled in the mouse or it is happening in the motherboard chipset. It's a difficult question.
But the fact is that my mouse became much more responsive after a few presses of the DPI button.

[TooManyPixels]

Some real progress this time: I was able to confirm the 2ms gaps in the traces (and the extra SOF packets in the USB trace) were caused by that timing bug in my Ardunino program - I rewrote it to use near-microsecond-level timers without any snapping to the nearest milisecond (nor USB microframe) and now the ETW trace shows consistent 1ms between updates.

Screenshot proof: no more gaps or grouping of events.

2023-11-14 - woo smooth no clumping - so now we can quantify the floaty feeling.png (1.06 MiB) Viewed 3509 times

---

Now I'll need to simply gather more data and compare the exact differences between raw HID input values (which can now be consistently replayed), the resultant Win32 WM_INPUT messages (which should be 1:1 with the HID reports), and then finding out why the same inputs result in very different mouse movement behaviour based on how much my computer dislikes me today.

-----

I've been following the thread about the Intel NVMe storage driver - because that might be a possible cause for me: all of my computers do have some form of NVMe storage (though my first affected computer had an Intel Optane PCIe card for storage, which I don't think uses NVMe interfaces even though it goes through PCIe?)

[masneb]

This is caused by a update to the USB stack this summer in W11, where they enabled USB polling coalescing in addition to preventing background apps from trying to query the mouse when they don't have priority. Packets will show up as a lower polling rate because they're coming in less frequently, but contain multiple polls. Usually it'll show up as 125hz.

Basically they're cheating at polling to reduce overhead of high frequency mice. Some programs will show the packet rate and others will show the 'unpackaged' rate, some go back and forth between the two depending on how fast you move your mouse. Just the poor state peripheral monitoring tools are in. 125ms click delay would be noticeable, so not sure exactly how they're doing it.

One of the reasons I haven't updated to the May update and rolled back after installing it as it felt worse to me.

viewtopic.php?f=10&t=12157

[TooManyPixels]

This is caused by a update to the USB stack this summer in W11

I've been having this issue since October 2019 on Windows 10.

, where they enabled USB polling coalescing in addition to preventing background apps from trying to query the mouse when they don't have priority. Packets will show up as a lower polling rate because they're coming in less frequently, but contain multiple polls. Usually it'll show up as 125hz.

Basically they're cheating at polling to reduce overhead of high frequency mice. Some programs will show the packet rate and others will show the 'unpackaged' rate, some go back and forth between the two depending on how fast you move your mouse. Just the poor state peripheral monitoring tools are in. 125ms click delay would be noticeable, so not sure exactly how they're doing it.

One of the reasons I haven't updated to the May update and rolled back after installing it as it felt worse to me.

viewtopic.php?f=10&t=12157

None of that applies to anything in this thread. And all of my screenshots show that I'm on Windows 10.

[TooManyPixels]

I don't have any real announcement to make yet, but I just wanted to share some observations I've made from my data, which includes a bunch of suspect possibilities I've eliminated so-far:

• There is no evidence of USB HID reports being dropped, i.e. all my traces indicate every HID report is eventually received as a WM_INPUT message in my Win32 Raw Input hWnd. So that's a relief.
• There is no evidence of Windows coalescing any mouse movement either.
• There is no evidence suggesting XHCI interrupt moderation is involved either (this was an early hunch of mine, as fiddling with XHCI interrupt moderation registers does cause similar "floaty" or imprecise mouse behaviour, however the Windows USB stack ETW traces show a 1:1 mapping from my replayed IN packets to ISR execution in Windows.
• On the "bad days" when my mouse is practically unusable for any high-precision task I've noticed that Windows' kernel scheduler runs CSRSS's thread (the one that handles mouse pointer events) on higher CPU Core numbers than usual (e.g. Core 6 instead of Core 0) - (but this isn't universally true, so this might be a red-herring, or (I hope!) a proxy for something else being askew).
• There is no evidence that any userland systemwide timer settings have any effect.
• Windows' own interrupt latency timer measurements (which are reported in undocumented ETW Tracelogging events in Win32k-Base-Input that I was able to subscribe to) don't show unusually high values here, so hopefully no-one will mention "DPC latency!" again in this thread, at least without hard numbers.
• There were times when using the DPI switch on my Logitech mice had no effect at all and I thought that might be related, but after looking at my USB traces it seems my mouse was stuck in HID "Boot mode", which is something I'll need to keep in-mind in future)

I'm still disappointed that I haven't actually quantified the problem yet (though that depends on getting more good data from unaffected machines so I can do a comparative-analysis) - because once I can describe the problem with numbers it becomes a testable problem - and it becomes far easier to isolate potential causes simply by using a good profiler tool).