Prometheus Latency Metrics & Exception Logging with Scrutor Decorators

Brick astronaut with camera in the Kalimarmaro, where the first Olympic Games were held. Brick astronaut with camera in the Kalimarmaro, where the first Olympic Games were held.

Ever since I stumbled upon the Scrutor project, I wanted to write a blog about building latency and exception logging decorators. At Wehkamp we used StructureMap in the past, but as it became obsolete and swapped out, I missed the decorators. What I love about Scrutor is how it is an extension on the way Microsoft has implemented dependency injection in .Net Core. This package helps us to create our beloved decorators again.

A big shout-out to my colleague Ionut Stanescu for collaborating on the code.

Why decorators?

Decoration gives our programs some nice traits. It helps with separation of concerns (and decoupling): let's say we want to add latency metrics — why would the original class need to know about Prometheus and metric collection? A decorator can add this trait without having to change the decorated class. Dependency injection does the setup of the decorator and the class.

Packages

We're going to use the following packages:

  • Install-Package Scrutor -Version 3.3.0
    Install-Package prometheus-net -Version 4.2.0
  • dotnet add package Scrutor --version 3.3.0
    dotnet add package prometheus-net --version 4.2.0
  • <PackageReference Include="Scrutor" Version="3.3.0" />
    <PackageReference Include="prometheus-net" Version="4.2.0" />

The Scrutor package implements the decorator feature. The Prometheus package are needed by the latency decorator.

Base decorator

A decorator wraps the decorated object. Let's create an abstract base class that helps us to wrap the decorated object:

using System;

public interface IDecorator
{
    string DecoratedClassName { get; }
}

public abstract class Decorator<TDecorated> : IDecorator
{
    private readonly Lazy<string> _decoratedClassName;
    private readonly Lazy<string> _decoratedFullClassName;

    protected string DecoratedClassName => _decoratedClassName.Value;

    protected string DecoratedFullClassName => _decoratedFullClassName.Value;

    protected TDecorated Decorated { get; }

    protected Decorator(TDecorated decorated)
    {
        Decorated = decorated ?? throw new ArgumentNullException(nameof(decorated));

        _decoratedClassName = new Lazy<string>(GetDecoratedClassName);
        _decoratedFullClassName = new Lazy<string>(GetDecoratedFullClassName);
    }

    protected virtual string GetDecoratedClassName() =>
        (Decorated as IDecorator)?.DecoratedClassName
        ?? Decorated?.GetType().Name
        ?? typeof(TDecorated).Name;

    protected virtual string GetDecoratedFullClassName() =>
        (Decorated as IDecorator)?.DecoratedFullClassName
        ?? Decorated?.GetType().FullName
        ?? typeof(TDecorated).FullName;

    string IDecorator.DecoratedClassName => DecoratedClassName;

    string IDecorator.DecoratedFullClassName => DecoratedFullClassName;
}

We'll be coding metric and logging decorators. It is useful to retrieve the type of the decorated object. When we use multiple decorators at the same interface, it is hard to retrieve the root object. When all decorators have the same base type or interface, it will be easier to retrieve that class name, that's why we're using an IDecorator.

Example interface

Dependency injection usually works with interfaces. An interface is mapped to a concrete class, or instance of a class. Here we have an example of an interface that has multiple methods and a property:

public interface IMyInterface
{
    string MyProperty { get; set; }

    void VoidMethod();

    Task VoidMethodAsync();

    string ReturnMethod();

    Task<string> ReturnMethodAsync();

    bool InOutMethod(int x);

    Task<bool> InOutMethodAsync(int x);
}

Notice how the interface has both synchronous and asynchronous methods.

Latency Decoration

The latency decorator helps us to measure how long methods of the class are taking to execute. These decorators are often used in HTTP client wrappers and storage classes. A rise in latency might indicate that something is wrong.

using Prometheus;
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Runtime.CompilerServices;
using System.Threading.Tasks;

public abstract class LatencyDecorator<TDecorated> : Decorator<TDecorated>
{
    private static readonly Summary _summary = Metrics.CreateSummary(
        "elapsed_time_ms_summary",
        "Records latency of methods.",
        new SummaryConfiguration()
        {
            AgeBuckets = 5,
            BufferSize = 500,
            MaxAge = new TimeSpan(0, 0, 2, 0),
            LabelNames = new[] { "class_name", "method_name" },
            Objectives = new List<QuantileEpsilonPair>
            {
            new QuantileEpsilonPair(0.01, 0.001),
            new QuantileEpsilonPair(0.05, 0.005),
            new QuantileEpsilonPair(0.5, 0.05),
            new QuantileEpsilonPair(0.9, 0.01),
            new QuantileEpsilonPair(0.95, 0.005),
            new QuantileEpsilonPair(0.99, 0.001),
            new QuantileEpsilonPair(0.999, 0.0001)
            }
        });

    protected LatencyDecorator(TDecorated decorated) : base(decorated)
    {
    }

    protected async Task WithMetrics(
        Func<Task> action,
        [CallerMemberName] string methodName = "")
    {
        var stopwatch = Stopwatch.StartNew();
        try
        {
            await action();
        }
        finally
        {
            CollectElapsedTime(methodName, stopwatch);
        }
    }

    protected async Task<TReturn> WithMetrics<TReturn>(
        Func<Task<TReturn>> action,
        [CallerMemberName] string methodName = "")
    {
        var stopwatch = Stopwatch.StartNew();
        try
        {
            return await action();
        }
        finally
        {
            CollectElapsedTime(methodName, stopwatch);
        }
    }

    protected TReturn WithMetrics<TReturn>(
        Func<TReturn> action,
        [CallerMemberName] string methodName = "")
    {
        var stopwatch = Stopwatch.StartNew();
        try
        {
            return action();
        }
        finally
        {
            CollectElapsedTime(methodName, stopwatch);
        }
    }

    protected void WithMetrics(
        Action action,
        [CallerMemberName] string methodName = "")
    {
        var stopwatch = Stopwatch.StartNew();
        try
        {
            action();
        }
        finally
        {
            CollectElapsedTime(methodName, stopwatch);
        }
    }

    protected virtual void CollectElapsedTime(
        string methodName,
        Stopwatch stopwatch)
    {
        stopwatch.Stop();
        _summary.Labels(DecoratedClassName, methodName).Observe(stopwatch.ElapsedMilliseconds);
    }
}

The WithMetric method will wrap the call to the decorator. Note that C# 5.0 automatically infers the name of the method into the methodName argument (because of the CallerMemberName). The class has support for both synchronous and asynchronous methods.

Latency decoration example

Let's look how we can implement the latency decorator for all the elements of our IMyInterface interface:

public class MyInterfaceLatencyDecorator :
    LatencyDecorator<IMyInterface>, IMyInterface
{
    public MyInterfaceLatencyDecorator(IMyInterface decorated) : 
        base(decorated)
    {
    }

    public string MyProperty
    {
        get => WithMetrics(() => Decorated.MyProperty);
        set => WithMetrics(() => Decorated.MyProperty = value);
    }

    public bool InOutMethod(int x) =>
        WithMetrics(() => Decorated.InOutMethod(x));

    public Task<bool> InOutMethodAsync(int x) =>
        WithMetrics(() => Decorated.InOutMethodAsync(x));

    public string ReturnMethod() =>
        WithMetrics(Decorated.ReturnMethod);

    public Task<string> ReturnMethodAsync() =>
        WithMetrics(Decorated.ReturnMethodAsync);

    public void VoidMethod() =>
        WithMetrics(Decorated.VoidMethod);

    public Task VoidMethodAsync() =>
        WithMetrics(Decorated.VoidMethodAsync);
}

Implementing the decorator is compact. This has to do with the fact that the method name does not have to be explicitly specified. Most methods are automatically mapped to Action or Func. Calls with parameters must be wrapped with a lambda.

Exception Logging Decoration

The logging decorator can be build in a similar way. It uses an injected instance of ILogger<T> to do the logging on:

using Microsoft.Extensions.Logging;
using System;
using System.Runtime.CompilerServices;
using System.Threading.Tasks;

public abstract class ExceptionLoggingDecorator<TDecorated> : Decorator<TDecorated>
{
    protected ILogger<TDecorated> Logger { get; }

    protected ExceptionLoggingDecorator(
        TDecorated decorated,
        ILogger<TDecorated> logger) : base(decorated)
    {
        Logger = logger ?? throw new ArgumentNullException(nameof(logger));
    }

    protected async Task WithLogging(
        Func<Task> action,
        [CallerMemberName] string methodName = "")
    {
        try
        {
            await action();
        }
        catch (Exception ex)
        {
            Log(ex, methodName);
            throw;
        }
    }

    protected async Task<TReturn> WithLogging<TReturn>(
        Func<Task<TReturn>> action,
        [CallerMemberName] string methodName = "")
    {
        try
        {
            return await action();
        }
        catch (Exception ex)
        {
            Log(ex, methodName);
            throw;
        }
    }

    protected TReturn WithLogging<TReturn>(
        Func<TReturn> action,
        [CallerMemberName] string methodName = "")
    {
        try
        {
            return action();
        }
        catch (Exception ex)
        {
            Log(ex, methodName);
            throw;
        }
    }

    protected void WithLogging(
        Action action,
        [CallerMemberName] string methodName = "")
    {
        try
        {
            action();
        }
        catch (Exception ex)
        {
            Log(ex, methodName);
            throw;
        }
    }

    protected virtual void Log(Exception ex, string methodName)
    {
        Logger.LogError(ex, $"Exception in {DecoratedClassName}.{methodName}: {ex.Message}");
    }
}

Exception logging decoration example

Implementation is straightforward:

public class MyInterfaceExceptionLoggingDecorator : 
    ExceptionLoggingDecorator<IMyInterface>, IMyInterface
{
    public MyInterfaceExceptionLoggingDecorator(
        IMyInterface decorated,
        ILogger<IMyInterface> logger) : 
        base(decorated, logger)
    {
    }

    public string MyProperty
    {
        get => WithLogging(() => Decorated.MyProperty);
        set => WithLogging(() => Decorated.MyProperty = value);
    }

    public bool InOutMethod(int x) => 
        WithLogging(() => Decorated.InOutMethod(x));

    public Task<bool> InOutMethodAsync(int x) =>
        WithLogging(() => Decorated.InOutMethodAsync(x));

    public string ReturnMethod() =>
        WithLogging(Decorated.ReturnMethod);

    public Task<string> ReturnMethodAsync() =>
        WithLogging(Decorated.ReturnMethodAsync);

    public void VoidMethod() =>
        WithLogging(Decorated.VoidMethod);

    public Task VoidMethodAsync() =>
        WithLogging(Decorated.VoidMethodAsync);
}

Registration of the decorators

The following code will register the example decorators into the DI:

public void ConfigureServices(IServiceCollection services)
{
    // service registrations first

    services.Decorate<IMyInterface, MyInterfaceLatencyDecorator>();
    services.Decorate<IMyInterface, MyInterfaceExceptionLoggingDecorator>();

Conclusion

With Scrutor, writing decorators is easy. If you need a simple way to measure latency, use our latency decorator base class. Exception logging can be easier with our exception logging decorator base class.

Improvements

2021-07-26: Changed the name of the generic from IDecorated to TDecorated. The IDecorated is also an interface, causing confusion.
2021-07-23: Added the DecoratedFullClassName to the base class, at it might come in handy in a later blog.
2021-07-21: Added the Registration of the decorators section.

expand_less