StopWatch

http://www.switchonthecode.com/tutorials/csharp-snippet-tutorial-performance-timers

Every once in a while, there comes a time when some chunk of code
that you have written isn’t performing quite as well as you think it
should. And when that time comes, you need to have a way of figuring
out what parts of your code are causing those performance problems. For
the heavy duty
cases, there are full blown code profiler programs out there, but for
the simpler cases you probably just want to time some segments of code
manually. And that is what we are going to take a look at today.

A couple of times in various articles in the blog, we have used the value from Environment.TickCount
to help determine how long a segment of code took to run. This is quick
and painless, but it doesn’t give you very high resolution. Even though
TickCount here return values that equate to milliseconds,
it doesn’t actually give you millisecond resolution for time – the best
resolution it will give you is 10 milliseconds.

For example, I ran the following code on my computer:

Debug.WriteLine(Environment.TickCount);
Debug.WriteLine(Environment.TickCount);
Debug.WriteLine(Environment.TickCount);
Debug.WriteLine(Environment.TickCount);
Debug.WriteLine(Environment.TickCount);
Debug.WriteLine(Environment.TickCount);
Debug.WriteLine(Environment.TickCount);
Debug.WriteLine(Environment.TickCount);
Debug.WriteLine(Environment.TickCount);
As you would expect, the code outputted 9 different tick count values, one right after another:
336757822
336757822
336757832
336757832
336757832
336757832
336757832
336757832
336757842

See how it jumps from 336757822 to 336757832? And then from
336757832 to 336757842? So if you are trying to time something that
takes less that 10 milliseconds, using TickCount won’t work – you will either get a result that says it took 0 milliseconds, or that it took 10 milliseconds.

In the non-.NET world, to time things with a higher precision than 10 milliseconds, you would use the Win32 API functions QueryPerformanceFrequency and QueryPerformanceCounter.
And before .NET 2.0, you would need to interop those functions into
your program and use them. But, fortunately, in .NET 2.0, Microsoft wrapped those function up into a nice class called Stopwatch.

So how do we use this nice new Stopwatch class? Well, it is almost as simple as timing things the Environment.TickCount way:

Stopwatch sw = Stopwatch.StartNew();
//Do Stuff
//Do More Stuff

sw.Stop();

Debug.WriteLine(sw.ElapsedMilliseconds);
Debug.WriteLine(sw.Elapsed.TotalMilliseconds);
Debug.WriteLine(sw.ElapsedTicks);

What that code does is create and start a stopwatch, "do some stuff", and then stop the stopwatch. The Debug.WriteLine() code shows different ways of printing out the time that the stopwatch recorded. The first value, ElapsedMilliseconds, returns the number of milliseconds the stopwatch ran as a long. The second, Elapsed.TotalMilliseconds, gives a slightly more precise value. Elapsed is a TimeSpan
object, and you can get the amount of time in a timespan out in all
sorts of different ways, such as seconds or minutes – and here we get
it out as milliseconds. It is a slightly more precise value because it
is a double, and so we get some decimal precision (ie., something can
take 6.34 milliseconds).

The third value, ElapsedTicks is slightly different.
This is the total number of ticks of the stopwatch that passed while it
was running. This is a very different tick than the Environment.TickCount
– a single tick here means a much smaller amount of time. Exactly how
much time a single tick is depends on your computer, which is why, as a
static property on the Stopwatch class there is the value Frequency. This value tells you the number of timer ticks there are in one second. You can use this value like this:

Stopwatch sw = Stopwatch.StartNew();
//Do Stuff
//Do More Stuff
sw.Stop();

double seconds = sw.ElapsedTicks / Stopwatch.Frequency;
Debug.WriteLine(seconds);

There are a couple of other useful things to know about the
stopwatch. One is that it can be stopped and restarted. So you can have
a block of code like this:

Stopwatch sw = Stopwatch.StartNew();
//
//Block A
//
sw.Stop();

//
//Block B
//

sw.Start();
//
//Block C
//
sw.Stop();
Debug.WriteLine(sw.Elapsed.TotalMilliseconds);

And the stopwatch, after this is run, will contain the total time it
took to run blocks A and C – ignoring the time that was taken during B.

You don’t need to use the Stopwatch.StartNew() function to create and start a stopwatch – you can just create one using new and start it yourself, and you can even reuse an already created stopwatch later on:

Stopwatch sw = new Stopwatch();

sw.Start();
//
//Block A
//
sw.Stop();
Debug.WriteLine(sw.Elapsed.TotalMilliseconds);

sw.Reset();
sw.Start();
//
//Block B
//
sw.Stop();
Debug.WriteLine(sw.Elapsed.TotalMilliseconds);

The Reset() method does exactly what you might expect – it resets the stopwatch to 0.

If a stopwatch ever seems to be giving you problems on a system
(i.e., it doesn’t seem to be giving you high precision time values
back), you should check the static flag Stopwatch.IsHighResolution. On some systems, QueryPerformanceCounter (which is what Stopwatch is based on) is unavailable – and so Stopwatch reverts back to using the system timer and its 10 millisecond resolution.

And there you go! That is it for using the Stopwatch
class to do performance timing on sections of code. If you have any
questions, or cool uses for the stopwatch, feel free to leave them in a
comment below.

Advertisements
This entry was posted in Software Development. Bookmark the permalink.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s