Why does the Stopwatch value change by an order of 10 with a Thread.Sleep?

Question

I'm seeing this very strange behavior with the Stopwatch object that I can't explain, in my code. I wrote this very simple application to reproduce the behavior and it's still there. In a brief summary, if I add a Thread.Sleep(1) in the loop, but outside of the timing portion, it changes the loop's time by an order of 10.

Here is the complete code.

public static void DoStuff()
{
    long ticks;
    double seconds;

    ticks = Stopwatch.GetTimestamp();

    if (ticks % 2 == 0)
    {
        ticks = ticks / Stopwatch.Frequency;
    }
    else
    {
        seconds = ticks / Stopwatch.Frequency;
    }
}

static void Main(string[] args)
{
    const int loopCount = 1000;
    List<double> times;

    Console.WriteLine("Loops = " + loopCount);

    // No sleep
    times = new List<double>();
    for (int i = 0; i < loopCount; i++)
    {
        Stopwatch sw = Stopwatch.StartNew();
        DoStuff();
        sw.Stop();

        times.Add(sw.Elapsed.TotalSeconds);

        // Thread.Sleep(0);
    }

    Console.WriteLine();
    Console.WriteLine("--- No sleep ---");
    Console.WriteLine("Average = " + times.Average() + " s");
    Console.WriteLine("Average = " + (times.Average() * 1000000000).ToString("N2") + " ns");

    // Sleep
    times = new List<double>();
    for (int i = 0; i < loopCount; i++)
    {
        Stopwatch sw = Stopwatch.StartNew();
        DoStuff();
        sw.Stop();

        times.Add(sw.Elapsed.TotalSeconds);

        Thread.Sleep(1);
    }

    Console.WriteLine();
    Console.WriteLine("--- Sleep ---");
    Console.WriteLine("Average = " + times.Average() + " s");
    Console.WriteLine("Average = " + (times.Average() * 1000000000).ToString("N2") + " ns");

    Console.WriteLine();
    Console.Write("Press any key to continue...");
    Console.ReadKey();
}

Here are the results of running that piece of code, and it is consistent. I can run this a few tens of times and if I have a Sleep(1) in there then the stopwatch timing changes completely. I don't know which number to believe. I do understand that Sleep(0) doesn't actually put the thread to sleep, just requeues it. However, the same behavior happens if I do a Sleep(0) or if I just comment out that line of code.

I have tried only instatiating the Stopwatch object just once and calling Restart(), Reset(), and Start(), but that didn't make a difference either. I don't know if this is more of a threading question or Stopwatch issue.

Thank you for taking a look.

Answer 1

The default timer resolution on Windows is 15.6 ms, so all your sleeps are by default going to be approximately a multiple of 15.6 ms.

It's possible to increase the resolution of the timer by calling the Windows API timeBeginPeriod()

You would need to call timeendperiod() to return to the normal resolution.

You can call these from C# using the following P/Invokes:

[DefaultDllImportSearchPaths(DllImportSearchPath.System32)]
[DllImport("winmm.dll", EntryPoint="timeBeginPeriod", SetLastError=true)]
public static extern uint TimeBeginPeriod(uint uMilliseconds);

[DefaultDllImportSearchPaths(DllImportSearchPath.System32)]
[DllImport("winmm.dll", EntryPoint="timeEndPeriod", SetLastError=true)]
public static extern uint TimeEndPeriod(uint uMilliseconds);

NOTE: It's not really advisable to mess around with this, because it's a system-wide setting, so changing it will affect all apps. I'm just posting this information so you can play around with it if you want to experiment.

On Windows, the Stopwatch class is implemented using the Windows API QueryPerformanceCounter() which is not affected by the current windows timer resolution, and hence is a lot more accurate and precise.

Answer 2

As you mention Sleep(0) will just allow the scheduler to run something else, in most cases you will have cores available, and the program will just continue to run.

Sleep(1) on the other hand will actually suspend the thread, likely for a full 16ms, and the CPU will just be idle if there is nothing else to run. But you are not measuring the sleep, only the time of DoStuff(), so why does it matter?

A likely explanation is caches. If your thread gets suspended for what amounts to an eternity in CPU time, it is very likely that any data in the CPU caches will get discarded and replaced. So when the thread eventually get to run again it has to fetch things from main memory, since a main memory access takes on the order of 100ns, a few cache misses could easily explain the difference in time.

Another possible explanation is frequencies and power. If the CPU is idle it will reduce frequency and power, as it starts working it will take some time to ramp up again. The details are rather complicated, and will vary between processors.

But in any case it is likely that you are measuring differences in actual CPU time. You might be able to use intel VTune if you really want to dig into the details of what the CPU is doing.