Wednesday, October 15, 2008

Beware of the stopwatch

In a comment on my last post, craniac argued that the StopWatch-class should be used for measuring time intervals.

Sadly, measuring a time interval is not as easy as it sounds. There are several mechanisms, I will explain 3 of them and point out their strengths and weaknesses.

1. DateTime.UtcNow

   1: DateTime begin = DateTime.UtcNow;
   2:  
   3: ...
   4:  
   5: DateTime end = DateTime.UtcNow;
   6: Console.WriteLine("Measured time: " + (end-begin).TotalMilliseconds + " ms.");

This is the fastest mechanism because under the hood it only reads a counter from memory (the code above takes only 76 nanoseconds to execute on my machine). However the resolution is not so great: only 10 milliseconds on recent version of Windows. If you want to measure a piece of code that takes shorter to execute, you will have to execute it e.g. 1000 times and measure how long this takes, then divide the result by 1000.

Another disadvantage is that this is not reliable if the system-time changes. This should be a very rare situation, but could for instance happen through synchronization with a time server.

2. Stopwatch

   1: Stopwatch watch = new Stopwatch();
   2: watch.Start();
   3:  
   4: ...
   5:  
   6: watch.Stop();
   7: Console.WriteLine("Measured time: " + watch.Elapsed.TotalMilliseconds + " ms.");

This mechanism is a bit slower than the previous one (10 times slower on my machine) so for short intervals this may have an impact on the result. However there are some serious issues:

  • This can be unreliable on a PC with multiple processors. Due to a bug in the BIOS, Start() and Stop() must be executed on the same processor to get a correct result.
  • This is unreliable on processors that do not have a constant clock speed (most processors can reduce the clock speed to conserve energy). This is explained in detail here.

I suspect that you can get a reliable result if you run it on a single-processor machine and disable any power-saving options in the BIOS. I haven’t tested this though.

On the upside, it has the hightest possible resolution (which depends on the hardware it runs on).

3. Process.TotalProcessorTime

   1: TimeSpan begin = Process.GetCurrentProcess().TotalProcessorTime;
   2:  
   3: ...
   4:  
   5: TimeSpan end = Process.GetCurrentProcess().TotalProcessorTime;
   6: Console.WriteLine("Measured time: " + (end - begin).TotalMilliseconds + " ms.");

This mechanism is different from the previous ones because it does not measure how much time has passed, but it measures how long your process has kept the CPU busy. This is great for performance measurements:

  • The timings are not distorted by other processes that consume a lot of CPU.
  • You can measure the impact that your code has on the overall performance of the system. On laptops, this also gives an indication towards the battery-power that is consumed by your process. This can be important for applications that run for a long time (such as services and other background tasks).

To interpret the measured time correctly, you should realize that time that is spent while your code is waiting (e.g. in a Sleep) will not be counted. On the other hand, if your process is keeping multiple processors busy, the time of each processor will be added (if a dual-core processor is kept 100% busy, the ‘TotalProcessorTime’ will increment with 2 each second!).

Note that this mechanism has the worst performance: the code above takes 19264 nanoseconds on my PC. This is 250 times slower than using DateTime.UtcNow!

So there is not one-size-fits-all solution to measure a time interval. Personally, if I want to measure how long a piece of code takes to execute, I run it in a loop (e.g. one million times) and measure it using DateTime.UtcNow.

9 comments:

Steven said...

Very interesting. Great post.

craniac said...

Thanks Kristof. I was asking more than arguing and this discussion is exactly the kind of thing I was hoping for. I thought your last tip was quite useful so I let my colleagues know about it and one responded that Stopwatch should be used for such timing, prompting me to make the comment.

ArabixTeam Member said...

What about Enviroment.TickCount? you did not mention any thing about it?

Kristof said...

@ArabixTeam: based on the documentation I think that Environment.TickCount has a resolution of 1 ms, which is better than DateTime.Now but worse than the StopWatch. So this might be a good alternative if the resolution of DateTime.UtcNow is not good enough for your application. I haven't done any testing regarding the performance implications, but I would guess that this just involves reading a counter. So the performance might be even better than using DateTime.UtcNow. I suggest you do your own test if performance is very critical for you.
Just be very careful that you handle the overflow situation well (every 49 days the the value will overflow from Int32.MaxValue to Int32.MinValue).
Thanks for bringing this to my attention. I never actually noticed that this property existed!

Anonymous said...

Shouldn't you be able to use Stopwatch.Frequency to normalize the ticks values in case the CPU frequency has changed?

Kristof said...

@Anonymous: but how do you know when the frequency has changed? I don't think there is an event that you can subscribe to, and polling the frequency will not be very efficient.

Andriy Buday said...

MSDN: "The Stopwatch measures elapsed time by counting timer ticks in the underlying timer mechanism. If the installed hardware and operating system support a high-resolution performance counter, then the Stopwatch class uses that counter to measure elapsed time. Otherwise, the Stopwatch class uses the system timer to measure elapsed time. Use the Frequency and IsHighResolution fields to determine the precision and resolution of the Stopwatch timing implementation."
See:
http://msdn.microsoft.com/en-us/library/system.diagnostics.stopwatch.aspx

Ivan P said...

Hi Kristof,

Why did you say that Environment.TickCount (that is in milliseconds) has a better precision than DateTime.UtcNow.Ticks (which is in hundreds of nanoseconds, or in 0.0001 milliseconds) ? DateTime seems to be 10000 times more accurate.

In .Net 2.0 Environment.TickCount is based on WinAPI GetTickCount(), and DateTime.Ticks is based on GetSystemTimeAsFileTime().
These functions are system dependent, and even though resolution is different, results may have the same precision (if OS clock aren't able to increment only with relatively big intervals)

And just for information:
The StopWatch (in 2.0) is based on QueryPerformanceCounter() if supported, or uses DateTime.UtcNow.Ticks if opposite.

mj1856 said...

With regard to Stopwatch, it would seem that the key would be to only use a Stopwatch within a single thread, or at least be sure that you are starting and stopping it from the same processor using ProcessThread.ProcessorAffinity.

With regards to Ivan's comment - the DateTime type has precision to the tick, but the source of that time is the system clock which only has accuracy to 10ms or so, like Kristof said in the article. Search google for precision vs accuracy - they are not the same thing.