Click here to Skip to main content
Click here to Skip to main content

Unity Interceptor for Performance Instrumentation

, 4 Apr 2013
Rate this:
Please Sign up or sign in to vote.
Unity interception



Introduction 

This interceptor instruments any methods that you wish to measure the performance of. It logs the number of calls, max time and min 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).

Background 

I've used SOLID principles, specifically the open/closed principle to 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 its 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 leasts does one poll in each period interval, so that it process and log what happened in the last period. It also depends on what your 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 other DI containers other than Unity, if they have a 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>>();

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 


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  

I'm looking for work in London so please contact me if you need any microsoft hands on software architecture.

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)

About the Author

Jean-marc Lai
Technical Lead
United Kingdom United Kingdom
Jean-marc is a IT consultant specializing on the microsoft platform. Jean-marc lives in London, UK.

Comments and Discussions

 
QuestionUpdate soon PinmemberJean-marc Lai4-Apr-13 11:13 
AnswerRe: Update soon PinprotectorPete O'Hanlon4-Apr-13 20:32 
AnswerRe: Update soon Pinmember GeekBond 27-Apr-13 22:51 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.

| Advertise | Privacy | Mobile
Web03 | 2.8.140718.1 | Last Updated 4 Apr 2013
Article Copyright 2013 by Jean-marc Lai
Everything else Copyright © CodeProject, 1999-2014
Terms of Service
Layout: fixed | fluid