James Michael Hare

...hare-brained ideas from the realm of software development...
posts - 136 , comments - 1092 , 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

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: , , , , , ,

Print | posted on Thursday, January 12, 2012 6:22 PM | Filed Under [ My Blog C# Software .NET Little Pitfalls ]

Feedback

Gravatar

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

Good info about Stopwatch ElapsedTicks.

I wonder if you can do another comparison between Stopwatch and DateTime.UtcNow and post the performance difference.

Thanks!
1/12/2012 8:29 PM | Simon
Gravatar

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

@Simon: Sure, I'll run another test with UtcNow when I have a chance.
1/13/2012 8:50 AM | James Michael Hare
Gravatar

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

so why even have or use Stopwatch ticks?
1/13/2012 9:27 AM | mike
Gravatar

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

@Mike: because in most cases they are more precise than DateTime Ticks, thus once you convert the Stopwatch Ticks to DateTime Ticks you lose some of the precision in favor of machine independence. If you did want those more precise calculations, though, you COULD use the Stopwatch Ticks, but just need to understand they are machine/OS dependent.

So, in short, 99% of the time you don't need to know about them, they are an internal artifact of the high resolution timer of the machine. But, they are there if you do want to know how many actual machine/OS ticks something took.
1/13/2012 10:18 AM | James Michael Hare
Gravatar

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

Sorry, I should have tried this out before posting my request.

I asked about using UtcNow versus 'Now' because 'Now' includes the local time zone conversion logic, which adds processing time. I tried creating a sample and got some different results. The loop is 1,000,000 times. I copied the code below. In order to change the Stopwatch.IsHighResolution, I had to use Reflection since it is a read-only field.

Really interested to know why you think they are differences in results from my code and yours. I used Release configuration and directly ran the exe (Ctrl-F5).

Using DateTime.Now: 68ms
Using DateTime.UtcNow: 8ms
Using Stopwatch.StartNew: 628ms
Using Stopwatch.Restart(Remove Constructor): 619ms
Using Stopwatch.IsHighResolution = false: 58ms

static void Main(string[] args)
{
var count = 1000000;

var sw1 = Stopwatch.StartNew();
for (int i = 0; i < count; i++)
{
var dt1 = DateTime.Now;
var dt2 = DateTime.Now;
var ts = (dt2 - dt1);
var local = ts.TotalMilliseconds;
}
sw1.Stop();

var sw2 = Stopwatch.StartNew();
for (int i = 0; i < count; i++)
{
var dt1 = DateTime.UtcNow;
var dt2 = DateTime.UtcNow;
var ts = (dt2 - dt1);
var local = ts.TotalMilliseconds;
}
sw2.Stop();

var sw3 = Stopwatch.StartNew();
for (int i = 0; i < count; i++)
{
var sw = Stopwatch.StartNew();
sw.Stop();
var local = sw.ElapsedMilliseconds;
}
sw3.Stop();

var sw4 = Stopwatch.StartNew();
var localSw = new Stopwatch();
for (int i = 0; i < count; i++)
{
localSw.Restart();
localSw.Stop();
var local = localSw.ElapsedMilliseconds;
}
sw4.Stop();

var fieldInfo = typeof(Stopwatch).GetField("IsHighResolution");
fieldInfo.SetValue(null, false);
var sw5 = Stopwatch.StartNew();
var localSw1 = new Stopwatch();
for (int i = 0; i < count; i++)
{
localSw1.Restart();
localSw1.Stop();
var local = localSw1.ElapsedMilliseconds;
}
sw5.Stop();

Console.WriteLine("Using DateTime.Now: " + sw1.ElapsedMilliseconds.ToString("#,##0"));
Console.WriteLine("Using DateTime.UtcNow: " + sw2.ElapsedMilliseconds.ToString("#,##0"));
Console.WriteLine("Using Stopwatch.StartNew: " + sw3.ElapsedMilliseconds.ToString("#,##0"));
Console.WriteLine("Using Stopwatch.Restart(Remove Constructor): " + sw4.ElapsedMilliseconds.ToString("#,##0"));
Console.WriteLine("Using Stopwatch.IsHighResolution = false: " + sw5.ElapsedMilliseconds.ToString("#,##0"));
Console.ReadLine();
}
1/15/2012 5:10 PM | Simon
Gravatar

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

I've seen discussions where it was mentioned that the usage of Stopwatch, sometimes, needs processer affinity.
1/16/2012 11:31 AM | Paulo Morgado
Gravatar

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

A clever thing to do would be to use DateTime.Now and Stopwatch.ElapsedTicks to have a fast machine independant high resolution timer. But the downside is that you will often run into troubles the more cores the CPUs get because Windows will use the rtdsc instruction or something different. Depending on the CPU the rtdsc instruction will count the CPU cycles or (newer CPUs) will be updated at a constant rate. But there are still today issues with different power saving modes which will deliver the wrong frequency (http://www.osronline.com/showthread.cfm?link=189427). The official MSDN docu states that you might need to get reliable results you could be forced to confine your timer to one CPU to get reliable results. But I doubt that this advice does help in all cases.
I had several cases where the time was off by 50s or more on some machines which is unfortunate.
1/16/2012 4:11 PM | Alois Kraus
Gravatar

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

@Simon: I'll run your code on my machine as soon as I get back in town. I've never had Stopwatch take longer than DateTime.Now, but I have had UtcNow go faster, though on the same order of magnitude.
1/17/2012 10:12 AM | James Michael Hare
Gravatar

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

@Simon: I think you should restructure your tests to take into account garbage collection possibilities as well. I've run your test code segments with my PerformTest() method (which forces collection after each test bundle) and I don't get your results. I get:

Using DateTime.Now took: 1552 ms, 0.001552 ms/item, 0 total length.
Using DateTime.UtcNow took: 30 ms, 3E-05 ms/item, 0 total length.
Using Stopwatch.StartNew took: 79 ms, 7.9E-05 ms/item, 0 total length.
Using Stopwatch.Restart took: 74 ms, 7.4E-05 ms/item, 0 total length.
Using High Resolution took: 45 ms, 4.5E-05 ms/item, 0 total length.

So DateTime.Now is still the slowest, UtcNow is fastest, though on same order of magnitude as the Stopwatch (and not as precise as the Stopwatch, of course).
1/19/2012 11:09 AM | James Michael Hare
Gravatar

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

I had an itch to figure out why your DateTime.Now results and mine were so different and I finally realized it is based on location. I am in Seoul, Korea, which doesn't use Daylight savings. When I changed my computer's time zone to Central U.S., the DateTime.Now results changed from 44ms to 310ms (reran with x64, which is faster in this case). Then if I changed my computer's time zone to Arizona, which also doesn't use DST, I get the 44ms result.

I would like to apologize for taking up your time and thank you for listening. I enjoy reading your blog.
1/20/2012 12:02 AM | Simon
Gravatar

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

@Simon: Hey no worries at all! That is definitely very interesting findings, so no wasted time. It's interesting to see the impact of the time zone and DST!
1/20/2012 11:17 AM | James Michael Hare
Gravatar

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

Excellent post! Thanks a lot for it.
1/20/2012 1:23 PM | essay help
Gravatar

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

Actually significant for the written content. in sequence that is display is complicated to reckon, and many astonishing things that I liked the way it goes here.
1/30/2012 12:25 PM | wild jerky
Gravatar

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

The code for the stopwatch is very easy to understand. However, is C# the same as C++ language and can it be combined with jQuery and PHP as well?
4/6/2012 3:22 AM | proxy server
Gravatar

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

Just getting started with C# and this helped. Thanks
4/18/2012 10:46 AM | bueler
Gravatar

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

I get rear in city. I've never had Stopwatch take longer than DateTime.Now, but I have had Utc at the moment go quicker, while on the same order of degree.
7/21/2012 12:41 PM | rural houses weardale
Post A Comment
Title:
Name:
Email:
Comment:
Verification:
 
 

Powered by: