ByteMark BenchBitOps regression

[AndyAyersMS]

Benchview indicates this regression is likely from dotnet/coreclr#22180.

cc @Maoni0

This particular test is known to be very sensitive to GC overhead on Linux. See for instance #11548.

[AndyAyersMS]

Also cc @jorive; spotted this from the weekly mail.

[Maoni0]

thanks Andy. looping in @Andy-MS.
how do we get this test? I searched the whole repo and it came up with nothing...

[jorive]

@Maoni0 This is the benchmark: https://github.com/dotnet/coreclr/blob/master/tests/src/JIT/Performance/CodeQuality/Bytemark/ByteMark.cs#L1330

I tried running this benchmark our linux machine and saw time actually decrease.

In both cases, ran this test:

py ./tests/scripts/run-xunit-perf.py -arch x64 -configuration Release -os linux -runtype local -optLevel full_opt -jitName ryujit -outputdir "$clr/bin/sandbox_logs" -testBinLoc ./bin/tests/Linux.x64.Release/JIT/Performance/CodeQuality/Bytemark

A "before" clr was at commit 930abba (the commit before dotnet/coreclr#22180), and an "after" clr was at commit ed52a00 .

This is on a machine with 64GB memory and 4 processors (8 logical processors).
In both cases I forced 30 iterations by setting $env:XUNIT_PERFORMANCE_MIN_ITERATION = 30.
"before" had an average of 860 ms (stdev 34ms), and "after" had an average of 837ms (stdev 8ms).

I also have a simple test file that just allocates a large array in a loop; and similarly shows a slight improvement in performance for "after". (I suspect this is basically what BenchBitOps is doing; see dotnet/coreclr#22783)

Update: ran with -stabilityPrefix "taskset 0x00000002 nice --adjustment=-10" to decrease variation; now takes 898ms (±6) before and 853ms (±2) after.

[Maoni0]

I'll close this and if you do not agree with what @Andy-MS said above please feel free to reactivate.

[AndyAyersMS]

Benchview / xunit-perf is still convinced this is a regression; seems like it is worth understanding why. The previous time this test regressed, there were real issues with cgroups.

Now this may be a perf harness artifact. Perhaps we can back-test this using the new performance repo and see if it sees a regression ... ?

cc @adamsitnik

[Maoni0]

we don't seem to be able to repro this. @adamsitnik can you please help?

[jorive]

There is an implicit, and not so obvious way on how the benchmarks run in Jenkins with xunit-performance. They run as high priority on a single core (affinity 0x2). The command to run the benchmarks, with the old harness, needs to be prefixed with the following commands:

• On Windows, START "CORECLR_PERF_RUN" /B /WAIT /HIGH /AFFINITY 0x2
• On Linux (Ubuntu in this case), taskset 0x00000002 nice --adjustment=-10

On the other hand, I tried running the benchmarks from dotnet/performance on Windows. The command I used is below, and an equivalent command can be run on Linux.

py.exe .\scripts\benchmarks_ci.py -f netcoreapp3.0 netcoreapp2.1 netcoreapp2.2 -c Release --filter *BenchBitOps* --dotnet-compilation-mode FullyJittedNoTiering

These are the results (we have improved performance on latest framework):

Framework	Method	Mean	Error	StdDev	Median	Min	Max	Gen 0/1k Op	Gen 1/1k Op	Gen 2/1k Op	Allocated Memory/Op
netcoreapp2.1	BenchBitOps	636.0 ms	44.16 ms	50.86 ms	612.2 ms	580.8 ms	765.4 ms	4166000.0000	4166000.0000	4166000.0000	12.21 GB
netcoreapp2.2	BenchBitOps	623.8 ms	6.678 ms	6.246 ms	621.2 ms	616.3 ms	638.2 ms	4166000.0000	4166000.0000	4166000.0000	12.21 GB
netcoreapp3.0	BenchBitOps	620.1 ms	4.848 ms	4.535 ms	619.5 ms	613.7 ms	628.8 ms	4166000.0000	4166000.0000	4166000.0000	12.21 GB

Finally, I ran the benchmarks affinitized with high priority, and I got this:

Framework	Method	Mean	Error	StdDev	Median	Min	Max	Gen 0/1k Op	Gen 1/1k Op	Gen 2/1k Op	Allocated Memory/Op
netcoreapp	Method	Mean	Error	StdDev	Median	Min	Max	Gen 0/1k Op	Gen 1/1k Op	Gen 2/1k Op	Allocated Memory/Op
netcoreapp2.1	BenchBitOps	617.7 ms	1.816 ms	1.699 ms	617.7 ms	614.7 ms	620.6 ms	4166000.0000	4166000.0000	4166000.0000	-
netcoreapp2.2	BenchBitOps	620.3 ms	4.282 ms	3.576 ms	620.6 ms	611.7 ms	624.7 ms	4166000.0000	4166000.0000	4166000.0000	-
netcoreapp3.0	BenchBitOps	659.9 ms	3.449 ms	3.226 ms	660.3 ms	653.0 ms	665.7 ms	4166000.0000	4166000.0000	4166000.0000	-

All of the sudden, the results invert. I do not have more time at the moment to look more into it, but I hope this gives more light on the investigation.

Please let me know if you have any questions.

Cheers,

-José

[adamsitnik]

Perhaps we can back-test this using the new performance repo and see if it sees a regression

We started uploading the results from performance repo to BenchView at the beginning of March and the regression showed by @AndyAyersMS took place in Jan/Feb so we don't have the historical data to answer this question.

https://benchview/trendline?jobgroup=.NET%20Performance&branchId=762&jobgroup=.NET%20Performance&branchId=762&jobtype=rolling&count=200&rtids=[1713]&archids=[9,4]&mpids=[1292]&cfgids=[3394,3391,3392,3393]&

The BenchBitOps benchmark is very special. It allocates more than 12 GB of managed memory per single iteration and the time reported by BDN and xunit-performance is much different when running the benchmarks in a standalone process. I have verified the results reported by BDN with a hand-written Stopwatch-based benchmark when I was porting all the benchmarks. Please see dotnet/performance#36 (comment) for more details.

I remember that when @janvorli was investigating the previous regression in November (already using the performance repo) the other very helpful metric was the number of GC Collects which has doubled when something was wrong with cpugroup:

FWIW this metric is super stable and did not change since the beginning of March:

[janvorli]

the number of GC Collects which has doubled when something was wrong with cpugroup

It was not a matter of cpugroups (cgroups, to be precise). I just found it when testing a cgroups performance and it was unrelated to the cgroups stuff.
The enormous growth in GC collections was caused by the amount of free memory on the system. When the free memory went down under some threshold, the number of GCs has grown 5 times, causing the test to take ~2.5 longer to complete.

[adamsitnik]

@janvorli thank you for clarification and sorry for the misinformation (I updated my previous comment and crossed text out).

I ran the same test as @jorive above and saw performance improve in 3.0 both with and without affinity.

Without affinity:
[Host] : .NET Core 3.0.0-preview6-27629-01 (CoreCLR 4.6.27624.71, CoreFX 4.700.19.22901), 64bit RyuJIT -- mean 839ms
[Host] : .NET Core 2.2.3 (CoreCLR 4.6.27414.05, CoreFX 4.6.27414.05), 64bit RyuJIT -- mean 881ms
[Host] : .NET Core 2.1.9 (CoreCLR 4.6.27414.06, CoreFX 4.6.27415.01), 64bit RyuJIT -- mean 846ms

With affinity (prefixing with START "CORECLR_PERF_RUN" /B /WAIT /HIGH /AFFINITY 0x2):
[Host] : .NET Core 3.0.0-preview6-27629-04 (CoreCLR 4.6.27624.71, CoreFX 4.700.19.22901), 64bit RyuJIT -- mean 778ms
[Host] : .NET Core 2.2.3 (CoreCLR 4.6.27414.05, CoreFX 4.6.27414.05), 64bit RyuJIT -- mean 803ms
[Host] : .NET Core 2.1.9 (CoreCLR 4.6.27414.06, CoreFX 4.6.27415.01), 64bit RyuJIT -- mean 819ms

This may only be a regression on certain CPUs?