microsoft / busiotools

Tools for debugging and testing io buses for Windows
MIT License
192 stars 100 forks source link

How can I resolve Provider GUIDs and "<Unknown>" entries in BusesTrace.cmd's InputTrace.etl? (And how do I interpret the saved, but undocumented, events?) #113

Open daiplusplus opened 1 year ago

daiplusplus commented 1 year ago

(I am not a hardware developer, I'm using busiotools to investigate weird and sporadic mouse/pointer movement behaviour with USB mice on a couple of my computers - which started in Windows 10 1909 and still affects later Windows 10 builds on multiple machines of mine)

(With respect to the Microsoft Support Policy documented in this repo I have already opened a ($500..., ouch) support ticket with MS Support over this issue, but after months of them being unable to repro the issue at their end they told me to come up with hard, solid, ETL traces that show what I'm observing, so that's why I'm here).

I ran BusesTrace.cmd with the "Input/HID components only" menu option and WPA shows that the saved WPR_initiated_WprApp_InputTrace.etl contains the Microsoft.Windows.Win32kBase.Input/MousePacketLatency and Microsoft.Windows.Win32kBase.Input/MouseLatency events which (as far as I know) show that something ain't right with USB HID mice on my computer judging by the jittery CursorRenderLatency, ProcessMouseInputInputDataLatency, and CursorUpdateLatency field columns for MousePacketLatency events, and the TransferLatency and ProcessInputLatency columns for the MouseLatency events (screenshots below).

However, the saved *.etl file from BusesTrace.cmd is seemingly lacking a lot of human-readable information: only a couple of the named providers have their names resolved, the rest are referenced only by their GUIDs; none of the observed userland processes (as logged by other tracing providers that BusesTrace.cmd added) saved process names, for example; similarly, almost all other Task Names are missing too, so the WPA screen is filled with unhelpful Unknown and <Unknown> strings...

Furthermore, I noticed the MouseLatency and MousePacketLatency events from the Microsoft.Windows.Win32kBase.Input provider aren't documented anywhere (seriously: there are zero Google/Bing/DuckDuckGo search results for the string MousePacketLatency or any of the events' field names like ProcessMouseInputDataLatency), so I'm unsure how to proceed with the data I have from BusesTrace.cmd. I understand that for all kernel ETL events (such as those from Win32kBase) it's possible to capture stack-traces to help narrow-down the cause of certain events, but in this case the data needed for stack-walking isn't included in the ETL - do I need that data to investigate further and if so, how do I capture it? (I did try playing with xperf -on latency -stackwalk Profile but this doesn't play-nice with BusesTrace.cmd - I see that BusesTrace.cmd wraps logman but the whole xperf/logman/wpr/traceview/tracelog/perfview experience is very intimidating and frustrating for the uninitiated - (why so many tools that do the exact same thing?)).

...and as these event types and fields are undocumented how do I interpret it all? (e.g. is ProcessMouseInputDataLatency measured in microseconds or milliseconds or some other unit? How do I interpret the other fields? What is the difference between MousePacketLatency and MouseLatency? How do I combine this with the DWM's SetCursorPosition events in the same WPA timeline?)


Update: I tried using tracerpt.exe to export the event definitions, however running tracerpt -l BusesMergedTraces.etl -export busesMergedTraces.xml gave me an almsot empty XML file (with an empty <stringTable> element). Similarly, running tracerpt -l WPR_initiated_WprApp_InputTrace.etl -export WPR_initiated_WprApp_InputTrace.xml gives me only two <template> elements, none of which correspond to the MousePacketLatency and MouseLatency events. I've attached both of those files to this issue (renamed to .txt as GitHub prohibits attaching .xml files for some reason) - see WPR_initiated_WprApp_InputTrace.txt below the screenshots at the bottom.


Showing MousePacketLatency events:

image

Showing MouseLatency events:

image


WPR_initiated_WprApp_InputTrace.txt busesMergedTraces.txt