2011-03-15

Using the Stopwatch class in C#

During the development of any kind of C# application you might find you need to measure how long some part of your code take to execute. Perhaps your customer demand an operation to finish in a maximum amount of time or you might be puzzled what part of a function is making it run slower than expected.



Is your first instinct doing something similar to this?
DateTime start = DateTime.Now;
//do stuff
DateTime end = DateTime.Now;
Console.WriteLine("Executed in {0} ms", (end - start).TotalMilliseconds);
..when you should actually be doing is this:
Stopwatch stopwatch = Stopwatch.StartNew();
//do stuff
stopwatch.Stop();
Console.WriteLine("Executed in {0} ms", stopwatch.ElapsedMilliseconds);

Stopwatch vs. DateTime for benchmarking


Stopwatch resides in the System.Diagnostics namespace and is (on most systems) a high resolution timer. Unlike DateTime, Stopwatch is actually meant for diagnostics and benchmarking. DateTime.Now is limited to a resolution of about 10 ms, probably worse in most cases while Stopwatch has a much higher resolution at about 0.0005 ms (500 nano seconds, often even lower) which is a whole lot more suitable for benchmarking.

While milliseconds is a useful tool it may be deceiving, especially when comparing two snippets of code that both run for a long time. An alternative is measuring execution time in ticks instead. While a DateTime.Ticks-tick is 100 nano seconds the Stopwatch.ElapsedTicks is defined as:
long tick = (1000L*1000L*1000L) / Stopwatch.Frequency;

The Stopwatch.Frequency field reflects the frequency of the hardware high resolution counter on the current system and the above code would reflect how long a tick in Stopwatch.ElapsedTicks is. These counters usually tick millions of times a second. As you can tell, the difference is accuracy is ridiculous.

Some of the basic properties and methods in Stopwatch


Properties:
  • Stopwatch.Elapsed – returns a TimeSpan
  • Stopwatch.ElapsedMilliseconds – returns a long
  • Stopwatch.ElapsedTicks – also returns a long. I prefer this property
I prefer instantiating my Stopwatch instance like this: Stopwatch s = new Stopwatch(); and run s.Start() on it when it’s time to use it. It is also possible to do Stopwatch s = Stopwatch.StartNew(); that can be used if one wants the Stopwatch to start right away.
There is the .Reset() and .Stop() methods that are, just as the above, pretty self explanatory. There is also a .Restart() method that is basically a shorthand for .Stop(), Reset() and Start(). most of the time I find I want to add to a counter or write something to Console or a log file somewhere between .Stop() and .Reset() which is why I seldom use .Restart().

An example benchmark using Stopwatch


In a previous post I compared counting the char ‘x’ in a string in a forward for loop and a for loop running backwards. Here is a simple example of what a benchmark could look like:
namespace BenchmarkExample
{
    using System;
    using System.Diagnostics;
 
    class ForwardBackwardBenchmark
    {
        public ForwardBackwardBenchmark()
        {
            //// create a 10000 character long string
            string s = new String('x', 10000);
 
            Stopwatch fwdSw = new Stopwatch();
            Stopwatch bwdSw = new Stopwatch();
 
            //// Set up some variables for displaying
            //// statistics in the end of the example
            int fwdCounter = 0;
            int bwdCounter = 0;
 
            //// Run the benchmark 10000 times
            for (int j = 9999; j >= 0; --j)
            {
                //// Loop forwards
                fwdSw.Start();
                for (int i = 0; i < s.Length; i++)
                {
                    if (s[i].Equals('x'))
                    {
                        ++fwdCounter;
                    }
                }
                fwdSw.Stop();
 
                //// Loop backwards
                bwdSw.Start();
                for (int i = s.Length - 1; i >= 0; --i)
                {
                    if (s[i].Equals('x'))
                    {
                        ++bwdCounter;
                    }
                }
                bwdSw.Stop();
            } //// Outer for-loop
 
            //// Output the result
            long f = fwdSw.ElapsedTicks;
            long b = bwdSw.ElapsedTicks;
 
            Console.WriteLine("Forward loop used {0} ticks.", f);
            Console.WriteLine("Backward loop used {0} ticks.", b);
 
            double r;
            r = Math.Round(((double)b / ((double)f)) * 100, 2);
 
            Console.WriteLine("Bwd used {0}% ticks compared to fwd", r);
            Console.WriteLine();
        }
    }
}

1 comment:

  1. Exactly can understand to process of good example of the program.

    ReplyDelete