(Time-)Tracing with Unity Interception, Decorators and Reflection

We use tracing to find out what takes us so long when processing X or computing Y. Tracing is a cross-cutting concern. It can be used anywhere in our applications. As such there are some well-known ways to implement it to keep our business code clean such as using hand-crafted decorators or an interception framework of our preference.

This is a non-scientific comparison of three different approaches. One uses Unity’s Interception Extension, two use decorators where one figures out what method it is currently tracing using reflection and the other needs magic strings for the same purpose.

There are many ways to measure the time it takes to perform a certain operation. Below you see the easiest and most convenient way I found over time.

public class TraceTimer : IDisposable
{
  private readonly string operationName;
  private readonly DateTime start = DateTime.Now;
  public TraceTimer()
  {
    StackTrace trace = new StackTrace();
    MethodBase method = trace.GetFrame(1).GetMethod();
    this.operationName = MethodSignatureHelper.GetMethodSignature(method);
  }
  public TraceTimer(string operationName)
  {
    this.operationName = operationName;
  }
  public void Dispose()
  {
    TimeSpan elapsed = DateTime.Now - this.start;
    string msg = string.Format("{0} took {1:F3}s", this.operationName, elapsed.TotalSeconds);
    Debug.WriteLine(msg);
  }
}

And this is how it is used:

using (new TraceTimer("Foo()"))
{
  Foo();
}

Which writes a message like ‘Foo() took 1.038s‘  to the debug console.

Using System.Diagnostics.Debug for writing your measurements is most often not the way you want to go in a real application. You can use a logging framework of your choice instead. But Debug does the job for our purpose here.

The TraceTimer has two constructors. One takes the name of the operation it measures as a parameter. The other extracts the method signature by using a StackFrame.

Unity Interception

Unity uses classes that implement IInterceptionBehavior to intercept calls to a certain target. For this test the behavior looks like this:

public class DummyTracingBehavior : IInterceptionBehavior
{
  public IMethodReturn Invoke(IMethodInvocation input, GetNextInterceptionBehaviorDelegate getNext)
  {
    var methodSignature = MethodSignatureHelper.GetMethodSignature(input.MethodBase);
    using (new TraceTimer(methodSignature))
    {
      return getNext()(input, getNext);
    }
  }
  public IEnumerable<Type> GetRequiredInterfaces() { return Type.EmptyTypes; }
  public bool WillExecute { get { return true; } }
}

And this is the test setup:

var container = new UnityContainer();
container.AddNewExtension<Interception>();
container.RegisterType<IDummy, Dummy>(
  new Interceptor<InterfaceInterceptor>(),
  new InterceptionBehavior<DummyTracingBehavior>());
using (new TraceTimer("WithInterception"))
{
  for (int i = 0; i < NumberOfRunsPerCycle; i++)
  {
    var dummy = container.Resolve<IDummy>();
    dummy.DoIt(i);
  }
}

Hand-crafted Decorator

The decorator implements the same interface as the target and delegates all calls to that target.

public class DummyDecorator : IDummy
{
  private readonly IDummy inner;
  public DummyDecorator(IDummy inner)
  {
    this.inner = inner;
  }
  public string DoIt(int i)
  {
    using (new TraceTimer("DoIt(int)"))
    {
      return this.inner.DoIt(i);
    }
  }
}

It won’t get much simpler than that. And again the test setup:

var container = new UnityContainer();
container.RegisterType<IDummy, Dummy>("Dummy");
container.RegisterType<IDummy, DummyDecorator>(
  new InjectionConstructor(new ResolvedParameter<IDummy>("Dummy")));
using (new TraceTimer("WithDecorator"))
{
  for (int i = 0; i < NumberOfRunsPerCycle; i++)
  {
    var dummy = container.Resolve<IDummy>();
    dummy.DoIt(i);
  }
}

Decorator with Reflection

The second decorator does not rely on magic strings to identify the method name and parameters but uses reflection to figure those details out on its own.

public class DummyDecoratorWithReflection : IDummy
{
  private readonly IDummy inner;
  public DummyDecoratorWithReflection(IDummy inner)
  {
    this.inner = inner;
  }
  public string DoIt(int i)
  {
    using (new TraceTimer())
    {
      return this._inner.DoIt(i);
    }
  }
}

The only thing that differs between the two decorators is the missing string parameter in the constructor call of the TraceTimer. The test setup is identical. Just replace the type DummyDecorator with DummyDecoratorWithReflection.

Prerequisites

For each of the three approaches I set the NumberOfRunsPerCycle to 10,000 and ran 10 cycles for each test.

Each test uses Unity to create a new test object for each run. That is by intention. To work with interception you need Unity anyway. The decorators can be new’ed up which saves you something between 2 and 5% per run. But you will loose Unity’s support for auto-wiring your targets. I prefer convenience and configurability over the last ounce of performance as long as there is no business need for that performance. So whenever possible I use a container to create my objects.

Results

I added up the times measured for each cycle and calculated the average time per cycle. The ranking is as follows:

1. Hand-crafted Decorator with 3.1015s
2. Unity Interception with 3.4265s
3. Decorator with Reflection with 3.5391

The total time taken is not really important as it depends on the machine that runs the tests, the logging framework you use to write your measurements, wether you run the tests as console application or unit-test etc. pp.

But it allows you to compare how one solution performs compared to the others. Not surprisingly the hand-crafted decorator is the fastest solution. But it is also the one with the lowest convenience for your developers. For each target (interface) you want to trace you would have to implement a decorator and you would have to provide the method signature on your own. If that signature changes you would have to change your decorator’s code as well.

Unity’s interception mechanism is about 10% slower than hand-crafted code. But it’s convenience factor is way higher. You write one implementation and all you have to do then is to change your configuration to enable it for arbitrary targets.

Looking at the numbers decorators that use reflection to figure out what is happening seem more like an academic exercise. They are slower than interception but provide less convenience. You have to write a decorator for each target but you don’t get the performance of the first solution. Yet you don’t have to care about changes to the method’s signature. If you can’t use Unity for one reason or another but want to avoid the overhead of maintaining your decorators they might still be a choice. Otherwise I think they are a suboptimal solution.