.NET Event Counters – When logging isn’t fast enough

Simon Timms Developer Tips, Tricks & Resources

Over the past few years, I’ve become more and more convinced that having really good production logs is critical to running a successful software deployment. Logging has always been important, however if you’re deploying a web of microservices and a business transaction might span twenty different services, then searchable centralized logging is crucial. There are plenty of great tools available for such logging: Sumo Logic, Log Entries, App Insights, and of course, Stackify’s own Retrace. Querying against logs in one of these tools provides a high-level overview of what’s happening.

However, there is a performance impact from logging. Logging is ideal for events that occur only a few times per second, but scenarios where events occur hundreds of times a second will quickly overwhelm logging services. Frequently we don’t need a detailed log to gather the performance metrics that are important to our application.

Consider people logging into our application: we’re more interested in how many login, rather than who it is. If we typically see 1,000 people a minute logging into the application, but after a deployment the number drops to 500 (or worse to 0), then we know that the deployment has likely introduced a regression. So instead of keeping track of detail logs, we could simply keep a counter of events.

Event Tracing

Most people don’t realize that there is a high-performance kernel-level logging and event counting facility built into Windows: Event Tracing for Windows (ETW).

ETW is an ancient system. Many of the articles I read in preparing this post dated back to 2007 (or even 2003). I’m not sure which release of Windows introduced ETW, but Windows 2000 seems like the first operating system referenced in any document. There is a trend these days to dismiss anything that old as silly, and then six months later reinvent it. Fortunately, ETW has continued to be actively developed and there seems to be no movement to replace it.

Writing to it can be enabled or disabled for a process without having to restart the process. This means that it can be turned on for a brief period, and then the logs analyzed at a later date.

ETW is divided into three parts.

  • Providers – anything which writes events or counters to the event stream
  • Consumers – processes that consume events; these consumers can write events to an event trace log (ETL) file or simply display them
  • Controllers – processes which turn log consumption on and off

Providers

Many processes already write events to ETW and allow some debugging without having to even write your own events. There is tight integration with managed .NET applications through instrumentation points in the runtime. The kernel is also a huge provider of event information, as is Internet Explorer or Edge browsers. Of course,you can write to ETW yourself, and we’ll get into that shortly.


Stackify Loves Developers

Consumers

Consumers read the stream of events from ETW. You can filter events and either display them, or log them to a file for later use. The PerfView tool is an open source project that can read logs from ETW and display them. It works by capturing a chunk of logs and then presents them for analysis. However, be warned that the amount of data captured can be quite impressive. In the example capture shown below from my my laptop, which had just been rebooted and was running very little, captured 312 MB in 10 seconds.

Screenshot of PerfView showing TCP traffic information

A capture of the TCP/IP send statistics from my laptop.

This capture spans all of the event sources on the machine. Notice the variety of applications making use of TCP/IP; because we captured globally, the data spans multiple processes. Fortunately, PerfView allows for some very aggressive filtering so it is possible to isolate a single event source.

Controllers

Controllers simply turn on the collection of information from a process. During normal operation, most of the event capturing is turned off for every process, and you must explicitly turn it on with a tool like PerfView or Logman. It is important to distinguish ETW from Performance Counters, which are what would be examined by the Performance Monitor tool. While they serve a similar purpose, ETW provides a deeper level of logging; Performance Counters are designed to provide a broader overview of the health of the system. A great explanation of the differences can be found on Stack Overflow.

PerfView

There are a few consumers of ETW in the wild; one of the better ones is PerfView. PerfView provides facilities to capture traces as well as examine saved traces. It can be downloaded from Microsoft where it is shipped as a friendly standalone executable. Once extracted, launching it presents a help file and browser to find existing ETL log sessions.

The PerView application showing a file browser on the left and help text on the right. In the browser an existing ETL session dump is selected.

Existing ETW log session saved as an ETL zip file (top left).

To start a new capture, select the Collect menu. This will present a screen that may have been designed by a programmer.

A view of the capture window from PerfView. It is ugly with a dozen checkboxes and links and misaligned fields. It is a window only a mother could love.

The data collection window is committed to being confusing, like a kitten to a ball of yarn.

Clicking on “Start Collection” will kick off a new capture session. By default, the collection window will capture all events, so it is advisable to only capture data for a short period. The capture does use a circular buffer, so if you collect for too long a period the earlier events will be overwritten.

Capturing custom events

Capturing system events can be very useful. I was particularly struck by the usefulness of the TCP/IP captures since they showed information on every process that using the network, and on the inner workings of the .NET framework.

PerfView showing 9 exceptions throw and caught by Visual Studio

List of various exceptions caught in running .NET processes.

It’s interesting to see that in a period of 10 seconds, Visual Studio threw 9 exceptions that were handled. Of course, this only shows built-in events, and you’re encouraged to build your own events.

New in .NET Framework 4.7.1

It has been possible to log to ETW from a .NET process for some time. More recently, writing event counters has been introduced. You may remember that event counters can be used when the details of log messages are not needed, and there is a great deal of throughput on a section of code. Event counters are not read continuously, but rather sampled, giving us a splash of values from which we can ascertain a trend.

The EventCounter class in System.Diagnostics.Tracing has had an interesting time. It was part of .NET Standard 1.5, but was not a part of full Framework 4.6.1, so there was a little gap. To use it against the full Framework, you’ll have to make use of .NET 4.7.1. Even then, you’ll need to include the System.Diagnostics.Tracing library (dll). As we move to fuller adoption of .NET Standard 2.0, it should be available in more places; however, it is unlikely to be implemented on Linux or macOS because it is unique to the Windows platform.


Stackify Loves Developers

Building an event counter

Following closely on the event counter tutorial in the corefx repository, let’s try building an event counter source example.

Create a new Visual Studio C# project and select .NET Framework 4.7.1. If this option doesn’t exist in your dropdown, you may need to download and manually install .NET Framework 4.7.1.

Screenshot of creating a new Visual Studio C# project and select .NET Framework 4.7.1

Selecting .NET Framework 4.7.1

Our example will be responsible for counting chickens because that’s a thing that changes with great frequency. We’ll need a main method that generates a bunch of events.

static void Main(string[] args) 
{ 
   var eventCounter = ETWLogger.Log; 
   var random = new Random();
 
   Console.WriteLine("Starting application");

   for (int i = 0; i < 10_000; i++) 
   { 
      Thread.Sleep(random.Next(1, 500)); 
      eventCounter.CountChickens(random.Next(1, 5_000)); 
      Console.Write("."); 
   }
 
   Console.WriteLine("Done."); 
   Console.ReadLine(); 
}

Here we’re simply counting a random number of chickens at a random interval. The ETW logger looks like this:

[EventSource(Name = "ChickenEventCounterExample")] 
public sealed class ETWLogger : EventSource 
{ 
   public static ETWLogger Log = new ETWLogger(); 
   private EventCounter _counter; 
 
   private ETWLogger() 
   { 
      this._counter = new EventCounter("chickens", this); 
   } 
 
   public void CountChickens(float numberOfChickens) 
   { 
      WriteEvent(1, "counting chickens before they've hatched", numberOfChickens); 
      this._counter.WriteMetric(numberOfChickens); 
   } 
}

In this class, we inherit from EventSource and annotate our class with the name of the event source (“ChickenEventCounterExample”). In the constructor, we setup a new counter called chickens inside of event source. To view the results of this event counter, we can launch PerfView.

PerfView.exe /onlyproviders=*ChickenEventCounterExample:EventCounterIntervalSec=1 collect

The result of running it for 10 seconds is a collection of captures.

The PerView screen with two new event sources related to our new counter

Two new event sources are shown related to chickens

The first of the two new event sources here is the result of log events writing, and the second of the event counter itself. Digging into the event counter as seen below, we find that each entry contains a few statistics. The mean, standard deviation, count, and range of each polling is shown. Because we’re only polling at 1 second intervals, the counter has been called a number of times.

Screenshot of event counter entry with statistics.

This data can be used to drive reporting, and it is gathered very cheaply.

Counting on Counters

Counters provide a view into your application that might otherwise be difficult to get: gathering statistics on high-frequency events. While this sort of logging is not going to solve every problem, having access to it and being able to enable it for narrow periods adds yet another debugging tool to your toolbelt.

SaveSave

About Simon Timms

Simon is a polyglot developer who has worked on everything from serial port drivers on an Android tablet, to NServiceBus, to processing tens of thousands of messages a second using stream analytics, to building Angular web applications. All that in the last year. He is the author of a number of books on JavaScript and ASP.NET and blogs far less regularly than he should on both the Western Dev's site (http://westerndevs.com) and on his blog (http://blog.simontimms.com). He is also the least visible member of the ASP.NET monsters (http://aspnetmonsters.com).His interests change as frequently as he changes his underwear. At the moment he is interested in F# and how AI is going to change how we develop software. He is a big picture specialist who can maintain a cogent view of an entire system and pick the right technology to solve a problem.
Improve Your Code with Retrace APM

Stackify’s APM tools are used by thousands of .NET, Java, and PHP developers all over the world.
Explore Retrace’s product features to learn more.