Why is Stopwatch.ElapsedTicks negative?

[nickdu]

I've got a simple console app which I've written which makes use of the
Stopwatch class to do some measurements. Surprisingly, to me at least, some
of the Stopwatch.ElapsedTicks are negative. IsHighResolution is true and the
Frequency is 2,612,080,000. The entire application runs in a little over a
minute. Why would any of the elapsed times I'm measuring come out negative?

I searched around and found some examples of this, but the reason given was
arithmetic overflow. Even if I measured the elapsed time of the entire run
of the application is would only be roughly 60 * 2,612,080,000 ticks which
I'm pretty sure should fit in a long without going negative. Can someone
shed some light on this?

--
Thanks,
Nick

(e-mail address removed)
remove "nospam" change community. to msn.com

 

[Patrice]

Are you able to repro this behavior with say, 10 lines of code ? It would
allow us to try by ourself... I would print out values to see what is the
last positive value and what is the next negative value...

 

[Peter Duniho]

[...] Why would any of the elapsed times I'm measuring come out negative?

[...]
I'm pretty sure should fit in a long without going negative. Can someone
shed some light on this?

Stopwatch absolutely should be able to measure a minute's worth of time
without problem.

As Patrice implies, without a concise-but-complete code example it's
nearly impossible to comment on what might be happening. My best guess is
that somewhere along the line you're converting something to a 32-bit
int. But without seeing the code, we can't say one way or the other.

Pete

 

[nickdu]

I'll see if I can come up with a simple repro. For now I'll include a
snippet of the code which shows how I use the stopwatch instance.

long[] durations = new long[1024L * 1024L / bufferSize];
Stopwatch stopwatch = new Stopwatch();

Console.WriteLine("Ready to start writing. Press any key to continue.");
Console.ReadLine();
DateTime start = DateTime.Now;
Console.WriteLine("Starting.");

// Write buffers.

for (int i = 0; i < 1024 * 1024 / bufferSize; ++i)
{
stopwatch.Reset();
stopwatch.Start();
ulong offset = (ulong) i * 1024L * 1024L;
IntPtr dataView = Win32.File.MapViewOfFile(dataMap,
Win32.File.FILE_MAP_WRITE,
(uint) (offset >> 32), (uint) (offset & uint.MaxValue), (uint) bufferSize
* 1024);
if (dataView == IntPtr.Zero)
{
result = Marshal.GetLastWin32Error();
throw(new Win32Exception(result, string.Format(
"Failed mapping view ({0}, {1}) of file '{2}', result = {3}",
offset, bufferSize * 1024, args[0], result)));
}
try
{
Marshal.Copy(buffer, 0, dataView, buffer.Length);
}
finally
{
if (flushview == true)
{
Win32.File.FlushViewOfFile(dataView, (uint) bufferSize * 1024);
}
Win32.File.UnmapViewOfFile(dataView);
}

stopwatch.Stop();
durations = stopwatch.ElapsedTicks;
if (stopwatch.ElapsedTicks < 0)
{
Console.WriteLine("ElapsedTicks < 0, i = {0}, elapsed ticks = {1}, " +
"elapsed milliseconds = {2}, IsHighResolution = {3}, frequency = {4}",
i, stopwatch.ElapsedTicks, stopwatch.ElapsedMilliseconds,
Stopwatch.IsHighResolution, Stopwatch.Frequency);
}
}
DateTime end = DateTime.Now;
Console.WriteLine("Finished.");

long min = long.MaxValue;
long max = long.MinValue;
long average = 0;

for (int i = 0; i < durations.Length; ++i)
{
average += durations;
if (durations > max)
max = durations;
if (durations < min)
{
min = durations;
if (min < 0)
Console.WriteLine("Min has gone below zero, duration: {0}", durations);
}
}

Console.WriteLine("duration: {0}", end - start);
Console.WriteLine("min: {0}", min * 1000000 / Stopwatch.Frequency);
Console.WriteLine("max: {0}", max * 1000000 / Stopwatch.Frequency);
Console.WriteLine("average: {0}", (average / durations.Length) * 1000000 /
Stopwatch.Frequency);

--
Thanks,
Nick

(e-mail address removed)
remove "nospam" change community. to msn.com

[...] Why would any of the elapsed times I'm measuring come out negative?

[...]
I'm pretty sure should fit in a long without going negative. Can someone
shed some light on this?

Stopwatch absolutely should be able to measure a minute's worth of time
without problem.

As Patrice implies, without a concise-but-complete code example it's
nearly impossible to comment on what might be happening. My best guess is
that somewhere along the line you're converting something to a 32-bit
int. But without seeing the code, we can't say one way or the other.

Pete

 

[Peter Duniho]

I'll see if I can come up with a simple repro. For now I'll include a
snippet of the code which shows how I use the stopwatch instance.

Are you by any chance running this code on a multi-core CPU?

I don't recall the specifics, but I have some memory of there being a
CPU-affinity issue with Stopwatch, in which if the Stopwatch is started
while code is executing on one CPU core, and stopped on a different CPU
core, you get unreliable results.

I may be confusing your issue with something entirely different. But you
might try doing a little Googling on that specific question and see what
comes up.

Pete

 

[nickdu]

It is running on a multi-proc machine and that's one thought that came to
mind. What's the solution for getting high resolution timing on a multi-proc
machine?
--
Thanks,
Nick

(e-mail address removed)
remove "nospam" change community. to msn.com

 

[Wilson, Phil]

Try setting thread affinity to one processor in case that's the issue, The
docs for StopWatch seem to be recommending that, I quote:

On a multiprocessor computer, it does not matter which processor the thread
runs on. However, because of bugs in the BIOS or the Hardware Abstraction
Layer (HAL), you can get different timing results on different processors.
To specify processor affinity for a thread, use the
ProcessThread..::.ProcessorAffinity method.

 

[Armin Zingler]

It is running on a multi-proc machine and that's one thought that came to
mind. What's the solution for getting high resolution timing on a multi-proc
machine?

Have a look if this applies to your problem:
http://support.microsoft.com/kb/895980

 

[nickdu]

Isn't there a better way to get accurate high resolution timings? What about
the performance counter? Isn't there a high resolution performance counter
timer, or something like that? That's what I assumed the stopwatch used.
--
Thanks,
Nick

(e-mail address removed)
remove "nospam" change community. to msn.com

 

[Peter Duniho]

Isn't there a better way to get accurate high resolution timings? What
about
the performance counter? Isn't there a high resolution performance
counter
timer, or something like that? That's what I assumed the stopwatch used.

AFAIK, it does, when it's available.