Add handler timing pipeline

Component: NServiceBus
NuGet Package NServiceBus (7.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 it will trigger the threshold occasionally.

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

    public Task Handle(Message message, IMessageHandlerContext context)
    {
        var milliseconds = random.Next(100, 1000);
        log.Info($"Message received going to Task.Delay({milliseconds}ms)");
        return Task.Delay(milliseconds);
    }
}

The Behavior

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

    public override async Task Invoke(IInvokeHandlerContext context, Func<Task> next)
    {
        var stopwatch = Stopwatch.StartNew();
        try
        {
            await next()
                .ConfigureAwait(false);
        }
        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

endpointConfiguration.Pipeline.Register(typeof(HandlerTimerBehavior), "Logs a warning if a handler take more than a specified time");

Related Articles


Last modified