.NET System.Diagnostics.Stopwatch issue (returns values too low)

Question

On my computer the Stopwatch is returning values way too low. For example, 200 ms when I specified Thread.Sleep(1000). The program is supposed to wait 1 second. I also tested with ManualResetEvent.WaitOne(1000) and got the same results. Both framework 2.0 and 3.0 gives this strange behavior. I am running Windows XP SP3 with .NET Framework 3.5 SP1.

Here is the result of my tests (code below):

1000 ms for DateTime.Now.Ticks
0201 ms for Stopwatch.ElapsedTicks
0142 ms for Stopwatch.ElapsedMilliseconds
0139 ms for Stopwatch.ElapsedTicks after Reset
0264 ms for Stopwatch.ElapsedTicks setting ThreadAffinity
0151 ms for Stopwatch.ElapsedTicks setting ProcessorAffinity (and more)
0371 ms for Stopwatch.ElapsedTicks with Syncronized object
Done!

// Program.cs file

class Program
{
    static void Main(string[] args)
    {
        StopWatchTest.Go();
        Console.WriteLine("Done!");
        Console.ReadLine();
    }
}

// StopWatchTest.cs class

internal static class StopWatchTest
{
    public const int SleepTime = 1000;

    public static void Go()
    {
        #region Test #0 with DateTime.Now.Ticks
        long startTick = DateTime.Now.Ticks;
        Thread.Sleep(SleepTime);
        long stopTick = DateTime.Now.Ticks;
        long elapsedDt = (stopTick - startTick) * 100;
        Display((int)(elapsedDt / 1000 / 1000), "DateTime.Now.Ticks");
        #endregion Test #0 with DateTime.Now.Ticks

        Stopwatch watch = Stopwatch.StartNew();
        long frequency = Stopwatch.Frequency;
        double nanosecPerTick = (1000.0 * 1000.0 * 1000.0) / frequency;

        #region Test #1 with Stopwatch.ElapsedTicks
        startTick = watch.ElapsedTicks;
        Thread.Sleep(SleepTime);
        stopTick = watch.ElapsedTicks;
        double elapsedSw = (stopTick - startTick) * nanosecPerTick;
        Display((int)(elapsedSw / 1000 / 1000), "Stopwatch.ElapsedTicks");
        #endregion Test #1 with Stopwatch.ElapsedTicks

        #region Test #2 with Stopwatch.ElapsedMilliseconds
        startTick = watch.ElapsedMilliseconds;
        Thread.Sleep(SleepTime);
        stopTick = watch.ElapsedMilliseconds;
        Display((int)(stopTick - startTick), "Stopwatch.ElapsedMilliseconds");
        #endregion Test #2 with Stopwatch.ElapsedMilliseconds

        #region Test #3 with Stopwatch.ElapsedTicks after Reset
        watch.Stop();
        watch.Reset();
        watch.Start();
        startTick = watch.ElapsedTicks;
        Thread.Sleep(SleepTime);
        stopTick = watch.ElapsedTicks;
        elapsedSw = (stopTick - startTick) * nanosecPerTick;
        Display((int)(elapsedSw / 1000 / 1000), "Stopwatch.ElapsedTicks after Reset");
        #endregion Test #3 with Stopwatch.ElapsedTicks after Reset

        #region Test #4 with Stopwatch.ElapsedTicks and ThreadAffinity
        Thread.BeginThreadAffinity();
        startTick = watch.ElapsedTicks;
        Thread.Sleep(SleepTime);
        stopTick = watch.ElapsedTicks;
        elapsedSw = (stopTick - startTick) * nanosecPerTick;
        Display((int)(elapsedSw / 1000 / 1000), "Stopwatch.ElapsedTicks setting ThreadAffinity");
        Thread.EndThreadAffinity();
        #endregion Test #4 with Stopwatch.ElapsedTicks and ThreadAffinity

        #region Test #5 with Stopwatch.ElapsedTicks and ProcessorAffinity (and more)
        const int affinity = 0x0001;
        Process proc = Process.GetCurrentProcess();
        proc.ProcessorAffinity = new IntPtr(affinity);
        proc.PriorityClass = ProcessPriorityClass.High;
        ProcessThreadCollection ptc = proc.Threads;
        foreach (ProcessThread pt in ptc)
        {
            pt.IdealProcessor = 0;
            pt.ProcessorAffinity = new IntPtr(affinity);
        }
        Thread.CurrentThread.Priority = ThreadPriority.Highest;

        startTick = watch.ElapsedTicks;
        Thread.Sleep(SleepTime);
        stopTick = watch.ElapsedTicks;
        elapsedSw = (stopTick - startTick) * nanosecPerTick;
        Display((int)(elapsedSw / 1000 / 1000), "Stopwatch.ElapsedTicks setting ProcessorAffinity (and more)");
        #endregion Test #5 with ProcessorAffinity and more

        #region Test #6 with Syncronized object
        elapsedSw = new SyncTimer().Go();
        Display((int)(elapsedSw / 1000 / 1000), "Stopwatch.ElapsedTicks with Syncronized object");
        #endregion Test #6 with Syncronized object
    }

    private static void Display(int milliseconds, string testName)
    {
        Console.WriteLine("{0:0000} ms for {1}", milliseconds, testName);
    }
}

[Synchronization]
internal class SyncTimer : ContextBoundObject
{
    [MethodImpl(MethodImplOptions.Synchronized)]
    public double Go()
    {
        Stopwatch.StartNew();
        long frequency = Stopwatch.Frequency;
        double nanosecPerTick = (1000.0 * 1000.0 * 1000.0) / frequency;

        long startTick = Stopwatch.GetTimestamp();
        Thread.Sleep(StopWatchTest.SleepTime);
        long stopTick = Stopwatch.GetTimestamp();
        return (stopTick - startTick) * nanosecPerTick;
    }
}

@user633578, There is mistake in your code. You should use one stopwatch instance per test. — acoolaum, Feb 25 '11 at 05:15
I did not see any limitation about re using the same Stopwatch instance. By the way, first test does not yield a valid value. — Ducharme, Feb 25 '11 at 07:01
I have the same issue, Have you found the cause ? My mesured times are half of the real time. — Michel, Apr 13 '11 at 13:21
My Stopwatch is acting funky, too. I am getting the correct result in ElapsedMilliseconds, but ElapsedTicks seems to give about 2500 ticks/ms. I guess ElapsedTicks is basically invalid. — Kendall Frey, Jan 10 '12 at 22:32
@KendallFrey: No, it simply uses a different sized tick. Compare [TimeSpan.TicksPerSecond](http://msdn.microsoft.com/en-us/library/system.timespan.tickspersecond.aspx) to [Stopwatch.Frequency](http://msdn.microsoft.com/en-us/library/system.diagnostics.stopwatch.frequency.aspx). The different tick sizes are clearly mentioned in the section of [Stopwatch.ElapsedTicks](http://msdn.microsoft.com/en-us/library/system.diagnostics.stopwatch.elapsedticks.aspx) that is highlighted in yellow. — Allon Guralnek, Jun 05 '12 at 11:36

score 6 · Answer 1 · edited May 23 '17 at 12:25

Have a look at the following links:

https://connect.microsoft.com/VisualStudio/feedback/details/94083/stopwatch-returns-negative-elapsed-time

System.Diagnostics.Stopwatch returns negative numbers in Elapsed... properties

It seems there is an issue with Stopwatch accuracy which can lead to it returning negative Elapsed times, and also wildly varying times. If you look at the Connect issue, most of the people there are talking about seeing the issue on a virtual machine, which is where we are seeing the negative Elapsed values issue.

Looking at the QueryPerformanceCounter doc, it seems to imply this issue can happen on multiprocessor systems due to BIOS or hardware abstraction layer bugs, but gives no further information and is not specific about virtualised machines.

As for the solution to this problem... I haven't found one in a lot of googling. You can ignore values less than zero, which is not ideal but workable in some cases. But that doesn't solve your problem - how do you know what values are invalid?

Hope this helps somewhat.

score 5 · Answer 2 · answered Jan 19 '17 at 11:43

I know this an old question, but I thought I'd provide my 2 cents after struggling with the same problem:

I started looking at the Frequency as suggested by @AllonGuralnek and it did provide the accurate time in seconds, but it dropped the remaining milliseconds which I also wanted to capture.

Anyway, after a lot of back and forth and not getting anywhere with this, I noticed that the sw.Elapsed had a Ticks property and this one provided me with the accurate number of ticks and once converted back it provided me with an accurate time.

Code wise, this is what I ended up with:

Stopwatch sw = new Stopwatch();
sw.Start();

... DO WORK

sw.Stop();

long elapsedTicks = sw.Elapsed.Ticks;
Debug.WriteLine(TimeSpan.FromTicks(elapsedTicks).ToString());

When running a test, calling:

sw.Elapsed.ToString() : "00:00:11.6013029"
sw.ElapsedTicks : Returns "40692243" and converts to "00:00:04.0692243" when calling TimeSpan.FromTicks(sw.ElapsedTicks).ToString() which is inaccurate.
sw.Elapsed.Ticks : Returns "116013029" and converts to "00:00:11.6013029" when calling TimeSpan.FromTicks(sw.Elapsed.Ticks).ToString() which accurate.

While I may be missing something, I feel it doesn't make sense that sw.ElaspedTicks returns a different value than sw.Elapsed.Ticks, so if someone wants to shed some light on this, please do, but from my point of view, I see it as a bug and if not, at least it feels very inconsistent!.

NOTE: Calling sw.ElapsedTicks / Stopwatch.Frequency returns 11 (i.e. seconds) but as I said, it drops the milliseconds which is no use to me.

score 2 · Answer 3 · answered Mar 19 '18 at 20:11

2

You can use that code to fix "Stopwatch.Elapsed" method problem:

using System;
using System.Diagnostics;

namespace HQ.Util.General
{
    public static class StopWatchExtension
    {
        public static TimeSpan ToTimeSpan(this Stopwatch stopWatch)
        {
            return TimeSpan.FromTicks(stopWatch.ElapsedTicks);
        }
    }
}

Usage:

using HQ.Util.General;

Debug.Print($"Elapsed millisec: { stopWatch.ToTimeSpan().TotalMilliseconds}");

answered Mar 19 '18 at 20:11

Eric Ouellet

10,996
11
84
119

tried all the other solutions above, affinity, elapsed.milliseconds, elapsedmilliseconds..this is the only one that worked for me – Cymricus May 17 '22 at 16:15

Will Dean · Answer 4 · 2011-02-25T13:01:22.960

1

I got this:

1000 ms for DateTime.Now.Ticks
0999 ms for Stopwatch.ElapsedTicks
1000 ms for Stopwatch.ElapsedMilliseconds
0999 ms for Stopwatch.ElapsedTicks after Reset
0999 ms for Stopwatch.ElapsedTicks setting ThreadAffinity
0999 ms for Stopwatch.ElapsedTicks setting ProcessorAffinity (and more)

(Couldn't run the last test)

On a quad-core i7 machine with .NET4 in Linqpad.

I only ever tend to use Stopwatch.ElapsedMilliseconds but I've never seen anything odd about it. It does sound like there's something broken about your machine or virtualization platform.

edited Feb 25 '11 at 13:01

answered Feb 25 '11 at 09:57

Will Dean

39,055
11
90
118

1

Thank you very much. Many people have the same results as you do. Next step: figure out what is broken and how to fix it... – Ducharme Feb 25 '11 at 12:06

score 0 · Answer 5 · answered Feb 25 '11 at 08:52

0

Seems like you're using Tick count in some cases. Remember that by default on modern Windows for example, the OS will save CPU. This means that the tick count and the time elapsed are not in linear proportion.

I suggest you try using the Stopwatch.ElapsedMilliseconds in the most basic form:

var sw = new Stopwatch();
sw.Start();
Thread.Sleep(1000);
var elpased = sw.Elapsed;

answered Feb 25 '11 at 08:52

Wernight

36,122
25
118
131

No luck! It returns 127 ms in my test.
**1000 ms for DateTime.Now.Ticks
0127 ms for Stopwatch.Elapsed
Done!** Stopwatch sw = new Stopwatch(); sw.Start(); Thread.Sleep(1000); Display((int)sw.Elapsed.TotalMilliseconds, "Stopwatch.Elapsed"); – Ducharme Feb 25 '11 at 09:01
3

Your running on a VM? Is the host of the guest machine having CPU performacne to max performance in control pannel? – Wernight Feb 25 '11 at 09:02
If yes, it the returned value proportional to the sleep time? – Wernight Feb 25 '11 at 09:08

score 0 · Answer 6 · answered Feb 25 '11 at 09:43

0

If the Stopwatch doesn't work, you can use the QueryPerformanceCounter on Windows.

See this little class on http://www.windojitsu.com/code/hirestimer.cs.html

answered Feb 25 '11 at 09:43

Wernight

36,122
25
118
131

Same result. I do some tests after killing as many processes as possible on the computer. Maybe one of them is changing the system clock... – Ducharme Feb 25 '11 at 09:58
2

The `Stopwatch` class is implemented by using P/Invoke to call the native `QueryPerformanceCounter` function, and doing it yourself instead of using the `Stopwatch` class shouldn't make a difference. – Martin Liversage Apr 17 '13 at 09:06
@Martin: I never knew why on that machine (which was corporate tweaked by copying files and registry settings) the stopwatch was wrong by a mile. – Wernight Apr 26 '13 at 08:17

score -1 · Answer 7 · answered Feb 25 '11 at 05:43

-1

I believe you'll find the answer here: http://social.msdn.microsoft.com/Forums/en-US/netfxbcl/thread/eec73d6e-f597-4342-be48-5d2ce30202f0/

but for more detail and explanation see also: http://msdn.microsoft.com/en-us/magazine/cc163996.aspx http://stackoverflow.com/questions/394020/stopwatch-accuracy http://msdn.microsoft.com/en-us/library/system.diagnostics.stopwatch.aspx

answered Feb 25 '11 at 05:43

Elroy Flynn

3,032
1
24
33

1

The links you mentionned are about resolution accuracy of the counters. My issue is not about the class giving few more milliseconds than expected, but having a lot less! Only the NOTE section on MSDN is helpful and I tested with ProcessThread.ProcessorAffinity like suggested by Microsoft. – Ducharme Feb 25 '11 at 07:04
I found this article http://support.microsoft.com/kb/896256 and checked the library version on my computer. It is 5.1.2600.6055, so more recent than those in the patch (5.1.2600.3023). I added the registry key [HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Session Manager\Throttle] and ran my tests again with "PerfEnablePackageIdle"=dword:00000000 and "PerfEnablePackageIdle"=dword:00000001 (after rebooting the computer each time). I got the same results... – Ducharme Feb 25 '11 at 08:46

.NET System.Diagnostics.Stopwatch issue (returns values too low)

7 Answers7

Linked