.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;
    }
}

Answer 1

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.

Answer 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}");