Announcing TraceEvent – Monitoring and Diagnostics for the Cloud

Announcing TraceEvent – Monitoring and Diagnostics for the Cloud

Rate This
  • Comments 6

In this post, Vance Morrison, software developer on the .NET Runtime team, will talk about the TraceEvent NuGet library we just shipped. -- Immo

I am happy to report that we have just released the TraceEvent library on (prelease) NuGet. This library is an important part of the .NET, end-to-end, cloud scale diagnostics and monitoring story. It allows you to easily control and process any Event Tracing for windows (ETW) logging events, and in particular the logging events generated by the .NET System.Diagnostics.Tracing.EventSource class. Together EventSource and TraceEvent form a complete logging system that is light weight, efficient, interoperable with operating system logging, and which can easily be automated for cloud-scale installations.

The TraceEvent library has been available for some time via the BCL codeplex site, however repackaging this library as a NuGet package makes it significantly easier for you to add to your app and also to get all of our updates. In addition we have created a ‘TraceEvent Samples’ NuGet package that makes it even easier to get started.

Here’s what it does

Here is a quick demo of what you can do. In the following demo we have two processes. The process on the left represents an application being monitored. This application EvenSource to log a ‘MyFirstEvent’ when it start a user’s request, and a ‘MySecondEvent’ when it is done. For demo purposes, this process also logs messages to the console when these events are logged. The process on the left is using ETW to monitor ‘interesting’ events machine wide, including the ‘MyFirstEvent’ and ‘MySecondEvents’ as well as .NET runtime garbage collection (GC) events. It uses this information to perform its analysis: for this demo, it is how long requests take and how long.NET GCs take. In this particular screenshot, you can see we highlighted a GC that happened on the third request and the resulting logging that happened in the monitor. This scenario is typical, how you can combine both your own events along with a wealth of built in ones to perform better analysis (in this case determining if GC has impact on response times). Building something like this is straightforward with the TraceEvent library, but you can also do so much more. The PerfView tool was built entirely on top of the TraceEvent library.

How to get started

It is really easy to get started with our sample in Visual Studio:

  1. Create an empty console application,
  2. Right click on the References node in Project Explorer and select Manage NuGet Packages
  3. Set the filtering to include pre-release packages and search for ‘TraceEvent Samples’ and select that package a part of that project.
  4. Add the line TraceEventSamples.AllSamples.Run(); to your main program.
  5. Browse the sample code in the ‘TraceEventSamples’ directory the NuGet package inserted into your project.
  6. Hit “F5” when you want to see it run.

The samples package shows you several of the most common scenarios for using TraceEvent. It demonstrates how to enable both your own EventSource or .NET/OS events and then send the data either to a file or process them in real time.

The TraceEvent NuGet package also comes with a ‘TraceEventProgrammersGuide.docx’ file (I have included a copy at the end of the blog but as you will see it is not finished. The most up to date one will always be in the package). Once you have decided that you want to use this library, reading this doc is the fastest way to get truly ramped up.

Enough Overview. Show me the code!

The EventSource class in the .NET Framework 4.5 makes logging as easy as defining a class that has a method for each different kind of event. You can see what that looks like in the example definition below, and learn more in my EventSource tutorial.

class MyEvents : EventSource 
public void MyFirstEvent(string MyName, int MyId) { WriteEvent(1, MyName, MyId); }
public static MyEvents Log = new MyEvents();

The MyFirstEvent method would then be called from the appropriate places within an app.

MyEvents.Log.MyFirstEvent("hello", 35); 

Events then ‘go to subscribers’. Those subscribers could be EventListeners in the same process as the EventSource. EventSource also supports out-of-process listeners, using its built in support to send events to the Event Tracing for Windows (ETW) infrastructure. There are tools like PerfView, which let you enable EventSource providers ‘manually’ (see my tutorial for details).

You can also listen to events from other processes from code, which is valuable for automation. This is where the TraceEvent library comes in, which make it easy to collect ETW events. Here is the code to turn on monitoring of the ‘MyEvents’ EventSource (from another process) for 10 seconds and send the data to MyEventData.etl. It is about as easy as you can get.

using (var session = new TraceEventSession("MySession", "MyEventData.etl"))
// Collect for 10 seconds then stop.

Once you have data, TraceEvent makes it easy to process the events that you’ve collected. Here is the code that plucks out the events you want, using lambda syntax.

using (var source = new ETWTraceEventSource("MyEtlFile.etl"))
source.Dynamic.AddCallbackForProviderEvent("MyFirstEvent", "MyEvents", (TraceEvent data) =>
Console.WriteLine("GOT {0}({1}, {2})", data.EventName,
data.PayloadByName("MyName"), data.PayloadByName("MyId"));
// Typically you have several of these callback registration calls.

You might wonder why the API signature includes an Actionparameter, which you see above as the lambda, instead of a more traditional IEnumerable pattern. TraceEvent also supports ‘real time’ processing of events, so exposes an API that works well for that. In that situation, an implementation needs to be called as events come in. In the scenario above, which processes an ETL file, that approach isn’t needed, however, that’s the reason for the API shape. Because the code is written in this way, it is easy to modify this sample to process the data in real time rather than from a file.

The code above registers callbacks for the set of events that it is interested in. In this example, that’s only ‘MyFirstEvent’ from the ‘MyEvents’ provider). This implementation is simple: it finds the ‘MyName’ and ‘MyId’ values and print them. A typical implementation would register several callbacks, one for each kind of event needed for analysis. Once all the callbacks are registered, ‘Process’ is called to invoke the callbacks, as the events are read from the source (in this case the ETL file).

Not bad. In a dozen lines of code or so, I have set up all the code needed to log an event, pass different types of argument to it, enable it from outside the process, and receive that event data to parse those arguments to do whatever monitoring logic I want. That’s not a lot of effort to create the beginnings of a real cloud monitoring solution.

And that is only the beginning. For those of you who like the Reactive Extensions framework, TraceEvent supports that too, and the NuGet TraceEvent Samples package has examples of this. You also have the wealth of .NET and OS events that let you know about the GC, the Just in time compiler, CPU, Disk I/O, Network activity, Blocked time and more. Events can also have stack traces associated with them, which are SUPER useful for doing ‘deep dive’ diagnosis. We have only scratched the surface.

If you want to learn more:

  1. Read the Programmers guide at the end of this blog entry.
  2. Read Vance Morrison’s Blog on TraceEvent and EventSource.
  3. Read Grigori’s blog on Semantic (strongly typed) logging and the Semantic Logging Application Block code on codeplex that lets you send EventSource events to other places besides ETW (e.g. a local file, or a database, or Azure storage …)

Next steps!

You should follow my suggestion above about creating an empty console project in Visual Studio and referencing the ‘TraceEvent Library Samples’ NuGet Package in your empty project (currently is a pre-release package so make sure your filters don’t hide it). If you want to skip the samples, you can simply reference the ‘TraceEvent Library’ directly and start writing your code that uses it. In either case, reading the TraceEventProgrammersGuide.docx (either at the end of this blog or in the TraceEvent package) is highly recommended.

How do I report bugs or make suggestions?

We are definitely interested in your feedback. For now please simply respond to this blog entry with any bug reports or suggestions.

Happy Eventing!

Attachment: TraceEventProgrammersGuide.docx
Leave a Comment
  • Please add 8 and 5 and type the answer here:
  • Post
  • Is it possible for us to monitor ETW events generated on client machines on SCOM 2007 without writing custom management packs, or would we ideally need an EventListener which would centralize our client events and allow SCOM to watch that central store?

  • Your question seems to be more about SCOM than about EventSource/TraceEvent, and I have little familiarity with SCOM.  EventSource can log to the windows EventLog (see which SCOM probably has support for, but I don't know for sure.   It is also relatively easy to write an EventListener that take the events and logs them to a (local)  file (This is what the sematic logging application block does (   Seem like one of those two options will work.  

  • Is Semantic Logging Application Block and Sinks written on top of TraceEvent Library? If not, it would be very easy to write that on top of this, isn't it?

  • Is there any reason why the SessionStartTime is not UTC? This causes a wrong Timestamp on the Event if the Timezone Offset changes while a Trace session is running (this happend last sunday with the start of daylight saving time).

    As far as I can tell, the code causing this is in the ETWReloggerTraceEventSource class. The property SessionStartTime is calculated with DateTime.FromFileTime which results in a local DateTime. I think you should be using FromFileTimeUtc.

  • I have tried using Microsoft.Diagnostics.Tracing.TraceEvent.1.0.32 and 1.0.35 with .NET 4.0 under Visual Studio 2013. (I can't use .NET 4.5 because of a dependency on Telerik controls.) The build fails with errors about Microsoft.Diagnostics.Tracing.TraceEvent.1.0.35\lib\net40\Microsoft.Diagnostics.Tracing.TraceEvent.dll being built against .NET 4.5 even though it appears in a directory named net40. The actual error output is copied at the end of this comment. When I load the assembly in Reflector there is no TargetFramework attribute.

    By contrast Microsoft.Diagnostcs.Tracing.EventSource does have a TargetFramework attribute

    [assembly: TargetFramework(".NETFramework,Version=v4.0", FrameworkDisplayName=".NET Framework 4")]

    I have experimented by editing my project file directly, replacing the "net40" in the HintPath for Microsoft.Diagnostics.Tracing.TraceEvent.dll with "net35". The build worked after this edit so I have something I can proceed with although it would be good to see this fixed for other people in future.

    When I was performing early experiments, building a test harness around EventSource and TraceEvent, I used the default .NET 4.5 and everything worked fine. The problem is just when using .NET 4.0 in production code.

    Here is as much of the full error output from the build as will fit in the comment:

    1>C:\Program Files (x86)\MSBuild\12.0\bin\Microsoft.Common.CurrentVersion.targets(1697,5): warning MSB3274: The primary reference "Microsoft.Diagnostics.Tracing.TraceEvent, Version=, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL" could not be resolved because it was built against the ".NETFramework,Version=v4.5" framework. This is a higher version than the currently targeted framework ".NETFramework,Version=v4.0".

    1>C:\Program Files (x86)\MSBuild\12.0\bin\Microsoft.Common.CurrentVersion.targets(1697,5): warning MSB3268: The primary reference "Microsoft.Diagnostics.Tracing.TraceEvent, Version=, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL" could not be resolved because it has an indirect dependency on the framework assembly "System.IO.Compression, Version=, Culture=neutral, PublicKeyToken=b77a5c561934e089" which could not be resolved in the currently targeted framework. ".NETFramework,Version=v4.0". To resolve this problem, either remove the reference "Microsoft.Diagnostics.Tracing.TraceEvent, Version=, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL" or retarget your application to a framework version which contains "System.IO.Compression, Version=, Culture=neutral, PublicKeyToken=b77a5c561934e089".

  • I have a suggestion for an improvement. EventSource accepts a wide range of arguments as parameters to a log method. However, I discovered that TraceEvent is limited in the types it will receive. From Reflector, the relevant method appears to be GetPayloadValueAt() in class Microsoft.Diagnostics.Tracing.Parsers.DynamicTraceEventData. It accepts Boolean, Char, SByte, Byte, Int16, UInt16, Int32, UInt32, Int64, UInt64, Single, Double, String, IntPtr, Guid, DateTime. I was trying to use a byte array holding a simple serialisation of some variable information. It would be nice to see support for byte array added and/or some documentation against EventSource drawing attention to this limitation. (I have resorted to base64-ing into a string for now.)

    Another thing I have experimented with but cannot get to work is the passing of command arguments. I have an override of EventSource.OnEventCommand(). When I call TraceEventSession.EnableProvider, using TraceEventProviderOptions to pass in some strings they don't appear in the EventCommandEventArgs.Arguments property when OnEventCommand() is called. None of the samples try to do this and I can't see what I am doing wrong. Any pointers would be appreciated. (I am running Windows 7. Could this be something that only works on Windows 8?) My application generates huge amounts of logging and ETW's ability to vary log level filtering while the system is running is very attractive. (The system runs 24x7 for months on end so stopping it to edit configuration file settings isn't an option.) I was hoping to build additional filtering capabilities based around the EventCommandEventArgs.Arguments mechanism.

Page 1 of 1 (6 items)