Experiment Report: Using BenchmarkDotNet to find methods that can cause longe GC pause times #1049
Description
I was asked by @jkotas if it would be possible to run a simple experiment using BenchmarkDotNet and find methods that can cause long GC pause times. Examples: https://github.com/dotnet/coreclr/issues/27106 https://github.com/dotnet/coreclr/issues/27683
I took the idea from following @jkotas example:
static void Main()
{
new Thread(() =>
{
var src = new int[10_000_000];
for (;;) Array.Sort(src);
}).Start();
for (;;) { Console.WriteLine("GC start"); GC.Collect(); Console.WriteLine("GC end"); Thread.Sleep(1); }
}And hacked BenchmarkDotNet to:
- start a new thread that runs the benchmark code with a heuristic that never stops running and does not report the results
- start a new benchmark on the startup thread that calls
GC.Collect(); Thread.Sleep(1);and reports the time it takes to execute it
So more or less the reported times were GC pause times.
More details: dotnet/BenchmarkDotNet@fb57a14
To verify that it works I've used the following example:
public class SimpleTest
{
private int[] array = Enumerable.Range(0, 1000).ToArray();
[Benchmark]
public void Sort() => Array.Sort(array);
[Benchmark]
public void Reverse() => Array.Reverse(array);
[Benchmark]
public void BubbleSort()
{
var arr = array;
int temp;
for (int write = 0; write < arr.Length; write++)
{
for (int sort = 0; sort < arr.Length - 1; sort++)
{
if (arr[sort] > arr[sort + 1])
{
temp = arr[sort + 1];
arr[sort + 1] = arr[sort];
arr[sort] = temp;
}
}
}
}
}Which has produced the following results for 2.1 (where the Array.Sort still calls native sort implementation and causes the problem):
BenchmarkDotNet=v0.12.0.20191121-develop, OS=Windows 10.0.18363
Intel Xeon CPU E5-1650 v4 3.60GHz, 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=5.0.100-alpha1-013817
[Host] : .NET Core 2.1.13 (CoreCLR 4.6.28008.01, CoreFX 4.6.28008.01), X64 RyuJIT
Job-JTLBSN : .NET Core 2.1.13 (CoreCLR 4.6.28008.01, CoreFX 4.6.28008.01), X64 RyuJIT
IterationTime=250.0000 ms MaxIterationCount=5 MinIterationCount=3
WarmupCount=1
| Method | Mean | Error | StdDev |
|---|---|---|---|
| Sort | 6,432.459 ms | 8,690.5440 ms | 2,256.9067 ms |
| Reverse | 2.047 ms | 0.2790 ms | 0.0724 ms |
| BubbleSort | 1.999 ms | 0.0237 ms | 0.0013 ms |
So as you can see the Reverse and BubbleSort despite doing more work for already sorted array report an order of magnitude less time than Sort.
