Execution Timer

• Download source files - 18.6 Kb

Introduction

Most coders do some kind of rudimentary performance testing from time to time. The most common of which is probably comparing the execution times of two or more methods to see which one is most efficient.

While it is not difficult to implement these sorts of comparative tests (they are sometimes no more than 5-6 lines of code, including writing the results out to the console), I thought it would be a good idea to write a little library to not only make it quicker and easier to duplicate what many already do, but to enable a few slightly more involved scenarios.

Classes in this library

• ExectuionTimer - This is the main class. It contains functions to time the execution of methods and display the results.
• ExecutionTimerCollection - This is, well, a collection of ExecutionTimer objects.
• ExecutionTimerManager - This class is used to manage a group of ExecutionTimers.
• BlockTimer - This class implements the IDisposable interface and exists to be used with the C# 'using' statement.
• TimedMethod - This class holds references to one or more delegates, whose target methods will be timed.
• TimedMethodCollection - A collection of TimedMethod objects.
• NameExistsExcpetion - Occurs when an ExecutionTimer is added to an ExecutionTimerManager that already contains a timer with the same name.
• SeriesAbortedException - Occurs when a TimerManagerException could not run a series.

I won't cover everything in this article; I'll try to just hit the high points.

The BlockTimer Class

The most direct way of measuring the execution time of a method is to simply record the system's tick count immediately before and after the method being timed is executed:

// This is the method we'll be timing throughout the article

void TakeOneSecond()
{
  System.Threading.Thread.Sleep(1000);
}
 
long start = DateTime.Now.Ticks;
MethodToTime();
long end = DateTime.Now.Ticks;
 
long executionTime = end - start;
 
Console.WriteLine("MethodToTime took {0} ticks to execute.", 
                                             executionTime);

Now, that certainly wasn't difficult, but it can be even easier. The ExecutionTimer's (introduced shortly) static TimeBlock returns a BlockTimer object which implements IDisposable. Here is the BlockTimer class, in its entirety:

public class BlockTimer : IDisposable
{
   private string _description;
   private long    _start;
 
   public BlockTimer(string description)
   {
      _description = description;
      _start = DateTime.Now.Ticks;
   }
 
   public void Dispose()
   {
      long totalTime = DateTime.Now.Ticks - _start;
      Console.WriteLine(_description);
      Console.Write(" - Total Execution Time: ");
      Console.Write(new TimeSpan(totalTime).TotalMilliseconds.ToString());
      Console.WriteLine(" ms.");
   }
}

That tiny class allows the last example to be rewritten like this:

using(ExecutionTimer.TimeBlock("MethodToTime"))
{
   TakeOneSecond();
}
 
// Output:

// Timer for TakeOneSecond

//  - Total Execution Time: 1000 ms.

Note: The output from BlockTimer is in milliseconds because I thought that would be more useful than ticks.

If all you need is to replace the 3-4 lines of code with one line and a couple of curly braces, you're good to go. However, if you'd like more control over the output and/or how something gets timed, there's much more in store.

The ExecutionTimer Class

The main class in this library is the ExecutionTimer class. The simplest use of this class is as follows (this code doesn't really gain you anything over using the BlockTimer):

ExecutionTimer timer = new ExecutionTimer("TakeOneSecond");
timer.Start();

// run the method being timed

TakeOneSecond();

timer.Stop();

// Write the results

// Note: Setting ExecutionTimer.AutoTrace to true

// would cause this to be called automatically when

// the timer is stopped.

Timer.Write();

// Output:

// ***********************

// Execution time for "TakeOneSecond" (Run 1): 1000 ms.

One way to ensure more accurate results when running any performance test is to run it multiple times. The ExecutionTimer class supports that by adding previous runs to a series when Start and Stop are called multiple times. Here's an example of running a series:

// We'll pass true as the second parameter so each run will

// be written to the Console automatically

ExecutionTimer timer = new ExecutionTimer("TakeOneSecond", true);

// We'll do three runs

for(int i = 0; i < 3; i++)
{
   timer.Start();
   TakeOneSecond();
   timer.Stop();
}

// Write the statistics for the series

timer.WriteSeries();

// Output:

// ***********************

// Execution time for "TakeOneSecond" (Run 1): 1000 ms.

//

// ***********************

// Execution time for "TakeOneSecond" (Run 2): 1000 ms.

//

// ***********************

// Execution time for "TakeOneSecond" (Run 3): 1000 ms.

//

// ***********************

// Stats for "TakeOneSecond":

// - Number of runs completed: 3

// - Average execution time per run: 1000 ms.

// - Shortest run: 1000 ms.

// - Longest run: 1000 ms.

Now, you not only get the results for each individual run (if AutoTrace is set to true), but you also get the total number of runs, average execution time, and shortest and longest runs.

There are a couple of different ways to alter the way results are output. The ExecutionTimer class has BeginDelim and EndDelim properties which you can use to specify what gets printed before and after the results for each run, as well as SeriesBeginDelim and SeriesEndDelim, which do the same for series results. As you can see from the previous example, the default string for BeginDelim and SeriesBeginDelim is "***********************", and an empty string for EndDelim and SeriesEndDelim.

Each of the properties just mentioned also has a "companion" property that is a delegate of type PrintString that will be used in place of the delimiting strings, if defined. The names of the companion properties are (not surprisingly) BeginPrintString, EndPrintString, SeriesBeginPrintString, and SeriesEndPrintString. Here is the definition of the PrintString delegate:

public delegate string PrintString(string timerName);

The parameter passed to the PrintString delegate is the name of the timer in question. Here's an example of how to use the *Delim and *PrintString properties:

private string GetExecutionDate(string timerName)
{
   string header = timerName + " is being timed on ";
   header += DateTime.Now.ToShortDateString();
   header += " at ";
   header += DateTime.Now.ToLongTimeString();
   return header; 
}

ExecutionTimer timer = new ExecutionTimer("Example", true);

// Set the method to be called before each run is printed

timer.BeginPrintString = new PrintString(GetExecutionDate);

// Set the string to be written before the series results are written

timer.SeriesBeginDelim = "Running series with blah, blah set to something";
timer.Start();
TakeOneSecond();
timer.Stop();

timer.WriteSeries();

In order to talk about some of the other features of the ExecutionTimer class, I need to introduce another class first. Namely, the TimedMethod class.

The TimedMethod Class

The TimedMethod class exists to facilitate the use of delegates to represent the methods to time. The Method property of TimedMethod represents the main method being timed by the ExecutionTimer. Just to clarify what I mean, here's a small example showing a use of ExecutionTimer I've already shown, as well as the equivalent use of TimedMethod:

ExecutionTimer timer = new ExecutionTimer("TakeOneSecond", true);

for(int i = 0; i < 3; i++)
{
   timer.Start();
   TakeOneSecond();
   timer.Stop();
}

timer.WriteSeries();

// Now do the same thing with delegates

ExecutionTimer timerWithDelegates = new ExecutionTimer("With Delegates", true");

// We'll pass the
timerWithDelegates.Method = new TimedMethod(new MethodInvoker(TakeOneSecond), 3);

timerWithDelegates.RunTimedMethod();

As you can probably deduce from the above example, the RunTimedMethod method of ExecutionTimer runs the method targeted by the specified delegate for the specified number of iterations, calling Start and Stop before and after each run.

I've used the MethodInvoker delegate here, which is defined in the System.Windows.Forms namespace, but the Method property of TimedMethod is of the base type Delegate so you can use whatever delegate is appropriate. If your delegate requires arguments, you can pass them via the Args property of TimedMethod.

The method we've been timing up till now (TakeOneSecond) does not change the state of any object, and can be called multiple times back-to-back and produce the same results. However, this is not the case if the method being timed alters something which needs to be reset before the method can be run again. To this end, the TimedMethod class defines two more delegate properties: SetUp and TearDown, which are called before and after the method being timed, respectively. Both properties also have companion properties (SetUpArgs and TearDownArgs) representing the arguments to be passed to those methods, if any.

Back to the ExecutionTimer Class

Up until now, all results have been written to the Console. However, the ExecutionTimer class has an Out property, which is of type TextWriter. This can be used to redirect the output to where ever is most appropriate, such as to a string for presentation in a message box, or to a text file, or to be parsed and entered into a database.

ExecutionTimer timer = new ExecutionTimer("Example", true);

// Instead of writing to the console, we'll write to a file

StreamWriter writer = new StreamWriter("Execution Results.log");

timer.Out = writer;

timer.TimedMethod = new TimedMethod("Method 1", 
                    new MethodInvoker(TakeOnSecond), 100));

timer.RunTimedMethod();

writer.Close();

Events of the ExecutionTimer Class

The ExecutionTimer class defines six events, which are TimerStarting, TimerStopped (there are no corresponding TimerStarted and TimerStopping events because they would alter the recorded execution time), ResultsPrinting, ResultsPrinted, SeriesResultsPrinting, and SeriesResultsPrinted.

They can be used to alter the properties of the ExecutionTimer, such as where the results will be printed, delimiter strings, etc., based on what is about to be printed, or the execution time of the most recent run, or whatever else you deem appropriate.

The ExecutionTimerManager Class

void RunManager()
{
   TimedMethodCollection methods = new TimedMethodCollection();
 
   methods.Add(new TimedMethod("No args", 
               new MethodInvoker(MethodToTime), 100)); 
   methods.Add(new TimedMethod("Int arg", 
               new VoidIntArg(MethodToTime), new object[]{10}, 100));
   methods.Add(new TimedMethod("String arg", 
               new VoidStringArg(MethodToTime), new object[]{" "}, 100));
        
   ExecutionTimerManager manager = new ExecutionTimerManager();
            
   StreamWriter writer = new StreamWriter("Managed Timers.log");
   manager.Out = writer;
 
   manager.ExecuteTimers(methods,false);
 
   manager.WriteAll();
 
   writer.Close();                
}
 
delegate void VoidIntArg(int iterations);
delegate void VoidStringArg(string arg);
 
private string GetResultsHeader(string timerName)
{
   string result = "Execution time for ";
   result += timerName;
   result += ":";
   return result;
}
 
private void MethodToTime()
{
   string res = "";
   for(int i = 0; i < 10000; i++)
   {
      res += " ";
   }
}
 
private void MethodToTime(int iterations)
{
   string res = "";
   for(int i = 0; i < iterations; i++)
   {
      res += " ";
   }
}
 
private void MethodToTime(string str)
{
   for(int i = 0; i < 10000; i++)
   {
      str += " ";
   }
}

I'd also like to add that the source code for this library is thoroughly commented. Some of the code samples from this article were lifted directly from the code comments. I used the XML commenting feature of the C# compiler. If you have NDoc, you can use it to build MSDN look-alike web pages for the documentation. If you don't have NDoc, I highly recommend it. The quality of my commenting improved dramatically once I started thinking about how it was going to look once I built the final documentation in NDoc. You can find it here.