James Michael Hare

...hare-brained ideas from the realm of software development...
posts - 136 , comments - 1089 , trackbacks - 0

My Links

News

Welcome to my blog! I'm a Sr. Software Development Engineer in Seattle, WA. I've been doing C++/C#/Java development for over 18 years, but have definitely learned that there is always more to learn!

All thoughts and opinions expressed in my blog and my comments are my own and do not represent the thoughts of my employer.

Blogs I Read

MCC Logo MVP Logo

Follow BlkRabbitCoder on Twitter

Tag Cloud

Archives

Post Categories

Thursday, January 12, 2012

C#/.NET Little Pitfalls: Stopwatch Ticks are not TimeSpan Ticks

C# is a wonderful language for modern programming.  While everything in C# has a reason and a place, occasionally there are things that can be confusing for a developer who isn’t aware of what is happening behind the scenes. This is another post in the Little Pitfalls series where I explore these issues; an index of the Little Wonders and Little Pitfalls posts is here.

This week will be a short post since I’m travelling to Denver for design meetings, and otherwise spending most of my free time celebrating a birthday with friends and family.  But I had a quick item to share that I’ve seen come up more than once on SO, so we’ll add it to the Little Pitfalls.

The System.Diagnostics.Stopwatch class is very useful for elapsed time measurements in .NET applications.  Today we’ll look at the ElapsedTicks member of the Stopwatch class, and some of the confusion of what this quantity represents, especially compared to TimeSpan or DateTime Ticks.

The Stopwatch Class

While DateTime is fine for getting the current value of the date and time, it is not exactly precise or lightweight.  Thus, when timing a process, a better way to go about this is to use the Stopwatch class from the System.Diagnostics namespace.

The Stopwatch was one of my first “Little Wonders” segments (here).  I won’t repeat all of that information here, but as a quick refresher let’s take a look at a small example:

   1: // we could also create with new and then call Start(), 
   2: // but StartNew() does it all in one step
   3: var sw = Stopwatch.StartNew();
   4:  
   5: // Do some work here, for now, let's just sleep
   6: Thread.Sleep(5000);
   7:  
   8: sw.Stop();
   9:  
  10: Console.WriteLine("We slept for {0} ms", sw.ElapsedMilliseconds);

So, we create and start a Stopwatch instance by calling the factory method StartNew(), then perform the work we want to measure (in this case, just sleeping), and then Stop() our Stopwatch and see how many ElapsedMilliseconds have gone by.  The results will vary somewhat (since Thread.Sleep() is not precise), but you would expect something like:

   1: The work took 4999 ms

So far, so good!  There’s actually a few properties we can use to see how much time has passed between Start()or StartNew()and Stop():

  • Elapsed – Returns a TimeSpan with the elapsed time.
  • ElapsedMilliseconds – Returns a long with the number of elapsed milliseconds.
  • ElapsedTicks – Returns a long with the number of Stopwatch elapsed ticks.

The first two are self explanatory, the last needs a bit more explanation as it can be a source of confusion.

Pitfall - Stopwatch Ticks are machine/OS dependent

The thing to remember with ElapsedTicks is that the ticks represented in Stopwatch are based on a combination of the hardware of the machine and the operating system.  Contrast this to DateTime and TimeSpan where Ticks are defined as 100 nanosecond intervals -- which is obviously machine/OS independent.

In short, that means that the following output values are (most likely) not going to be identical:

   1: var sw = Stopwatch.StartNew();
   2:  
   3: Thread.Sleep(5000);
   4:  
   5: sw.Stop();
   6:  
   7: // This one is the raw ticks of the Stopwatch and is machine dependent
   8: Console.WriteLine("ElapsedTicks is:  " + sw.ElapsedTicks);
   9:  
  10: // This one goes to a TimeSpan, which normalizes the Ticks
  11: // to 100 nanosecond intervals and is machine independent
  12: Console.WriteLine("Elapsed.Ticks is: " + sw.Elapsed.Ticks);

For example, if I run this on my current machine, I see the following output:

   1: ElapsedTicks are:  9973892461
   2: Elapsed.Ticks are: 49993947

Notice in my results that there are a lot more ElapsedTicks than Elapsed.Ticks!  And, as I said, if you ran this on a different machine/OS combination, you could get a totally different magnitude of difference.  This can be an issue when people think that the ElapsedTicks of the Stopwatch can be directly used to construct a TimeSpan (or DateTime):

   1: // Wrong!  The ticks are most likely completely different!
   2: var elapsedTime = new TimeSpan(sw.ElapsedTicks);
   3:  
   4: Console.WriteLine("Was it {0} or was it {1}",
   5:     sw.Elapsed, elapsedTime);

So if we tried to create a TimeSpan from ElapsedTicks instead DateTime/TimeSpan ticks, or instead of just using Elapsed (which returns an appropriate TimeSpan), we can get totally different values:

   1: Was it 00:00:04.9994341 or was it 00:16:37.3971203

There’s a big difference between four seconds and sixteen minutes!  I’ve seen code like the above where the person using Stopwatch didn’t know its ticks were machine/OS dependent and thus made the mistake of using them to construct a TimeSpan instead of simply calling Elapsed to get one.

Sidebar: What’s the Frequency?

For those interested, you can convert from Stopwatch ticks to seconds by using the Stopwatch.Frequency static property, which tells you the ration of Stopwatch ticks per second.  Thus these two are (roughly, due to precision differences) the same:

   1: // take the ElapsedTicks, then divide by Frequency to get seconds
   2: Console.WriteLine("ElapsedTicks to sec:  {0}", 
   3:     sw.ElapsedTicks / (double)Stopwatch.Frequency);
   4:  
   5: // take the Elapsed property, and query total number of seconds it represents
   6: Console.WriteLine("Elapsed.TotalSeconds: {0}", sw.Elapsed.TotalSeconds);

Which gives us results (on my machine) like:

   1: ElapsedTicks to sec:  4.9998583024032
   2: Elapsed.TotalSeconds: 4.9998583

Sidebar: Stopwatch is more efficient than DateTime.Now math

You may look at the Stopwatch and think why not just subtract two instances of DateTime.Now, like:

   1: var start = DateTime.Now;
   2:  
   3: // Do some work here, for now, let's just sleep
   4: Thread.Sleep(5000);
   5:  
   6: var stop = DateTime.Now;
   7:  
   8: Console.WriteLine("The code took: {0} ms", (stop - start).TotalMilliseconds);

There’s two reasons not to do this, though.  First of all, the Stopwatch is generally more precise, and secondly, it’s more lightweight.

For example, running the same code using Stopwatch vs DateTime.Now math, the differences in computational speed for 1 million iterations are:

   1: DateTime math took: 1534 ms, 0.001534 ms/iteration.
   2: Stopwatch took: 70 ms, 7E-05 ms/iteration.
That’s a huge difference between the two!  So when you want to measure elapsed time of a process running on a machine, strongly consider the Stopwatch.

Summary

In short, remember that the ticks in Stopwatch are machine/OS dependent, thus you should never count on the ration of Stopwatch ticks to seconds to be the same between two systems, and possibly even on the same system after a reboot.  Thus, you can never count on Stopwatch ticks to be the same interval as DateTime/TimeSpan ticks.

To get system-independent time, make sure to use the Stopwatch’s Elapsed or ElapsedMilliseconds properties, which already take the Stopwatch.Frequency (ticks per second) into account.

Technorati Tags: , , , , , ,

Posted On Thursday, January 12, 2012 6:22 PM | Comments (16) | Filed Under [ My Blog C# Software .NET Little Pitfalls ]

Powered by: