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).
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" />
</register> <span style="font-size: 9pt;"> </span>
<matchingRule name="TypeMatch" type="TypeMatchingRule">
<param name="typeName" value ="IOrderService"/>
<matchingRule name="MemberMatch" type="MemberNameMatchingRule">
<param name="nameToMatch" value="Purchase">
<callHandler name="Handler" type="InstrumentationCallHandler">
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  DEBUG Purchase [(null)] - 20 calls in previous minute. Slowest: 29627.1982ms, Fastest: 1000.1604ms, Average: 2433.719805ms
2013-03-20 20:42:15,229  DEBUG Purchase [(null)] - 0 calls in previous minute. Slowest: 0ms, Fastest: 0ms, Average: 0ms</span>
2013-03-20 20:43:13,201  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  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  DEBUG Purchase [(null)] - 60 calls in previous minute. Slowest: 1000.4533ms, Fastest: 1000.1001ms, Average: 1000.595075ms
2013-03-20 20:46:13,262  DEBUG Purchase [(null)] - 24 calls in previous minute. Slowest: 1000.704ms, Fastest: 1000.0908ms, Average: 1000.52014583333ms
2013-03-20 20:47:13,276  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:
If you download the non-exe version you may have to source the references yourself.
- Unity Interception
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.
I'm looking for work in London so please contact me if you need any microsoft hands on software architecture.