Add handler timing pipeline

Component: NServiceBus
NuGet NServiceBus (5.x)

Introduction

This sample leverages the pipeline to add timing to handlers. It injects a Behavior into the pipeline before a handler is executed and uses a Stopwatch to measure how long a handler takes and then log a warning if the handler execution exceeds a specified threshold.

The Handler

The handler sleeps for a random amount of time so as to sometimes trigger the threshold.

public class Handler1 :
    IHandleMessages<Message>
{
    static ILog log = LogManager.GetLogger<Handler1>();
    static Random random = new Random();

    public void Handle(Message message)
    {
        var milliseconds = random.Next(100, 1000);
        log.Info($"Message received going to Thread.Sleep({milliseconds}ms)");
        Thread.Sleep(milliseconds);
    }
}

The Behavior

class HandlerTimerBehavior :
    IBehavior<IncomingContext>
{
    static ILog log = LogManager.GetLogger<HandlerTimerBehavior>();

    public void Invoke(IncomingContext context, Action next)
    {
        var stopwatch = Stopwatch.StartNew();
        try
        {
            next();
        }
        finally
        {
            var elapsedMilliseconds = stopwatch.ElapsedMilliseconds;
            if (elapsedMilliseconds > 500)
            {
                var handlerName = context.MessageHandler.Instance.GetType().Name;
                log.Warn($"{handlerName} took {elapsedMilliseconds}ms to process");
            }
        }
    }
}

Configuring the Pipeline

public class HandlerTimerFeature :
    Feature
{
    internal HandlerTimerFeature()
    {
        EnableByDefault();
    }

    protected override void Setup(FeatureConfigurationContext context)
    {
        context.Pipeline.Register<Registration>();
    }

    public class Registration :
        RegisterStep
    {
        public Registration()
            : base(
                stepId: "HandlerTimer",
                behavior: typeof(HandlerTimerBehavior),
                description: "Logs a warning if a handler take more than a specified time")
        {
            InsertBefore(WellKnownStep.InvokeHandlers);
        }
    }
}

Related Articles


Last modified