This month marks ten years since I started this blog . On this occasion, I would like to thank you for being my reader! Let’s celebrate with a new post on ETW

Empty paths issue in the wtrace output has been bugging me for quite some time. As I started working on a new wtrace release (coming soon!), there came the right moment to fix it. I’ve seen other people struggling with this problem too, so I thought that maybe it’s worth a blog post Wtrace uses the TraceEvent library to interact with the ETW API, and in this post, I will use this library as well. Note that this issue affects only the real-time ETW sessions.

Tracing FileIO events

Overall, when it comes to storage I/O tracing, there are two classes of events: DiskIO and FileIO. DiskIO events represent disk driver operations, while FileIO events describe the calls to the file system. I consider wtrace a user-mode troubleshooting tool. Therefore I decided to trace only the file system events. Another benefit of using FileIO events is that they are emitted even when the file system cache handles the I/O request.

Enabling FileIO events in the trace session requires only the FileIOInit flag in the call to TraceEventSession.EnableKernelProvider. You may also add the FileIO flag if you want to track the IO request duration (new wtrace will do that). The next step is to add handlers to the interesting FileIO events, for example:

However, you will shortly discover that the FileName property will sometimes return an empty string. An example wtrace output with this problem:

What’s causing this? Before we answer this question, let’s check how the file name resolution works internally.

File names resolution

Each ETW event emitted by the kernel is represented by the EVENT_RECORD structure. ETWTraceEventSource decodes this structure into a TraceEvent class, which is much easier to process in the managed code. As you can see in the structure definition, ETW events have some common properties, such as ProcessId, TimeStamp, or ThreadId. The data specific to a given event goes into the UserData field, which, without a proper manifest, is just a block of bytes. Thus, to process the UserData, we need a parser. The TraceEvent library already contains parsers for all the Kernel events, and it could even generate parsers dynamically. The Kernel parsers are located in a huge KernelTraceEventParser file (13K lines). By scanning through the FileIO*TraceData classes defined there, we can see that almost all of them have the FileName property. However, the way how this property is implemented differs between the parsers. For example, in FileIOCreateTraceData, we have the following code:

While FileIOSimpleOpTraceData, for example, has the following implemention:

The difference is that FileIOCreateTraceData extracts the FileName from its payload (the string is in the UserData field). FileIOSimpleOpTraceData, on the other hand, queries an instance of the KernelTraceEventParserState class to find the name by either FileObject or FileKey. It keeps a private _fileIDToName dictionary for this purpose. As you may have guessed, we receive an empty path when the FileObject/FileKey is missing in this dictionary.

_fileIDToName dictionary and FileIO events

From the previous paragraph, we know that an empty path signifies that there is no record in the _fileIDToName dictionary for a given FileObject/FileKey. If we look for code that modifies this dictionary, we should quickly locate the hooks in the KernelTraceEventParser constructor:

As handlers registered here will always execute before our handlers, delete, rundown, or cleanup events won’t have the file name as it just got removed from the _fileIDToName dictionary :). A simple fix is to keep your own FileObject/FileKey/FileName map, and that’s what the current version of wtrace is doing. However, as you remember, that does not always work. After some debugging, I discovered another problem. The FileIORundown events were never emitted, so the _fileIDToName contained only FileObjects from the FileCreate events. That explains why there are almost no empty paths for processes that started while the trace session was running. After checking the documentation and some more debugging, I learned that FileIORundown events appear in the trace when you enable DiskFileIO and DiskIO keywords. And, what’s important, they are issued at the end of the trace session. Although the documentation states they contain a FileObject, it is in fact a FileKey. Fortunately, TraceEvent has the property correctly named to FileKey in the FileIONameTraceData class.

Working example

My final approach is to open a “rundown” session for two seconds, prepare my fileIDToName dictionary, and then pass it to the actual tracing session with only the FileIO events:

Notice, I am not removing anything from the dictionary, so you may want to add logic for that if you plan to run the trace session for a long time.

[BONUS] What are FileObject and FileKey

I’m unsure why some FileIO events have only the FileObject field, while others have both, FileKey and FileObject. To check what these fields represent, I created a simple app in LINQPad that keeps a file open while running:

Then I started a tracing app and recorded few writes:

Next, I attached WinDbg to the kernel locally and checked the FileObject address:

As the !fileobj command worked, FileObject is a Kernel Object representing a file. From the WinDbg output, we can also learn that FileKey denotes the FsContext field of the FILE_OBJECT structure. As we can see in the API documentation, for the file system drivers, it must point to the FSRTL_ADVANCED_FCB_HEADER. This does not answer the initial question why some events miss this field, but at least we know its meaning.