Execution Timer

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 the 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

ExecutionTimer

s.

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 an

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

The

ExecutionTimerManager

class exists mostly for convenience. It allows you to control a group of

ExecutionTimer

objects with fewer lines of code. It can be useful for setting up tests to be run automatically. I can imagine a configuration file being used to specify what tests to run and the options used to run them, but I haven't implemented anything like that yet.

Here is an example of using 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 += " ";
}
}

Conclusion

I'd like to be perfectly clear when I say this is not attempting to be a commercial-grade performance testing tool, or anything of the sort. There are a lot of variances to consider when testing for performance and I have taken into account... well, none of them. Also, the first run of whatever method you're calling will often be the longest, as it won't get JIT'd until you call it for the first time.

These classes will do a good job, overall, of telling you which of your routines is quickest, but it obviously will not suggest any improvements, as it is not a code analysis tool. If you take it for what is, you may find it to be helpful.

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: http://ndoc.sourceforge.net/