Unity Interceptor for Performance Instrumentation

• Download source files - 8.1 MB

Introduction

This interceptor instruments any methods that you wish to measure the performance of. It logs the number of calls, maximum time and minimum time within each period interval. It can be configured to minute intervals or hour intervals, or you can write your own. Each interval is defined as a minute by the clock e.g. from 01.00.00 to 1.00.59.59. This allows you to graph out the logs over the day / week, etc. and it will exactly correlate with the time of day (as opposed to minutes from when the program starts).

What is Interception?

Interception is a design pattern (namely the decorator pattern) that alters the functionality of the objects that it is intercepting (or decorating). Unity and other containers have specific mechanisms for dynamically decorating any object without having to write a specific decorator class for each type of object - this mechanism is called interception.

The reason you would want to do this is to design in cross-cutting concerns, part of Aspect Oriented Programming. An often used example of this is logging. If, for example, you wanted to log the performance of any method, if you didn't use any type of design pattern, you would have to write some logging code in each and every method that you wanted to measure the performance of. This would lead to a lot of repetitive code and would dilute the core business code of what actually the method is doing, which would make it hard to read and maintain.

As mentioned before, this article implements a logging cross-cutting concern using Unity and its interceptor mechanism. You may choose PostSharp or another specific AOP framework, or choose a different DI container which has an interceptor mechanism to do this.

Background

I've used SOLID principles, specifically the open/closed principle so it's open to extension (e.g. a new time interval class) but closed to modification.

When a method that has been configured to use the instrumentation interceptor is called, Unity will intercept the call and measure the time it has taken for the call. The interceptor puts this on a queue so it doesn't interfere too much with the main thread of the method call. A separate thread is used to pull the timings off the queue and average it out with calls that happened in the same configured period, as well as noting the maximum and minimum call times. When the interceptor recognises that it's in a 'new' period, it will log the results (of the previous period).

I've designed the thread doesn't need to poll (to process and log) very frequently, in theory as infrequently as to guarantee that it at least does one poll in each period interval, so that it processes and logs what happened in the last period. It also depends on what you are instrumenting, if the method is called very often, it may make sense to increase the polling so that the queue doesn't get too large. As a default, I've set it to 1/3 of the period (20 seconds for minute periods and 20 minutes for hourly periods).

I've abstracted out the actual work into an interface IAsychInterceptor (which is an interface to PerformanceLogger), so this can be used for DI containers other than Unity, if they have an interception mechanism. It would be possible to add another class that performed a same role as InstrumentationCallHandler, but for the different DI container. IAsychInterceptor is a generic class - it templates on any class of type TEventArgs - basically specifying the type of event args the interface will return when the asynchronous operation completes.

Using the logs, you can graph out the performance of the methods being monitored measured against the actual time of day, dynamically if for example instead of logging to a file, it logs to a database (just configure log4net for this).

Using the Code

To use the interceptor, configure Unity either using XML configuration or code configuration. The key parts are registering the type you want instrumented with an interceptor. Then defining a policy. Here, I'm saying to instrument the IOrderService type, and type match on IOrderService, and only on the method Authorise. I've used policy based interception to target a specific method, but you can use interface interception too, in which case you would have to have a different class to implement the correct interface interception interface similar to InstrumentationCallHandler, and configure it differently.

<register type="IOrderService" mapTo="OrderService">
  <interceptor type="InterfaceInterceptor" />
  <interceptionBehavior type="PolicyInjectionBehavior"/>
</register> <span style="font-size: 9pt;">      </span>

<interception>
  <policy name="InstumentationPolicy">
    <matchingRule name="TypeMatch" type="TypeMatchingRule">
      <constructor>
        <param name="typeName" value ="IOrderService"/>
      </constructor>
    </matchingRule>
    <matchingRule name="MemberMatch" type="MemberNameMatchingRule">
      <constructor>
        <param name="nameToMatch" value="Purchase">
        </param>
      </constructor>
    </matchingRule>
    <callHandler name="Handler" type="InstrumentationCallHandler">
      <lifetime type="singleton"/>
    </callHandler>
  </policy>
</interception>

Then just use Unity to resolve your interface to a concrete class and call it as you would normally:

var performanceLogging = unityContainer.Resolve<IAsynchInterceptor<LoggedEventArgs>>();

Results

The log file will look like this:

2013-03-20 20:41:47,066 [11] DEBUG Purchase [(null)] - 20 calls in previous minute. 
Slowest: 29627.1982ms, Fastest: 1000.1604ms, Average: 2433.719805ms
2013-03-20 20:42:15,229 [11] DEBUG Purchase [(null)] - 0 calls in previous minute. 
Slowest: 0ms, Fastest: 0ms, Average: 0ms</span>
2013-03-20 20:43:13,201 [11] DEBUG Purchase [(null)] - 6 calls in previous minute. 
Slowest: 1000.3109ms, Fastest: 1000.1399ms, Average: 1001.54535ms</span>
2013-03-20 20:44:13,258 [11] DEBUG Purchase [(null)] - 60 calls in previous minute. 
Slowest: 1000.2761ms, Fastest: 1000.12ms, Average: 1000.68573333333ms</span>
2013-03-20 20:45:13,259 [11] DEBUG Purchase [(null)] - 60 calls in previous minute. 
Slowest: 1000.4533ms, Fastest: 1000.1001ms, Average: 1000.595075ms
2013-03-20 20:46:13,262 [11] DEBUG Purchase [(null)] - 24 calls in previous minute. 
Slowest: 1000.704ms, Fastest: 1000.0908ms, Average: 1000.52014583333ms
2013-03-20 20:47:13,276 [11] DEBUG Purchase [(null)] - 0 calls in previous minute. 
Slowest: 0ms, Fastest: 0ms, Average: 0ms  

You can if you wish then create a graph like the following to help analyse the performance over time (24 hours in this case (note each log line shows results of the previous period so you have to adjust for this). Even better would be to configure log4net to write to a table which say a front end program/web page could read the results and produce the graph for you in real time.

The above results show that there are 2 peaks around about 09:00 and 17:00 hours, with a correlation in increased transaction times. There is also an unexpected increase in transaction times at 02:00. There are no transactions between 03:00 and 05:00. There is also quite a significant gap between minimum and maximum times.

The interpretation of this (as part of an investigation exercise to improve performance) may conclude:

1. Is there some job running around 02:00 on the servers that hinder performance? Can this job be moved to a different server or improved? Also, since there are no transactions between 03:00 and 05:00, if there is a job running can be moved to 04:00.
2. Investigate why there is a significant difference between minimum and maximum times - maybe an issue with caching.
3. Is it possible to expand compute resources just for around 09:00 and 17:00 (for example, if using cloud based hosting)?

Hopefully, the above illustration shows that this interceptor can be of use to help performance investigations.

Design

The solution is made up of the following projects

• JML.Main, a console application. You can run this to see it working.
• JML.OrderService, containing code that needs to be intercepted
• JML.Framework, containing interception logging code
• JML.Framework.Tests, unit tests to test framework

Note it is written using Visual Studio 2012.

The solution has the following references added using NuGet:

• Unity
• Unity Interception
• Moq
• Log4Net

If you download the non-EXE version, you may have to source the references yourself.

Points of Interest

It was quite tricky to think about time from one period to another, to make sure it logs what happened in the last period as well as allowing it to process the queue for timings within the same period.

I'm planning to add different types of logging for:

• top 10 slowest methods across any objects
• log parameters when an error occurs

Changes you can make:

• You can log to a database instead by reconfiguring log4net.
• You can use code configuration instead of XML - this would allow you to turn logging on and off by adding/removing the interceptor dynamically.

History

• 4^th April, 2013: Initial version