Can the .NET Stopwatch class be THIS terrible?

Question

I'm making an application that needs some pretty tight timing, and the Stopwatch class is the perfect solution. However, I noticed sometimes, when running on a small panel PC, the Stopwatch values were way off. I added some debug printouts that monitor the value of the stopwatch every 200 ms or so:

0:00:197
0:00:502
0:00:702
...
0:03:356
0:12:93
0:13:21
0:13:421
...

How could it possibly jump from ~3 seconds to ~13 seconds? I now see that the underlying function QueryPerformanceCounter() is buggy (Beware of QueryPerformanceCounter()), but I get the sense that something else is going on here.

Any insight is appreciated.

Update:

Here's a little more detail on my code: it's pretty straightforward. It's a WPF application that creates a new Stopwatch object on startup, and then kicks it off via Start(). I then create a DispatcherTimer, like so:

displayTimer = new DispatcherTimer(); 
displayTimer.Tick += display_Tick; 
displayTimer.Interval = DISPLAY_INTERVAL_TIMESPAN; 

where the timespan is 200 ms. My debug code simply prints out the value of the Stopwatch object every time the dispatchTimer ticks.

Update2:

A fun Microsoft support article is Performance counter value may unexpectedly leap forward.

Foti

You haven't told us anything about what's happening between these measurements. Perhaps your app stalled? What happens if you print out DateTime.UtcNow at the same time? – Wye

How are you guaranteeing that the code is called exactly every 200ms? – Levina

buggy it may be, but not that buggy :) – Avid

agreed. 10 seconds is unacceptable. – Laurentian

Maybe you're assuming timers stop advancing when you hit a breakpoint? That's not the case, although it would be nice. I often see time-dependent code behave incorrectly because I spent a minute at a breakpoint and it assumes smaller intervals. – Patency

Here's a little more detail on my code... it's pretty straightforward. It's a WPF app that creates a new Stopwatch object on startup, then kicks it off via .Start(). I then create a DispatcherTimer like so: displayTimer = new DispatcherTimer(); displayTimer.Tick += display_Tick; displayTimer.Interval = DISPLAY_INTERVAL_TIMESPAN; where the timespan is 200 ms. My debug code simply prints out the value of the Stopwatch object everytime the dispatchTimer ticks. I'm almost out of characters, but I'd like to display additional debug info. – Foti

Here is a link to a debug log: dl.dropbox.com/u/7999907/hburg.txt. The first bit of data on each line is the current date/time via DateTime.UtcNow. The time all the way to the right is the value via Stopwatch.Elapsed. You can see how the stopwatch jumps but the DateTime doesn't. – Foti

Are you sure you're not seeing some threading time issue where the Machine simply swapped out the running process? A small panel PC might be so underpowered that this would occur. (it's unlikely) – Ultraviolet

I have to note, that this problem was in windows XP, but is removed in WIn Vista, and they are using less precise, counter in Motherboard IO controller instead, It has less precision but isn't core bound. – Shiekh

Answer 1

Update (after seeing your log)

As you already mentioned, the Stopwatch class uses the QueryPerformanceCounter function underneath. In the Remarks section MSDN says:

On a multiprocessor computer, it should not matter which processor is called. However, you can get different results on different processors due to bugs in the basic input/output system (BIOS) or the hardware abstraction layer (HAL). To specify processor affinity for a thread, use the SetThreadAffinityMask function.

As you are using the Dispatcher, QueryPerformanceCounter might not be executed on the same CPU every time that you query the elapsed time.

You can possibly check if the issue mentioned in MSDN is the reason for your problem by specifying a processor affinity for your process, e.g. by calling your executable using the start command. 10 seconds seems like a big lag between CPUs to me, but the documentation is very vague on how big the difference may be. The following command will bind your application to the first CPU:

> start.exe /AFFINITY 1 program.exe

If this should solve the issue you might want to have a look at the suggested workaround, i.e. calling the SetThreadAffinityMask function before querying the Stopwatch object.

Your comment said that you are using a WPF DispatcherTimer. The documentation of that class states:

Timers are not guaranteed to execute exactly when the time interval occurs, but they are guaranteed to not execute before the time interval occurs. This is because DispatcherTimer operations are placed on the Dispatcher queue like other operations. When the DispatcherTimer operation executes is dependent on the other jobs in the queue and their priorities.

This means that the timer event may arrive delayed, especially if the dispatcher is busy with other tasks. Did you place other things in the dispatcher queue that will prevent the event from triggering earlier?

Deni

Understood, but the dispatcherTimer is simply monitoring the Stopwatch. The dispatcherTimer tick doesn't really need to be accurate for me... I just can't absorb a 10 second jump in my stopwatch :) – Foti

@Tim: Ok, hadn't seen your log file yet when I answered. Are you able to produce a small sample application to reproduce the artifact? By the way, you are able to edit your question and include additional information. – Deni

Interesting. Unfortunately, I'm running on a small panel PC (with Windows Embedded Standard) that only has one CPU. I'm not very familiar with start.exe, but there is no AFFINITY switch available for me. – Foti

@Tim: Alright, this is actually an important fact that you are observing this on an embedded system and not a regular desktop PC. As the clock is based on hardware after all, this makes a hardware bug the most likely. – Deni

That's what I was afraid of. I suppose I can roll my own stopwatch that doesn't use 'QueryPerformanceCounter'. It is especially frustrating when a library call doesn't work as advertised. I mean, I can deal with my stuff not working, but not somebody else's :) – Foti

Answer 2

Exact timing on PC hardware isn't straightforward, period. Here are some resources, showing some experiences with timing in Windows, which will be the underlying implementation of any counter in a Windows environment, including .NET:

• Results of some quick research on timing in Win32
• Need help with QueryPerformanceCounter and Dual Processors

It explains why sometimes you will get 10 ms resolution, depending on which system call you use, and sheds a little more light on why QueryPerformanceCounter is "buggy". One of the points made is that power saving modes/variable CPU speeds can interfere with these timings.

A related concept to this is "locking the timestep" in real-time physical simulations. If you google for that, you may get some ideas on how to work around problems you are having. The basic concept is that you have fixed time steps, and do a sort of producer/consumer implementation for your timing/update functions. I don't know if this applies to your specific domain, but it is considered a best-practices in video games.

Scant

10 ms resolution is fine for me... I'm seeing a 10 SECOND jump forward by the Stopwatch class. – Foti

I agree... 10 seconds is pretty nuts. – Laurentian

Maybe, just maybe, 10 seconds actually passed? What was your program actually doing? – Karns

@Tim: This is the closest most people are going to get at guessing your problem. You'll have to show some minimal code that repros the problem, and give specifics about your environment for us to stop guessing :) – Scant

Ten seconds may be "pretty nuts" but it's very possible if the GC kicks in. – Sullage

Answer 3

Perhaps I am misunderstanding your question, but do you need to just measure time intervals or do you need to execute code at those intervals? If you need to execute code, then check out System.Timers.Timer class as it is thread safe and should work fine for multi-processors.

Granuloma

Both :) I need to fire up a method every so often and I need to measure time intervals. – Foti