Handy time measurement with Windsor Castle AOP

This is a good old issue, how to know where the program spends most of its time?

If you want to spend the money, the best profiling tool from my point of view is still JetBrains’ DotTrace. You’ll get a lot of information down on method level, great stuff. But how can the program execution time be measured

when it shall be done always?
when measurement shall be possible to switch on and off?

This sounds like an infrastructural problem? We need a functionality that can measure time and is maybe more precise than the DateTime class. Improving my Google Fu let me get these results: How do I measure how long a method is running. Certainly all the links lead to the unavoidable StopWatch class.

Let’s have a look onto a simple (nonworking) example.

 public void ImportCsv()
 {
    var stopwatch = new Stopwatch();
    stopwatch.Start();
    try
    {
       OpenFile();
       ImportData();
    }
    finally
    {
      CloseFile();
      stopwatch.Stop();
    }
    _log.Info($"ImportCsv execution took {stopWatch.TotalMilliseconds}ms");
 }

This does fit my needs but it really pollutes my code that would be much more readible and simpler without performance measurement:

 public void ImportCsv()
 {
    try
    {
       OpenFile();
       ImportData();
    }
    finally
    {
      CloseFile();
    }
 }

So direct implementation and repeating the same code all over again – creating stopwatch instance, starting instance, stopping and logging can be done more elegant and without polluting code too much. Let’s go the SRP way and implement an own class for measure execution time:

  public class TimeElapsedPerformanceCounter : IDisposable
  {
    private readonly Action<TimeSpan> _action;
    private readonly Stopwatch _stopwatch;

    public TimeElapsedPerformanceCounter(Action<TimeSpan> action)
    {
      _action = action;
      _stopwatch = new Stopwatch();
      _stopwatch.Start();
    }

    public void Dispose()
    {
      _stopwatch.Stop();
      _action(new TimeSpan(_stopwatch.ElapsedTicks));
    }
  }

This approach takes the burden to know how time measurement is done to another class and allows for injecting an action that execution time gets measured. The call to the function looks a little different know, clearly communicating which part is measured and which tells about the results:

 
    using (var timeElapsedPerformanceCounter = new TimeElapsedPerformanceCounter(elapsedTime =>
    {
       _log.Info($"ImportCsv execution took {elapsedTime.TotalMilliseconds}ms");
    }))
    {
       try
       {
          OpenFile();
          ImportData();
       }
       finally
       {   
          CloseFile();
       }
    }

Much better, the actual code didn’t change anymore, it just needs to be encapsulated. The repetition is gone, but the code is still polluted. Because I have to add some lines. What about this approach?

 
 [Interceptor(typeof(TimeElapsedPerformanceCounterInterceptor))]
 internal class CsvImporter : ICsvImporter
 {
    public void Import()
    {
       try
       {
          OpenFile();
          ImportData();
       }
       finally
       {
          CloseFile();
       }
    }
 }

Let’s ignore the fact that the import function doesn’t return the actual result – it is just sample code. The important part for sure is the interceptor attribute of the class. How does it look like?

 
 internal class TimeElapsedPerformanceCounterInterceptor : IInterceptor
 {
     private readonly ILog _log;

     public TimeElapsedPerformanceCounterInterceptor(ILog log)
     {
        _log = log;
        _log.Debug();
     }

     public void Intercept(IInvocation invocation)
     {
          _log.Debug();
          using (var performanceCounter = new TimeElapsedPerformanceCounter(elapsedTime =>           
          {                
               _log.Info($"Execution of method {invocation.TargetType.Name}.{invocation.Method.Name} took {elapsedTime.TotalMilliseconds}ms"); }))
               {
                     invocation.Proceed();
               };
         }
   }

As stated above the interceptor is based on the IInterceptor interface from Windsor Castle. With that implementation we get a lot of benefits:

Code is not polluted at all but decorated
Performance measurement can be easily switch off and on but configuration handled inside of the interceptor
Function can be used cascading, so any part of the program can be measured

But as always this comes to a price. As you can see the CsvImporter class is based on an interface. When there is only one implementation of the importer, an interface sounds like overengineering. With Windsor Castle there are two possibilities to implement AOP/ interceptions:

Either implementing the interface or
making the functions that shall be intercepted being virtual

In any case, choose your death :-D.

Handy time measurement with Windsor Castle AOP

holgerleichsenring