An End-To-End ETW Tracing Example: EventSource and TraceEvent

I have already made a series of blogs about EventSource starting with my tutorial introduction to EventSource.  This gives you enough information to generate events, and using the PerfView tool, lets you look at these events in a viewer.  This is great for a broad variety of ad-hoc scenarios.     However what if you want to go further and build automation that processes your EventSource events programmatically?    This is what this blog entry is about.   Here I show you how to use the TraceEvent library (there is a old version of the code available here, but the version of this DLL that is included in the ZIP file associated with this blog is much newer, and I recommend using that until the codeplex site gets updated (hopefully soon).    The TraceEvent library is all about reading ETW data, and it is the library that the PerfView tool itself is built upon.   Here we show you how easy it is to use this library to programmatically enable your EventSources and parse the results programmatically.

 

You will notice that I have attached a SimpleMonitor.zip file to this blog entry.  This zip file contains the TraceEvent.dll library as well as a simple, one page demonstration application called 'SimpleMonitor'.   To demonstrate the 'end-to-end' scenario, this application contains both parts: the EventSource that generated the events as well as the logic that turns on the EventSource and parses the resulting events.   Normally these two parts would be in different processes but to make the demo super-simple to run, both parts are in the same executable.  

  1. The Event Generator generates 3 types of events, MyFirstEvent, MySecondEvent, and Stop.   It happens to generate the first two once a second for 10 seconds then logs the Stop event and then goes silent.    The listener code turns on this provider, watches for these particular events, takes different actions on each of them, using the event payloads in the events in the processing.   The processing consists of computing the time delay between the 'MyFirstEvent' and 'MySecondEvent'.   When it sees the 'Stop' event the listener shuts down and the whole program exits.  This example is simple enough to demonstrate the end-to-end process in a small amount of code.   Here is a condensed version where I simplified it to highlight the essentials. 

 

 Basically you create a TraceEventSession which is a 'sink' which represents a stream of ETW events.  These sessions are KERNEL objects, and in particular they can live beyond the lifetime of the process that created them (thus you can have one process 'start' a session' and another 'stop' it.    You can create a session that logs to a file, but in this case we passed 'null' as the file name which means we don't want it to go to a file but we will read it in 'real time'.    Session are for CONTROLLING ETW sessions (thus you see that later we do an 'EnableProvider' on the session to turn on the particular EventSource we want.  You an turn on many providers on the same session, but in this case we did only one.  

Because we want to READ the data that is being logged to this session in real time, we attach a 'ETWTraceEventSource' to the session.  This knows how to READ etw events.  You can tell this to read from a file, but in our case we told it to read in real time directly from 'My session', so this is where it will get its data.    Now an ETWTraceEventSource knows how to read ETW events, but every different provider has its own different 'payloads' and you need something that understand the particular payload for the events you are interested in decoding completely.   This is what a 'TraceEventParser' is: something that knows how to parse a PARTICULAR provider's events.   We will see in later blog entries how we can create TraceEventParsers that are designed to decode just ONE EventSource's events, however in this case we are using the 'DynamicTraceEventParser' which knows how to decode ANY EventSource (but can only do so relatively inefficiently and is relatively cumbersome to code against). 

One way you can get parsed events from a TraceEventParser is to ask the parser to call you back when a particular event happens.   In this case we ask the DynamicTraceEventParser, to call us back whenever any event happens (by subscribing to the 'All' event).   Thus the anonymous delegate shown above get a callback whenever any event happens that the 'DynamicTraceEventParser' knows how to parse (which includes all EventSources).    In the demo we simply print the event (which will show you all the payload fields printed out nicely as XML), and look for an event called 'Stop'.   When that happens to close the source (which stops the listern). 

Once we have set up the callbacks for our READER, we turn our attention back to the SESSION and tell it to actually enable the EventSource that we want.   From that point events are starting to accumulate in the session.   We then call the 'Process()' event on the SOUCE (the reader), which will start reading events from the session and dispatching them to the parsers which dispatch them to our callback.    This continues until there are 'no more events'.  For files, this is the end of the file, but for real-time sessions, it only stops when the source is closed (which we do when we see the Stop() event). 

So in recap to get at EventSource event programmatically you

  1. Create a session which allows you to turn on and off particular event sources
  2. Enable one or more EventSources in the session
  3. Connect up a ETWTraceEventSource to the seesion which can READ the events
  4. Connect up a TraceEventParser, that knows how to PARSE a Particular provider's events
  5. Subscribe to the TraceEventParser's events that you are interested in.  What you get back is a fully parsed event
  6. Call source.Process() which runs the dispatch loop and only returns when all events are read (or the source is closed())
  7. Call source.Close()  or source.Dispose() (They are synonyms) when you are done
  8. Call session.Dispose() when you are done with the session (this is what the using clause does)

You can see that you can do all of this in just a few lines of code.   If this piques your interest, you should definitely download the source and take a look.  It is not long (2 pages), and most of it is comments that describes in detail what the code is doing.   It is definitely worth a read. 

Next time I will show you how this changes when you log to a file instead.    In later blog entries I will also show you how you can build parsers that are specific to your EventSource, and make building the processing code easier and significantly more efficient.    You can also turn on other providers that are built into the OS and the .NET Runtime, and capturing stack traces when event fire, which is where things really start to get interesting. 

Source Code Guide

To look at the complete source, simply open the SimpleMonitor.zip file and copy it to your machine.   You can build the solution in Visual Studio.  All the interesting code is in Program.cs, and only consists of about 2 pages of code which hopefully you will recognize from the snippet above.

 

SimpleMonitor.zip