Home Dashboard Directory Help
Search

Stopwatch returns negative elapsed time by Kent Boogaart


Status: 

Closed
 as Fixed Help for as Fixed


12
0
Sign in
to vote
Type: Bug
ID: 94083
Opened: 5/27/2006 6:16:42 PM
Access Restriction: Public
1
Workaround(s)
view
8
User(s) can reproduce this bug

Description

For small time periods the Stopwatch.Elapsed* properties can return negative values. This is counterintuitive at best. An elapsed period should never be < 0.
Details
Sign in to post a comment.
Posted by JamesJohnston on 3/16/2012 at 7:18 AM
Hello all: I learned this is a problem in the Windows API classes the Stopwatch uses itself. From the docs of QueryPerformanceCounter:

"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)."

Stopwatch works by calling this API when the stopwatch is started. When you measure the elapsed time with the stopwatch, it calls this API again and calculates the difference. If these two API calls happen on different processors, then you may get bitten by this. I'd guess that each processor must have its own counter that is not synchronized properly, and if one is significantly ahead of the other then you get bad results from this subtraction. This is seen as (1) negative results from stopwatch as originally identified here, (2) values of zero from newer versions of stopwatch that "fixed" the bug, (3) more subtle: the Elapsed property will return a value higher than expected.

If you want an accurate stopwatch, you MUST set processor affinity for the thread to only ONE processor (doesn't matter which one). That fixed the problem for me.

It would be nice if they'd document this in the .NET Stopwatch class - it would stop a lot of these questions; I had to examine the .NET Framework's source code and find the underlying Win32 API call to identify the issue.
Posted by RemyE06 on 11/15/2011 at 2:22 AM
I can reproduce the bug on .NET 4, sometimes the elapsed value jumps far under 0
Posted by JamesJohnston on 9/22/2011 at 12:47 PM
After some more digging since this wasn't mentioned in the comments before:

"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."

So you'll have to set thread affinity to only one processor first if you want 100% reliability. I confirmed that this fixes the problem in my VirtualBox virtual machine.
Posted by JamesJohnston on 9/22/2011 at 11:58 AM
I don't know how they can say this is fixed in .NET 4.0. I decompiled the Stopwatch class in both .NET 2.0 and .NET 4.0 using Reflector and then compared the differences. Besides the addition of the new Restart method, this is all I found for a difference:

    public void Stop()
    {
        if (this.isRunning)
        {
            long num2 = GetTimestamp() - this.startTimeStamp;
            this.elapsed += num2;
            this.isRunning = false;
// THE NEXT 4 LINES ARE NEW IN .NET 4.0:
            if (this.elapsed < 0L)
            {
                this.elapsed = 0L;
            }
        }
    }

So basically they set elapsed to 0 in the Stop method if the value is negative. There are still bugs IMHO:
1. What if the user reads any of the Elapsed properties before stopping the stopwatch? You might still get a negative value.
2. Resetting to 0 is not correct. *Some* time had to have elapsed, even if it was only a few microseconds!
3. It does nothing to handle the unusually large positive elapsed values that I and others have reported.
Posted by JamesJohnston on 9/22/2011 at 11:47 AM
Some code for my sample output:

0.01637
0.0467692
0.0918732
-0.3303107
0.0141431
0.0777333
0.4072037

^--- BUG: negative value!

.....

0.0624842
0.0139555
0.0156225
0.4538692
0.0463795
0.0138234

^---- BUG: Stopwatch elapsed value of 0.453 seconds, which is far more than the maximum 100 milliseconds allowed by the rng.Next(100) function call.
Posted by JamesJohnston on 9/22/2011 at 11:46 AM
I can reproduce this in VirtualBox 4.1.2 virtual machine under Windows XP SP3 with .NET Framework 2.0 RTM. Example:

class Program {
    static Random rng = new Random();
    static void Test() {
        Stopwatch sw = Stopwatch.StartNew();
        System.Threading.Thread.Sleep(rng.Next(100));
        Console.WriteLine(sw.Elapsed.TotalSeconds);
    }
    static void Main(string[] args) {
        for (int i = 0; i < 100; i++) {
            Test();
        }
    }
}
Posted by Adam Ralph on 2/1/2011 at 7:34 AM
Problem is not fixed. I have observed negative values being returned using .NET 3.5 on a virtual machine.
Posted by RichardJECooke on 10/16/2009 at 3:05 AM
I don't if this is supposed to be fixed under Window Mobile too, but I am having it happen for small, and occasionally big, times in .NET Compact Framework 3.5.
Posted by Spec8472 on 7/1/2009 at 8:20 PM
This occurrs for me continually when running code under Hyper-V. I get both extremely high and extremely low values (approx -122k and +122k ms)

Guest OSs: WS2003, WS2003 R2, WS2008
Host OS: WS2008

Host is Multiproc/Multicore (2x4 Core Xeon), Guest can be either Single or Multi Core.

Example Code:
while (true)
        {
            Stopwatch sw = new Stopwatch();
            sw.Start();
            sw.Stop();

            if (sw.ElapsedMilliseconds < 0)
                Debugger.Break();

        }

Also happens when doing real work within the stopwatch (eg: Calling remote webservice)
Posted by ICSim on 1/23/2009 at 7:21 PM
I cound not find any "attached project" as mentioned in the "Steps to Reproduce" point no 1. Please put a link to download the project. I am having the same issue as mentioned here. When I am trying to compute the time taken to process a request in a fast web service using Stopwatch I get -ve Elapsed time. The web service is installed on a virtual machine(VM) and is running Windows Server 2003 version 5.2 + sp2. Interestingly in one VM negative value shows up whereas in other it does not. Both VMs are having Windows Server 2003 version 5.2 + sp2. Any suggestion or explanation helps. Thanks.
Posted by ICSim on 1/23/2009 at 7:10 PM
Where is the download link?
Posted by Peter Zo on 5/30/2008 at 6:28 PM
I take it back. After installing the latest CPU drivers from AMD the problem is fixed.
Posted by Peter Zo on 5/30/2008 at 9:07 AM
This is definitely NOT fixed; I'm experiencing this problem right now with .NET framework 3.5 (latest updates). It seems to do this only on an AMD Opteron 1700 processor. The same code returns correct values for an Intel Core 2 Duo processor; both machines are running Windows Server 2003.
Posted by LeoTohill on 11/1/2007 at 9:17 AM
Why is this marked fixed? What is the fix information? I have repro'd the problem on .Net 2.0.

Sign in to post a workaround.
Posted by Kent Boogaart on 5/30/2006 at 9:03 PM
As a workaround, negative values can be ignored.

long elapsedMilliseconds = Math.Max(0, stopwatch.ElapsedMilliseconds);