One of my readers recently asked me an interesting question. It relates to my book's chapter about Interception (chapter 9) and Decorators and how they can be used for instrumentation-like purposes.

In an earlier blog post we saw how we can use Decorators to implement Cross-Cutting Concerns, but the question relates to how a set of Decorators can be used to log additional information about code execution, such as the time before and after a method is called, the name of the method and so on.

A Decorator can excellently address such a concern as well, as we will see here. Let us first define an IRegistrar interface and create an implementation like this:

public class ConsoleRegistrar : IRegistrar
{
    public void Register(Guid id, string text)
    {
        var now = DateTimeOffset.Now;
        Console.WriteLine("{0}\t{1:s}.{2}\t{3}",
            id, now, now.Millisecond, text);
    }
}

Although this implementation ‘logs' to the Console, I'm sure you can imagine other implementations. The point is that given this interface, we can add all sorts of ambient information such as the thread ID, the name of the current principal, the current culture and whatnot, while the text string variable still gives us an option to log more information. If we want a more detailed API, we can just make it more detailed - after all, the IRegistrar interface is just an example.

We now know how to register events, but are seemingly no nearer to instrumenting an application. How do we do that? Let us see how we can instrument the OrderProcessor class that I have described several times in past posts.

At the place I left off, the OrderProcessor class uses Constructor Injection all the way down. Although I would normally prefer using a DI Container to auto-wire it, here's a manual composition using Pure DI just to remind you of the general structure of the class and its dependencies:

var sut = new OrderProcessor(
    new OrderValidator(), 
    new OrderShipper(),
    new OrderCollector(
        new AccountsReceivable(),
        new RateExchange(),
        new UserContext()));

All the dependencies injected into the OrderProcessor instance implement interfaces on which OrderProcessor relies. This means that we can decorate each concrete dependency with an implementation that instruments it.

Here's an example that instruments the IOrderProcessor interface itself:

public class InstrumentedOrderProcessor : IOrderProcessor
{
    private readonly IOrderProcessor orderProcessor;
    private readonly IRegistrar registrar;
 
    public InstrumentedOrderProcessor(
        IOrderProcessor processor,
        IRegistrar registrar)
    {
        if (processor == null)
        {
            throw new ArgumentNullException("processor");
        }
        if (registrar == null)
        {
            throw new ArgumentNullException("registrar");
        }
 
        this.orderProcessor = processor;
        this.registrar = registrar;
    }
 
    #region IOrderProcessor Members
 
    public SuccessResult Process(Order order)
    {
        var correlationId = Guid.NewGuid();
        this.registrar.Register(correlationId,
            string.Format("Process begins ({0})",
                this.orderProcessor.GetType().Name));
 
        var result = this.orderProcessor.Process(order);
 
        this.registrar.Register(correlationId,
            string.Format("Process ends   ({0})", 
            this.orderProcessor.GetType().Name));
 
        return result;
    }
 
    #endregion
}

That looks like quite a mouthful, but it's really quite simple - the cyclomatic complexity of the Process method is as low as it can be: 1. We really just register the Process method call before and after invoking the decorated IOrderProcessor.

Without changing anything else than the composition itself, we can now instrument the IOrderProcessor interface:

var registrar = new ConsoleRegistrar();
var sut = new InstrumentedOrderProcessor(
    new OrderProcessor(
        new OrderValidator(),
        new OrderShipper(),
        new OrderCollector(
            new AccountsReceivable(),
            new RateExchange(),
            new UserContext())),
    registrar);

However, imagine implementing an InstrumentedXyz for every IXyz and compose the application with them. It's possible, but it's going to get old really fast - not to mention that it massively violates the DRY principle.

Fortunately we can solve this issue with any DI Container that supports dynamic interception. Castle Windsor does, so let's see how that could work.

Instead of implementing the same code ‘template' over and over again to instrument an interface, we can do it once and for all with an interceptor. Imagine that we delete the InstrumentedOrderProcessor; instead, we create this:

public class InstrumentingInterceptor : IInterceptor
{
    private readonly IRegistrar registrar;
 
    public InstrumentingInterceptor(IRegistrar registrar)
    {
        if (registrar == null)
        {
            throw new ArgumentNullException("registrar");
        }
 
        this.registrar = registrar;
    }
 
    #region IInterceptor Members
 
    public void Intercept(IInvocation invocation)
    {
        var correlationId = Guid.NewGuid();
        this.registrar.Register(correlationId, 
            string.Format("{0} begins ({1})", 
                invocation.Method.Name,
                invocation.TargetType.Name));
 
        invocation.Proceed();
 
        this.registrar.Register(correlationId,
            string.Format("{0} ends   ({1})", 
                invocation.Method.Name, 
                invocation.TargetType.Name));
    }
 
    #endregion
}

If you compare this to the Process method of InstrumentedOrderProcessor (that we don't need anymore), you should be able to see that they are very similar. In this version, we just use the invocation argument to retrieve information about the decorated method.

We can now add InstrumentingInterceptor to a WindsorContainer and enable it for all appropriate components. When we do that and invoke the Process method on the resolved IOrderProcessor, we get a result like this:

bbb9724e-0fad-4b06-9bb0-b8c1c460cded    2010-09-20T21:01:16.744    Process begins (OrderProcessor)
43349d42-a463-463b-8ddf-e569e3170c97    2010-09-20T21:01:16.745    Validate begins (TrueOrderValidator)
43349d42-a463-463b-8ddf-e569e3170c97    2010-09-20T21:01:16.745    Validate ends   (TrueOrderValidator)
44fdccc8-f12d-4057-ae03-791225686504    2010-09-20T21:01:16.746    Collect begins (OrderCollector)
8bbb1a0c-6134-4652-a4af-cd8c0c7184a0    2010-09-20T21:01:16.746    GetCurrentUser begins (UserContext)
8bbb1a0c-6134-4652-a4af-cd8c0c7184a0    2010-09-20T21:01:16.747    GetCurrentUser ends   (UserContext)
d54359ff-8c32-487f-8728-b19ff0bf4942    2010-09-20T21:01:16.747    GetCurrentUser begins (UserContext)
d54359ff-8c32-487f-8728-b19ff0bf4942    2010-09-20T21:01:16.747    GetCurrentUser ends   (UserContext)
c54c4506-23a8-4553-ba9a-066fc64252d2    2010-09-20T21:01:16.748    GetSelectedCurrency begins (UserContext)
c54c4506-23a8-4553-ba9a-066fc64252d2    2010-09-20T21:01:16.748    GetSelectedCurrency ends   (UserContext)
b3dba76b-6b4e-44fa-aca5-52b2d8509db3    2010-09-20T21:01:16.750    Convert begins (RateExchange)
b3dba76b-6b4e-44fa-aca5-52b2d8509db3    2010-09-20T21:01:16.751    Convert ends   (RateExchange)
e07765bd-fe07-4486-96f1-f74d77241343    2010-09-20T21:01:16.751    Collect begins (AccountsReceivable)
e07765bd-fe07-4486-96f1-f74d77241343    2010-09-20T21:01:16.752    Collect ends   (AccountsReceivable)
44fdccc8-f12d-4057-ae03-791225686504    2010-09-20T21:01:16.752    Collect ends   (OrderCollector)
231055d3-4ebb-425d-8d69-fb9c85d9a860    2010-09-20T21:01:16.752    Ship begins (OrderShipper)
231055d3-4ebb-425d-8d69-fb9c85d9a860    2010-09-20T21:01:16.753    Ship ends   (OrderShipper)
bbb9724e-0fad-4b06-9bb0-b8c1c460cded    2010-09-20T21:01:16.753    Process ends   (OrderProcessor)

Notice how we care easily see where and when method calls begin and end using the descriptive text as well as the correlation id. I will leave it as an exercise for the reader to come up with an API that provides better parsing options etc.

As a final note it's worth pointing out that this way of instrumenting an application (or part of it) can be done following the Open/Closed Principle. I never changed the original implementation of any of the components.



Wish to comment?

You can add a comment to this post by sending me a pull request. Alternatively, you can discuss this post on Twitter or somewhere else with a permalink. Ping me with the link, and I may respond.

Published

Monday, 20 September 2010 19:18:21 UTC

Tags



"Our team wholeheartedly endorses Mark. His expert service provides tremendous value."
Hire me!
Published: Monday, 20 September 2010 19:18:21 UTC