ETW and Async in .NET

I ran into this problem at work and wanted to capture the findings for future me.

ETW uses the ActivityId field on the TEB to track an activity. This gets logged with the ETW events.

When adding async Tasks to the mix, Tasks have an abstraction on the execution context that is per Task. Tasks may run on multiple different threads and so it’s possible that a Task gets hooked up to a thread that already has an activityId set. This messes up logging.

AsyncLocal provides a way to “flow” an ambient value across multiple Tasks as part of a logical operation. This can be used to track activityId on Tasks, but the trick is getting it pushed down onto the native thread.

AsyncLocal has a constructor argument that is a callback that is executed when the value changes. Values are always refreshed from empty when a Task is assigned to a thread. This provides a place where the activityId can be flowed down to the executing thread so that ETW logging works.

See ActivityTracker.cs on ReferenceSource to see how this works in .NET Framework.

Creating an ETW Provider Step by Step

Event Tracing for Windows is a strongly-typed, high-volume, low-latency tracing framework for Windows. It’s also frustratingly difficult to use. MSDN has a ton of documentation but no simple ‘Hello World’ end-to-end example. Hopefully this post will help you get started writing your own ETW events from your application.

Creating an ETW provider requires the following steps. Each step is described in detail below.

  1. Create the event manifest.
  2. Compile the manifest to produce headers and resources.
  3. Register application as a provider and write events.
  4. Register the event manifest with ETW.

Background

Before diving in, you will need to know a few basics about ETW. First of all ETW is not a very friendly API. It’s fast and extensible but producing and consuming events is challenging. Just getting a program set up to receive events takes almost 100 lines of C code (mostly esoteric flags and parameters). Strangely, producing events is much easier than reading them.

In C# you can use the EventSource and EventListener classes in System.Diagnostics.Tracing but those libraries don’t produce events that are easily read by existing tools like logman or Message Analyzer (which Microsoft deprecated). These libraries aren’t an option from native code so you’re stuck with the C API.

Before you continue, take a look over the following articles to get acquainted with ETW jargon.

Creating the Event Manifest

ETW events are structured – they have a strongly typed schema. This means that you need to plan for what you will be logging before you get started. You could simply define an event with a single string field and use it to log strings (there’s actually a special case for that), but you’d be missing out on one of the best features of ETW.

Define the events

The first thing you need to do is decide what your events should look like. For this tutorial we’ll build a system that logs an event that carries a single integer metric and a string describing the metric.

// simple metric event
struct metric {
    const wchar_t*  metric_name
    int             metric_value;
};

NOTE: this code is not required, this just shows the shape of the data to emit

You can use this event in your code to emit metrics like the number of items processed or the number of milliseconds spent in a call. It’s very simple but it allows you to add arbitrary metrics in new code without recompiling the manifest and you can write a consumer application that can monitor these metrics in real time.

Create the manifest file

Once you know the shape of the data you want to log, you will need to write a manifest. The manifest provides the following information about events.

  • The provider Id – this is unique on the system and is used to identify your provider.
  • The resource file name – this is the absolute path to the location where you will eventually put the binary (DLL or exe) that contains the schema for your events. Yes, you have to include a path to the location where you will put the DLL that contains the compiled version of the manifest in the manifest!
  • The event Id – this Id is unique within the provider
  • The event name and description – these provide human-readable strings that describe the event. These strings can be localized.
  • The event template – this is basically a schema but it can be reused across multiple events. It’s optional if you don’t have any additional data to send.

Or as MSDN puts it:

Metadata fields are combined for each event and defined in an tag that is uniquely associated with an event ID. Event layouts are specified with a tag which describes user-specified context data for each event. The layout can specify data fields such as strings and integers, or other more complex data structures. Template information does not have to be specified for all events; however, if unspecified for a particular event, it will have no user context data.

There are many other things that can be defined in the manifest file but these are the only things we need to know for now.

The manifest file is an XML document that has a pretty complex structure. You can download an XSD and wing it in your favorite editor or you can use ECManGen.exe which provides a questionably (try it, you’ll see) nicer experience for creating and editing manifest files. ECManGen.exe comes with the Windows SDK and on my machine is found here: C:\Program Files (x86)\Windows Kits\8.1\bin\x64\ecmangen.exe. I’m not going to describe how to use this tool – although not beautiful, it’s pretty self-explanatory.

TIP: after creating your provider, create the template first – you will need to reference it when creating the event.

Here’s the finished manifest file. It defines a provider called Hello World Metric Provider with a symbol HELLO_METRIC. The symbol is the name given to the GUID value in the generated headers. The provider has one event called SIMPLE_METRIC with an event Id of 1 and a schema defined by template Simple Metric. The Simple Metric template has a Unicode string field called metric_name and an integer field called metric_value.

Notice the resource and message file names. helloworld.dll will need to be generated and added to the Windows folder so other applications will be able to find the schema.

helloworldmetric.man

<?xml version="1.0" encoding="UTF-16"?>
<instrumentationManifest
    xsi:schemaLocation="http://schemas.microsoft.com/win/2004/08/events eventman.xsd"
    xmlns="http://schemas.microsoft.com/win/2004/08/events"
    xmlns:win="http://manifests.microsoft.com/win/2004/08/windows/events"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xmlns:xs="http://www.w3.org/2001/XMLSchema"
    xmlns:trace="http://schemas.microsoft.com/win/2004/08/events/trace">
    <instrumentation>
        <events>
            <provider
                name="Hello World Metric Provider"
                guid="{06A2EA53-FC6C-42E5-9176-18749AB2CA13}"
                symbol="HELLO_METRIC"
                resourceFileName="c:\Windows\helloworld.dll"
                messageFileName="c:\Windows\helloworld.dll">
                <events>
                    <event
                        symbol="SIMPLE_METRIC"
                        value="1"
                        version="1"
                        template="Simple Metric"
                        message="$(string.Hello World Metric Provider.event.1.message)">
                    </event>
                </events>
                <templates>
                    <template tid="Simple Metric">
                        <data
                            name="metric_name"
                            inType="win:UnicodeString"
                            outType="xs:string">
                        </data>
                        <data
                            name="metric_value"
                            inType="win:Int32"
                            outType="xs:int">
                        </data>
                    </template>
                </templates>
            </provider>
        </events>
    </instrumentation>
    <localization>
        <resources culture="en-US">
            <stringTable>
                <string
                    id="Hello World Metric Provider.event.1.message"
                    value="A simple metric">
                </string>
            </stringTable>
        </resources>
    </localization>
</instrumentationManifest>

Note: the file encoding must match the encoding specified in the XML tag.

Compile the Event Manifest

Once you have a manifest defined you need to compile it. This will produce a header file that has the provider GUID and event descriptors defined as well as a resource that needs to be included in a binary which will be registered with ETW as the source for schemas for schemas for events from your provider. You can also produce C# files that can log your events. The generated code is… functional (read: it’s gross).

To compile the manifest, you need the mc.exe Message Compiler tool. Message compiler is installed with Visual Studio and is found here on my machine: C:\Program Files (x86)\Windows Kits\8.1\bin\x64\mc.exe. Specify the -um parameter which will generate macros for logging your events. This is optional, but without it, you’ll have to manage registering the provider and logging events yourself.

mc.exe -um helloworldmetric.man

This will compile the manifest and generate the resources and headers that you need to include when generating the helloworld.dll.

  • helloworldmetric.h – defines the provider guid and event descriptors. If -um was specified, also contains generated helper macros to register/unregister the provider as well as log events.
  • helloworldmetric.rc – a resource script that includes the compiled bin files.
  • helloworldmetricTEMP.BIN – the compiled schema for your events. This is a binary file that the ETW system will use to unpack the events logged by your provider.
  • MSG00001.bin – contains the localized strings from the manifest.

From Visual Studio

You can include these files directly into a project or generate them during the build. The simplest way is to add a pre-build step that runs mc.exe to generate the files. You can specify parameters to mc that let you control where generated files are written. Then you’ll have to manually modify the project file to include the generated files. Just remember that the output of the build must eventually be written to the path specified in the manifest.

In my sample project, I use a batch file to run mc.exe and rc.exe to produce the files above and compile the resource file. In the linker options for the project, specify the .res file generated by rc.exe as an “Additional Dependency”. Once built, you can verify that your executable has the manifest embedded by opening the .dll or .exe in Visual Studio. In the resources you should see a resource name starting with WEVT_.

From command line

If you don’t want to set up a project, you have everything you need at this point to build the helloworld.dll. You need to compile the resource file using Resource Compiler found in the same directory as mc.exe. Finally, you’ll have to link the compiled resource into a DLL using link.exe (in the Visual Studio bin folder).

From a Visual Studio Developer Prompt (which has the PATH set up already)

mc.exe `helloworldmetric.man`
rc.exe `helloworldmetric.rc`
link.exe  /dll /noentry /machine:x64 helloworldmetric.res /OUT:helloworld.dll

Registering the Provider and Writing Events

Now that you have the generated header, you can register your program as a provider. This basically tells ETW that you’ll be writing events as this provider (based on its GUID). You might not have considered this, but because the program gets to pick which providers and events to log, it means that any program can log as any provider. This makes sense for things like .NET were any program can log the .NET events like garbage collections or context switches. It also means that you can write applications to simulate other providers emitting events which can be useful for testing or spoofing events.

Any program can log events as any provider.

You’ll need to include Windows.h, Evnprov.h and the header from the generated manifest in the code you want to log from.

#include 
#include 
#include "helloworldmetric.h"

void do_work(int i)
{
    // actually log an event
    EventWriteSIMPLE_METRIC(L"test event", i);
}

int main(int argc, char** argv)
{
    // register this program with ETW
    EventRegisterHello_World_Metric_Provider();

    for (int i = 0; i < 10; ++i) {
        do_work(i);
    }

    // unregister this program with ETW
    EventUnregisterHello_World_Metric_Provider(); 

    return 0;
}

Register the Manifest

Now that you have some code that writes an ETW event, you can start to listen to the provider. Run Message Analyzer and listen to the provider by specifying the GUID from the manifest (you’ll have to add a Custom Provider). When you run the test program, you’ll see your events but they won’t have a schema associated with them. This is because the manifest has not been registered with ETW.

To register the manifest, you’ll need to use WevtUtil.exe with the im parameter.

wevtutil.exe im helloworldmetric.man

Remember the helloworld.dll? This is when you actually need the file specified in the manifest to exist. The compiled resources themselves don’t actually contain the path so you can update the paths in the manifest before registering the event, the DLL just has to exist when you run wevtutil.exe.

Now if you run Message Analyzer, you’ll find ‘Hello World Metric Provider’ in the list of system providers. If you listen to that provider, and run the test program, you’ll see the events are received but have a schema now. Huzzah!

If you want to modify the manifest, you must unregister the manifest first using the um parameter before reinstalling.

wevtutil.exe um helloworldmetric.man

Wrap up

Getting set up to log and consume manifest events is complicated, but once you’ve done it a few times it’s not too bad. Using ETW allows you to log events that you can dump to files, the Windows Event Log or even consume the traces in real-time from other processes. You can build powerful watchdog/monitor systems this way or use existing tools like Message Analyzer to collect and analyze trace data.

UPDATE: Microsoft has deprecated the Message Analyzer. Their suggestion is to use something like WireShark. I haven’t tried that, but I have found a few extensions for WireShark which claim to process ETW. Your best bet for visualization may be to write your own tooling with KrabsETW or EventTrace in .NET.


Additional Resources