Stopwatch inconsistent behavior when initialized using StartNew()

Question

Doing some performance tests I find the following behavior that seems wrong or counterintuitive.

Does anyone know what can be due?

The following occurs: If I initialize a watch with StartNew() the results seem inconsistent. The same is not true if I create an instance of StopWatch. I leave a sample to reproduce the case with an integer sort function.

Incongruous case:

int[] orderedArray = new int[1000000];
int[] unorderedArray = new int[1000000];

for (int i = 0; i < 999999; i++)
{
    orderedArray[i] = i;
}
for (int i = 999999; i > -1; i--)
{
    unorderedArray[i] = i;
}

Console.WriteLine(Environment.NewLine);
Console.WriteLine($"Init: {nameof(orderedArray)}");
Stopwatch watch = Stopwatch.StartNew();
Array.Sort(orderedArray);
watch.Stop();
long elapsedTicks = watch.ElapsedTicks;
long elapsedMs = watch.ElapsedMilliseconds;
Console.WriteLine($"End: {nameof(orderedArray)}");
Console.WriteLine($"{nameof(orderedArray)}|{elapsedTicks} ticks|{elapsedMs} ms");

Console.WriteLine(Environment.NewLine);

Console.WriteLine($"Init: {nameof(unorderedArray)}");
watch = Stopwatch.StartNew();
Array.Sort(unorderedArray);
watch.Stop();
elapsedTicks = watch.ElapsedTicks;
elapsedMs = watch.ElapsedMilliseconds;
Console.WriteLine($"End: {nameof(unorderedArray)}");
Console.WriteLine($"{nameof(unorderedArray)}|{elapsedTicks} ticks|{elapsedMs} ms");
Console.WriteLine(Environment.NewLine);

Correct case (using a new instance of StopWatch then Start-Stop):

Console.WriteLine(Environment.NewLine);
Console.WriteLine($"Init: {nameof(orderedArray)}");
Stopwatch watch2 = new();
watch2.Start();
Array.Sort(orderedArray);
watch2.Stop();
long elapsedTicks2 = watch2.ElapsedTicks;
long elapsedMs2 = watch2.ElapsedMilliseconds;
Console.WriteLine($"End: {nameof(orderedArray)}");
Console.WriteLine($"{nameof(orderedArray)}|{elapsedTicks2} ticks|{elapsedMs2} ms");

Console.WriteLine(Environment.NewLine);

Console.WriteLine($"Init: {nameof(unorderedArray)}");
watch2.Reset();
watch2.Start();
Array.Sort(unorderedArray);
watch2.Stop();
elapsedTicks2 = watch2.ElapsedTicks;
elapsedMs2 = watch2.ElapsedMilliseconds;
Console.WriteLine($"End: {nameof(unorderedArray)}");
Console.WriteLine($"{nameof(unorderedArray)}|{elapsedTicks2} ticks|{elapsedMs2} ms");
Console.WriteLine(Environment.NewLine);

Results:

Init: orderedArray
End: orderedArray
orderedArray|129247 ticks|12 ms

Init: unorderedArray
End: unorderedArray
unorderedArray|63792 ticks|6 ms

Init: orderedArray
End: orderedArray
orderedArray|61332 ticks|6 ms

Init: unorderedArray
End: unorderedArray
unorderedArray|73364 ticks|7 ms

Put them both in same file you can reproduce directly. ¿What is happening? :)

Edit: By my understanding both should have same output. Actually it is not. And also first case says that best sorting case take more time than worst case. I don't know if it's a bug or some expected behavior of StopWatch.

Thanks in advance.

Answer 1

If you want to do a proper (micro)benchmarking you should look into corresponding tools, like BenchmarkDotNet which is created by people with corresponding expertise.

As for your question - assuming that by "inconsistent" you mean the first sort time output being bigger than the later ones it is not Stopwatch issue (just use the Stopwatch.StartNew approach second after running Stopwatch watch2 = new();) it is related to how .NET is executed - runtime needs to load appropriate assemblies and JIT (Just In Time) compile methods/classes from them on the first usage which will result in the "performance hit" you see for the first sort invocation (see Managed Execution Process doc).