Report test execution time at a higher resolution

We should probably try to find out if the use of Stopwatch consumes too many resources on it's own, as compared to DateTime. If so, we can make the higher resolution an option. We should not use an option unnecessarily, however.

I probably missed the discussion, but was there a specific requirement behind the need for a lower resolution?

There was one with Jiri, but I'm not sure if it was on the list or
offline now. Anyway, subsequent discussion seems to show that his
interest is in measuring parts of the test - for example, test case
generation versus setup versus the actual test versus teardown. That's
an entirely different matter and I'll wait for him to write something
about it.

My interest is in the resolution of what we are already measuring. The
issue came up because of how NUnit reports results to VS2012. MSTest
tests show up frequently with timings displayed as '< 1ms' but NUnit
shows a blank or some multiple of 10 to 15ms. Seems to me that if we
are measuring elapsed time, we want it to be accurate for normal
ranges of execution. These days, micro tests run very fast so we need
better resolution and precision of timing than we did in the early
days of NUnit.

I just finished running some benchmarks using two Stopwatches. The
inner Stopwatch measured the time to execute a test for a given number
of repetitions, while the outer one measured that plus the overhead of
the inner stopwatch. The test itself was very fast - it simply
returned Math.Sqrt(d), where d was the iteration count.

Over repetitions from 100 to 100,000 I found that the results were
fairly consistent. The other stopwatch time is a bit less than double
the inner stopwatch. My test itself ran in 10 to 12 nanoseconds on my
laptop, while the stopwatch overhead averaged between 7 and 10
nanoseconds.

In a second set of tests, I measured the time it takes to run my test
method plus two calls to DateTime.Now, one before and one after, which
is our current approach. Using DateTime.Now, my test now ran in a
range from 150 to 200 nanoseconds, that is 15 to 20 times the overhead
of Stopwatch. There doesn't seem to be a downside here.

I think the next step is to actually spike an implementation to see
what the impact is with a set of real tests. Since NUnitLite has
pretty fast tests, that seems to be a good place to start.

Charlie

On Sun, Oct 28, 2012 at 9:17 AM, Simone Busoli
<email address hidden> wrote:
> I probably missed the discussion, but was there a specific requirement
> behind the need for a lower resolution?
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1072379
>
> Title:
> Report test execution time at a higher resolution
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/nunit-3.0/+bug/1072379/+subscriptions

Hello everyone,

Just a few notes on the current stopwatch implementation of microsoft, it has a few issues on multicore systems :
(noted in the reference page http://msdn.microsoft.com/en-us/library/system.diagnostics.stopwatch.aspx)

in short 1): if the stopwatch instance is used on a thread for which the processor affinity is not set to a single logical core, the stopwatch measurements are unreliable (they will report negative times, unbelieavable times like 100 times the amount).

2) from my personal experience with this class, i tried to work arround this (setting processor afinity is clearly what you dont want to deal with) using the StopWatch.GetTimeStamp() method which is supposed give a high resolution timer if the underlying system supports it. this amount of ticks can be converted into ms like that:

var start = StopWatch.GetTimeStamp();
var end = StopWatch.GetTimeStamp();
long elapsedms = ((end - start) / StopWatch.Frequency;

On the plus side, this static method might be lighter and lower level than the instance usage.

Btw, thanks for your hard work.

Thanks for the suggestion. The current implementation creates a
stopwatch for each test, so use of the static method might be better
anyway.

Charlie

On Thu, Nov 15, 2012 at 2:53 AM, Geoffroy Querol
<email address hidden> wrote:
> Hello everyone,
>
>
> Just a few notes on the current stopwatch implementation of microsoft, it has a few issues on multicore systems :
> (noted in the reference page http://msdn.microsoft.com/en-us/library/system.diagnostics.stopwatch.aspx)
>
> in short 1): if the stopwatch instance is used on a thread for which the
> processor affinity is not set to a single logical core, the stopwatch
> measurements are unreliable (they will report negative times,
> unbelieavable times like 100 times the amount).
>
> 2) from my personal experience with this class, i tried to work arround
> this (setting processor afinity is clearly what you dont want to deal
> with) using the StopWatch.GetTimeStamp() method which is supposed give a
> high resolution timer if the underlying system supports it. this amount
> of ticks can be converted into ms like that:
>
> var start = StopWatch.GetTimeStamp();
> var end = StopWatch.GetTimeStamp();
> long elapsedms = ((end - start) / StopWatch.Frequency;
>
> On the plus side, this static method might be lighter and lower level
> than the instance usage.
>
>
> Btw, thanks for your hard work.
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1072379
>
> Title:
> Report test execution time at a higher resolution
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/nunit-3.0/+bug/1072379/+subscriptions

Re-opening this in the NUnitLite project in order to apply Geoffroy's suggestion.