• Home
  • Tutorials
  • Introduction Tutorial: Logging ETW events in C#: System.Diagnostics.Tracing.EventSource
 
222
0
0

Introduction Tutorial: Logging ETW events in C#: System.Diagnostics.Tracing.EventSource

Event Tracing for Windows (ETW) is a fast, scalable logging mechanism built into the Windows operating system.   It is powerful because of three reasons

  1. The operating system comes pre-wired with a bunch of useful events
  2. It can capture stack traces along with the event, which is INCREDIBLY USEFUL.
  3. It is extensible, which means that you can add your own information that is relevant to your code.

Tools like PerfView  and Windows Performance Analyzer (formally XPERF) can be used immediately for (1) and (2) above.  This blog is about doing (3).  You can also watch the video of me going through the steps below. 

When you log events to an ETW event stream, in ETW parlance, you are creating a ETW Event Provider.    Sadly, historically creating a ETW event provider has been a non-trivial task, which writing an XML 'Schema manifest' and  using a specialized tool (MC.exe) to generate source code to link into your application.   You also need to register the provider using another obscure tool (WEVTUTIL) when your application was deployed.    This discouraged most users from ever building their own ETW providers, which is a shame because it is a powerful feature of ETW. 

To fix this, we have added the System.Diagnostics.Tracing.EventSource type to  Version V4.5 of the .NET Runtime (Now available for download, as a release candidate.  It will officially ship later in 2012).   It makes writing ETW provider as simple as writing just a few lines of code.    In this blog entry I will demonstrate just how easy it is to log your own events to the ETW data stream and thus make the OS ETW data EVEN MORE USEFUL by correlating it with what you are doing in your code.    

The first step in logging ETW events is to decide what we need to log.  We need to decide on a name for the provider, as well as the events and all their payloads.   You can do this with just a few lines of code using EventSource.   For example the code

sealed class MinimalEventSource : EventSource

{

    public void Load(long ImageBase, string Name) { WriteEvent(1, ImageBase, Name); }

    public static MinimalEventSource Log = new MinimalEventSource();

}

defines a new ETW provider called 'MinimalEventSource' (by default the name of your subclass of EventSource) and defines a event called 'Load' which has a payload which consists of long value called 'ImageBase' and a string called 'Name'.    So for (the text in blue), we are just specifing what we want (what the 'shape' of the event is).   Ideally this is all that we would specify, however to 'hook it up' we need to write a SMALL amount of 'boiler plate' code.  This code is purple above where we pass the data to the 'WriteEvent' function, along with the 'Event ID' (this number starts at 1, and increases for each event you add to your provider).    EventSource does the rest.   That is not so bad!

The code in green simply creates a global variable called 'Log' which holds our EventSource (typically you only make one for the whole app).    Now we can generate events simply by typing 

MinimalEventSource.Log.Load(10, "MyFile");

TADA!   you have just written the code necessary to write your very first ETW event.     So, how do you turn it on.    This is where PerfVIew comes into play.   If you are not familiar with PerfView check out the Tutorial Videos.   Perfview has some special support for EventSources that make it particularly easy to use .    Lets assume we compiled the code above into an application called 'EventSourceDemo.exe'.   To run that program with the 'MinimalEventSource turned on we can do

PerfView /OnlyProviders=*MinimalEventSource run eventSourceDemo.exe

This command turns on MinimalEventSource (do not forget the *, that * indicates is important and I will explain it in a later posting).   The /OnlyProviders tells PerfView to ONLY turn on the listed providers (normally it turns on a default set of CLR and Kernel Events).   The 'run' command then specifies that the rest of the command line should be executed as a command while those providers are active.   The result is a file (because we did not specify it is called 'PerfViewData.etl').   After creating that file PerfView immediately opens it.    The result is probably a display that looks like this

 On the left, you wee the PerfViewData.etl file that was just created.  If you open it you see various 'Views' of the data in that file. The one we care about right now is is the 'Events' view.   Double clicking on that brings up the Event Viewer.  

 On the left you see all the events from all the ETW event providers that were captured in the file.   You can see the ones from 'MinimalEventSource'  as well as a bunch from 'PerfView'  (Hmmm, I wonder what .NET library PerfView used to generate those ETW events?).  By selecting events in that left pane (In particular the MinimalEventSource/Load event) and hitting return you will see all the events selected in the right pane.   You can see in the above case the event that we logged in our sample code.   Notice that we know that it was a load event, what process and thread, and time the event was logged, as well as the payload values (ImageBase and Name) that were passed when it was logged.   Just what you might expect. 

OK Now your turn.    At the end of the article is a ZIP archive of all the source code for EventSoruceDemo (it is actually significantly more complex that what I have shown above (there is a lot that I have not told you yet).   The ZIP file contains both the source code as well as the compiled binary (in the bin\Debug directory).   Because V4.5 has not shipped yet, I have made it super-easy for you to try this out by including a 'stand-alone' EventSource.dll binary that works on current runtimes.    Thus you can try this out by doing

  • Extract the files in the ZIP file below.
  • Download PerfView.exe from the PerfView Download Site.
  • Open a command window in the PerfViewDemoV3.5\bin\debug directory
  • Execute the command: PerfView /OnlyProviders=*MinimalEventSource run eventSourceDemo.exe
  • Open up the 'events' view and take a look at the events generated. 

Since you have the complete source, you can recompile it using Visual Studio (Free version here) to see how changing the code changes the events being logged.   You can also use the EventSource.DLL in your own  applications right now if you like (when V4.5 ships later this year, it will simply be part of the framework).  

There is a lot more to say, as we have only done the 'hello world' version of event logging so far.   However I hope I have at least piqued your interest.   EventSource (and PerfView) make it truly easy to log events to ETW and thus leverage the power of all those existing OS events.   If you are not adveneros to dowload it right now, you shoudl at least watch the video of me doing so. 

OK, that is enough for this posting.   I will post more soon, but in the mean time, have fun experimenting with the demo.

See Also  

  1. EventSource Spec
  2. Why use ETW EventSource
  3. End-to-End example using EventSource and TraceEvent

 

Discussion

-