Execution time measured by two different stopwatches

Question

I want to analyse the execution time of method Tuple<A,B,C,D> Calculate().

What I did is the following:

Tuple<A, B, C, D, E>
Calculate(Line l, Path p)
{
    var stopwatch = new System.Diagnostics.Stopwatch();
    stopwatch.Start();

    var rv = Calculate2(l, p);

    System.Diagnostics.Debug.WriteLine($" stopwatch.ElapsedMilliseconds} ms;");
    }

    return rv;
}


Tuple<A, B, C, D, E>
Calculate2(Line l, Path p)
{
    var stopwatch = new System.Diagnostics.Stopwatch();
    stopwatch.Start();

    A a = ...; B b = ...; C c = ...; D d = ...; E e = ...
    ... content of this method

    System.Diagnostics.Debug.WriteLine($" stopwatch.ElapsedMilliseconds} ms;");

    return Tuple.Create(a,b,c,d,e);
}

The first measurement gives 28 ms, the second one only 8 ms (every time).
Does this mean that the return statement takes 20 ms?
I find this impossible to believe..?

It is not a Tuple-issue: I tried a struct tuple and an explicit class, with the exact same result.

EDIT
I added a static stopwatch in the class and found that immediately on entrance of Calculate2(..) the static stopwatch shows a 20 ms delay.

I wonder whether this might have to do with JIT compliation of the method.
I added a second run after the first and it didn't show a delay.
As a matter of fact the delay was in the first call to that function and for some other reason I assumed this first one was the bottleneck.

Indeed! However I found that this cannot explain the difference 8/28 because in both cases the same amount of Debug.Writeline's are executed. — Gerard, Apr 19 '18 at 10:19
From the timer point of view, calling the first one calls the second one entirely, so Debug.WriteLine completely and tuple creation; whereas calling the second one is just building the five variables. — Bentoy13, Apr 19 '18 at 10:22
Yes, you measured the jitter overhead. 20 msec is a bit on the high end, so it probably also includes disk overhead, the cost of finding one or more framework assemblies. — Hans Passant, Apr 19 '18 at 12:45
Thank you @HansPassant for the comment. This is a pitfall when evaluating performances. — Gerard, Apr 20 '18 at 07:33

score -1 · Answer 1 · answered Apr 19 '18 at 10:02

-1

Stopwatch sw = new Stopwatch();
sw.Start();
//do some work
Thread.Sleep(TimeSpan.FromSeconds(30));
sw.Stop();

var totalTimeElapsed = sw.Elapsed.TotalMilliseconds;
var milSecs = sw.ElapsedMilliseconds;

You will need to use Elapsed.TotalMilliseconds instead of ElapsedMilliseconds. You can find a good explanation here

ElapsedMilliseconds might be giving you unexpected results.

answered Apr 19 '18 at 10:02

BossRoss

869
2
11
31

That answer details something completely different and revolves around using `.Elapsed.TotalMilliseconds` vs `.Elapsed.Milliseconds`, which goes through `TimeSpan`. This is **completely different** from what the question is about. The main difference between `.ElapsedMilliseconds` and `Elapsed.TotalMilliseconds` is rounding, nothing more. This may be relevant to the question, but the linked answer is not. The difference between the two values in your code, when I run it on my computer, is on the size of .7ms, which is far less than the OP's observed difference of 8. – Lasse V. Karlsen Apr 19 '18 at 10:14
The difference of 20/28 is not a rounding issue, and indeed both give the exact same result. Thanks for the effort, but it must be something else. – Gerard Apr 19 '18 at 10:17
@LasseVågsætherKarlsen it is more than a rounding issue. A stopwatch at 1.234 seconds would return 234 in the property of ElapsedMilliseconds. A stopwatch stopped at 1.23456 seconds would return 1234.56 in the property of TimeSpan.TotalMilliseconds. But as Gerard said, this is not the issue but it did catch me out once or twice. – BossRoss Apr 19 '18 at 10:21
No, it would not, StopWatch.ElapsedMilliseconds will return 1234, however, Stopwatch.Elapsed.Milliseconds will return 234, but the OP isn't using that. – Lasse V. Karlsen Apr 19 '18 at 13:02

Execution time measured by two different stopwatches

1 Answers1