I wish to implement switchable code timing facilities in my production code, the idea being that when performance issues are occurring on a user machine the performance logging can be turned on to provide useful data to indicate where issues are.
To this end my logic would be to have a factory class that would implement a bool property TrackPerformance and a method GetPerformanceTracker that returns either of NullPerformanceTracker or LoggingPerformanceTracker that implement an IPerformanceTracker interface.
The Null is obviously there to do nothing and the other would write out to a Log4Net logger which could potentially be split out from the normal logging if required. I'd use the StopWatch class for timings. So far so good.
The issue?
How best to implement this without it overly affecting performance itself? I'm thinking of using compiler services attributes on a MarkElapsedTime method as
MarkElapsedTime(string message, [CallerMemberName] callerMemberName = "", [CallerLineNumber] int = 0)
Instantiating a timer at method level seems sub-optimal due to the number of factory calls. It therefore seems to be preferable to instantiate this at a class level, in which case I need to tie the MarkElapsedTime call to the relevant Start() call in order to measure the correct amount of elapsed time. Loosely
class LoggingPerformanceTracker:IPerformanceTracker
{
private readonly ILog mLogger = LogManager.GetLogger(....);
private readonly StopWatch mStopWatch = new StopWatch();
private readonly Dictionary<int, TimeSpan> mElapsed = new Dictionary<int, TimeSpan>();
private int mNextId = 0;
public void MarkElapsedTime(int timerId, string message, [CallerMemberName] callerMemberName = "", [CallerLineNumber] int = 0)
{
var ts = mStopWatch.Elapsed.Subtract(mElapsed[timerId]);
if (mLogger.IsInfoEnabled)
mLogger.Info(string.Format("{0}: {1} - [{2}({3})]", message, ts, callerMemberName, callerLineNumber));
}
public int Start()
{
if (!mStopWatch.IsRunning)
mStopWatch.Start();
var key = mNextId;
mNextId++;
mElapsed.Add(key, mStopWatch.Elapsed);
return key;
}
}
I've not had to do this before and given that these measurement calls would be placed all over the codebase in key areas I'd ideally like to get it right first time. Also is the use of the Log4Net logger a good or bad idea - I obviously need to see the data at some point whether that means logging in memory then dumping or sending to file straight off.
So here's how to do some dependency injection to solve this issue.
First, let's just say we have this code:
public class DoSomeWork
{
public void Execute()
{
Console.WriteLine("Starting");
Thread.Sleep(500);
Console.WriteLine("Done");
}
}
It's piece of code that performs some (potentially) long running task.
We might call it like this:
static void Main(string[] args)
{
var doSomeWork = new DoSomeWork();
doSomeWork.Execute();
Console.ReadLine();
}
Now, to add logging I could go thru the code base and add code like this:
public class DoSomeWork
{
public void Execute()
{
var sw = Stopwatch.StartNew();
Console.WriteLine("Starting");
Thread.Sleep(500);
Console.WriteLine("Done");
Console.WriteLine(sw.ElapsedMilliseconds);
}
}
But this means that if I want to add logging code to the entire code base I'm editing a lot of files and making my code more complicated.
There is a way to make this work without adding the logging code to each file.
To start with we need to introduce an interface with the Execute method to abstract the code we're calling.
public interface IDoSomeWork
{
void Execute();
}
Now the DoSomeWork class looks like this:
public class DoSomeWork : IDoSomeWork
{
public void Execute()
{
Console.WriteLine("Starting");
Thread.Sleep(500);
Console.WriteLine("Done");
}
}
Now the calling code looks like this:
static void Main(string[] args)
{
var context = Context.CreateRoot();
context.SetFactory<IDoSomeWork, DoSomeWork>();
var doSomeWork = context.Resolve<IDoSomeWork>();
doSomeWork.Execute();
Console.ReadLine();
}
Now, I've used a dependency injection framework that I wrote for this, but you could use Castle Windsor, Ninject, etc.
The line Context.CreateRoot() creates a dependency injection container. The context.SetFactory<IDoSomeWork, DoSomeWork>() configures the container to know that when I ask for an instance of IDoSomeWork to actually return an instance of DoSomeWork.
The line var doSomeWork = context.Resolve<IDoSomeWork>() asks to container to try to resolve (create or return) an instance of an object that implements IDoSomeWork.
From there the code runs like the original code.
Now I can write a logging class that "decorates" the concrete class.
public class DoSomeWorkLogger : IDoSomeWork, IDecorator<IDoSomeWork>
{
public void Execute()
{
var sw = Stopwatch.StartNew();
this.Inner.Execute();
Console.WriteLine(sw.ElapsedMilliseconds);
}
public IDoSomeWork Inner { get; set; }
}
This class implements IDoSomeWork as well as a special interface IDecorator<IDoSomeWork> required by my container to allow this class to act as a decorator.
So now the calling code looks like this:
static void Main(string[] args)
{
var context = Context.CreateRoot();
context.SetFactory<IDoSomeWork, DoSomeWork>();
context.SetDecorator<IDoSomeWork, DoSomeWorkLogger>();
var doSomeWork = context.Resolve<IDoSomeWork>();
doSomeWork.Execute();
Console.ReadLine();
}
The line context.SetDecorator<IDoSomeWork, DoSomeWorkLogger>() now tells the container that there is a decorator for the IDoSomeWork interface.
So what now happens when the line var doSomeWork = context.Resolve<IDoSomeWork>() is called is that an instance of DoSomeWork is created like before, but also an instance of DoSomeWorkLogger is created. The Inner property of the DoSomeWorkLogger instance is set with the instance of the DoSomeWork and the DoSomeWorkLogger instance is returned from the Resolve method.
So now when the doSomeWork.Execute() method is call then the logger code is run which in turn calls the actual execute code.
The DoSomeWork code doesn't need to change for me to add the logging functionality.
Now this code as it stands isn't perfect yet as we have all of the SetFactory and SetDecorator code that would create dependencies that we want to avoid.
So here's how we get around it.
First the IDoSomeWork, DoSomeWork, and DoSomeWorkLogger code are moved into three separate assemblies.
Then DoSomeWork and DoSomeWorkLogger have two special attributes added. They look like this:
[Factory(typeof(IDoSomeWork))]
public class DoSomeWork : IDoSomeWork { ... }
[Decorator(typeof(IDoSomeWork))]
public class DoSomeWorkLogger : IDoSomeWork, IDecorator<IDoSomeWork> { ... }
Now I can change the calling code to this:
static void Main(string[] args)
{
var config = XDocument.Load(@"fileName");
var context = Context.LoadRoot(config);
var doSomeWork = context.Resolve<IDoSomeWork>();
doSomeWork.Execute();
Console.ReadLine();
}
The container is now configured using an XML file. The format of the XML isn't important, but what is is that it can be changed without recompiling the code. So by changing the XML to not include the assembly that the DoSomeWorkLogger class is defined in will effectively remove the logging. Add that assembly and instantly the logging code is added back in with no recompilation necessary.
Simple. :-)