Reporting Metrics Using .Net (Core) EventSource and EventCounter
Tags: devops, csharp, monitoring, logging
Published: 2019-01-06 14:22:54

---
title: Reporting Metrics Using .Net (Core) EventSource and EventCounter
published: true
cover_image: https://expecho.blob.core.windows.net/blogposts/appinsights-postbanner.png
description: Reporting Metrics Using .Net (Core) EventSource and EventCounter
tags: DevOps, csharp, monitoring, logging
---

Hardly anybody argues the importance of instrumenting your code and there are some built-in log options in the .Net Framework, not to mention countless great 3rd party libraries like Nlog, Serilog and Log4Net. But when it comes to reporting metrics (Think: requests per minute, usage, message rate and things like that) the built-in support is very limited. Of course we have the Performance Counters but they cannot be used cross-platform as they are Windows only. Luckily there is a relative simple way to report metrics using the EventSource class that is cross-platform and a part of the Framework so there is no need for external dependencies.  

# Introducing EventCounters

ETW (Event Tracing for Windows) and the [`EventSource`](https://docs.microsoft.com/en-us/dotnet/api/system.diagnostics.tracing.eventsource?view=netframework-4.7.2) class have long been a part of the .Net Framework. EventSources are heavily used by the framework itself, and by a lot of (3rd party) libraries as well. It allows you to use structured logging in your application code with a minimal performance overhead. The data can be collected in-process or out-of-process using tools like [PerfView](https://github.com/Microsoft/perfview).

In this blogpost we will take a closer look to the not so well-known `EventCounter` class that lets us define and report metrics using an `EventSource`. I specifically want to show how you can read those counters in-process using an `EventListener` as this is not very well [documented](https://github.com/dotnet/corefx/issues/30988).

As a starter, let us see what the CoreFx team has to say about EventCounters (taken from their [tutorial](https://github.com/dotnet/corefx/blob/master/src/System.Diagnostics.Tracing/documentation/EventCounterTutorial.md)): 

> While EventSource is fast, logging too many events for very frequent events is still a performance hit. In this tutorial, we will introduce EventCounter, a mechanism for measuring performance for very frequent events.

> For event that happen very frequently (for example, if it happen every few milliseconds), in general, you will want the performance overhead per event to be very low (e.g. less than a millisecond), otherwise it is going to cost a significant performance overhead. Logging an event, at the end of the day, need to write something to the disk. If the disk is not fast enough, you will lost events. We need a solution other than logging the event itself.

> When dealing with large number of events, knowing the measure per event is not very useful either. Most of the time all we need is just some statistics out of it. So we could crank the statistics within the process itself and then write an event once in a while to report the statistics, that's what EventCounter will do for us. 

Sounds great, doesn't it? It is a matter of defining and reporting metrics and the framework will do the aggregation and calculation in memory. All we need to do is to specify the interval at which the data is outputted.

# The Recipe

First, we need to define an `EventSource` that will contain the `EventCounter` instances. You can dynamically create `EventCounter` instances at runtime but, due to a bug I documented [here](https://github.com/dotnet/corefx/issues/30904), you will have the create at least one `EventCounter` instance in the constructor.   


```csharp
[EventSource(Name = "My-CustomMetricsEventSource-Minimal")]
public sealed class CustomMetricsEventSource : EventSource
{
    private EventCounter methodDurationCounter;

    private Dictionary<string, EventCounter> dynamicCounters =
        new Dictionary<string, EventCounter>();

    public static CustomMetricsEventSource Log = new CustomMetricsEventSource();

    public CustomMetricsEventSource()
    {
        methodDurationCounter = new EventCounter(nameof(methodDurationCounter), this);
    }

    public void ReportMethodDurationInMs(long milliseconds)
    {
        methodDurationCounter.WriteMetric(milliseconds);
    }

    public void ReportMetric(string name, float value)
    {
        if (!dynamicCounters.TryGetValue(name, out EventCounter counterInstance))
        {
            counterInstance = new EventCounter(name, this);
            dynamicCounters.Add(name, counterInstance);
        }
        counterInstance.WriteMetric(value);
    }
}
```

We will use `CustomMetricsEventSource` to log our metrics in a console application. But we also need a listener that picks up the logged metrics and sends them to a destination. In this example we will write the data to the console using a custom implementation of an `EventListener`:


```csharp
internal class CustomMetricsEventListener : EventListener
{
    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        var counterData = eventData.ToEventCounterData();

        // Only write to console if actual data has been reported
        if (counterData?.Count == 0)
            return;

        Console.WriteLine(
            $"Counter {counterData.Name} reported values " +
            $"Min: {counterData.Min}, " +
            $"Max: {counterData.Max}, " +
            $"Count {counterData.Count}, " +
            $"Mean {counterData.Mean}, " +
            $"StandardDeviation: {counterData.StandardDeviation}, " +
            $"IntervalSec: {counterData.IntervalSec}");
    }
}

```
The code listened above uses the `ToEventCounterData` method. This is actually an extension method. It returns an `EventCounterData` instance which makes it easier to work with the reported metric data:


```csharp
public static class EventWrittenEventArgsExtensions
{
    public static bool IsEventCounter(this EventWrittenEventArgs eventData)
    {
        return eventData.EventName == "EventCounters";
    }

    public static EventCounterData ToEventCounterData(this EventWrittenEventArgs eventData)
    {
        if (!eventData.IsEventCounter())
            return null;

        return new EventCounterData(eventData);
    }
}

public class EventCounterData
{
    public EventCounterData(EventWrittenEventArgs eventData)
    {
        var payload = (IDictionary<string, object>) eventData.Payload[0];

        Name = payload["Name"].ToString();
        Mean = (float)payload["Mean"];
        StandardDeviation = (float)payload["StandardDeviation"];
        Count = (int)payload["Count"];
        IntervalSec = (float)payload["IntervalSec"];
        Min = (float)payload["Min"];
        Max = (float)payload["Max"];
    }

    public string Name { get; }
    public float Mean { get; }
    public float StandardDeviation { get; }
    public int Count { get; }
    public float IntervalSec { get; }
    public float Min { get; }
    public float Max { get; }
}
```

Finally we can create the console application that will call `CustomMetricsEventSource` to log metric values. The `CustomMetricsEventListener` is constructed in such a way that the metrics are outputted once per second. 

It is important to understand that it is the configuration of the `CustomMetricsEventListener` that determines the metric reporting interval. This is done by passing a numeric value specifying the interval in seconds to the `EventCounterIntervalSec` argument.


```csharp
class Program
{
    static void Main(string[] args)
    {
        var reader = new CustomMetricsEventListener();
        var arguments = new Dictionary<string, string>
        {
            {"EventCounterIntervalSec", "1"}
        };
        reader.EnableEvents(CustomMetricsEventSource.Log, EventLevel.LogAlways, EventKeywords.All, arguments);

        var random = new Random();
        for (int i = 0; i <= 10; i++)
        {
            SleepingBeauty(random.Next(10, 200));
        }

        Console.ReadKey();
    }

    static void SleepingBeauty(int sleepTimeInMs)
    {
        var stopwatch = Stopwatch.StartNew();

        Thread.Sleep(sleepTimeInMs);

        stopwatch.Stop();

        CustomMetricsEventSource.Log.ReportMethodDurationInMs(stopwatch.ElapsedMilliseconds);
        CustomMetricsEventSource.Log.ReportMetric("someCounter", DateTime.Now.Millisecond);
    }
}
```

When we run the program we will see the metric values being reported to the console:

> Counter methodDurationCounter reported values Min: 23, Max: 215, Count 8, Mean 113,125, StandardDeviation: 64,10429, IntervalSec: 1,026394

> Counter someCounter reported values Min: 87, Max: 982, Count 9, Mean 603,1111, StandardDeviation: 269,2832, IntervalSec: 1,026394

Do mind that the metrics will always be reported at the specified interval (using `EventCounterIntervalSec`) even if no call to the `WriteMetric` method of an `EventCounter` instance is made. All numeric values, except *IntervalSec*, will have the default value 0.

You can find the whole working example in my GitHub repository:

{% github https://github.com/Expecho/Blog %}


# What is next?

Of course, reporting those values to the console does not add much value, it is up to you to send the data to  your own logging backend. You could for example send them as custom metrics to Application Insights using the [EventCounterCollectionModule](https://docs.microsoft.com/en-us/azure/azure-monitor/app/eventcounters), log to your ELK stack or whatever log system you are using.

I really wish reporting metrics gets a bit more attention since having metrics data available is very important in order to have a detailed insight in how your application is behaving. For example, you can use metrics to scale in or out or get insights in the usage of certain parts of your application. Most logging frameworks I know of do not cater for metrics.

There was a lot of discussion about whether or not the support writing metric using the new `ILogger` interface of .Net Core but in the end there is no support for it right know. More details about the how and the why can be read in the issue created for this discussion:

{% github https://github.com/aspnet/Logging/issues/708 %}