[Perf][x86 & x64] Investigate performance regression in SpectralNorm_3

[nategraf]

There appears a 25% performance regression in release/2.1 as compared 7f14336

A possible cause for this regression has yet be found

[AndyAyersMS]

I'll investigate.

[AndyAyersMS]

Locally when I run this master/2.1 is considerably faster than 2.0 (~350 vs ~610). Raw numbers are nothing like what benchview sees (~2500 for 2.0, ~3200 for master/2.1). But this test is multithreaded (creating 100 tasks by default) and so absolute perf will be very machine dependent.

Looking at the benchview history for master we see the same stable perf level since October 2017 (test was introduced in September 2017 but can't quite see back that far). And 2.0 has always been around ~2500 right from the introduction of the test.

So if this is a regression whatever introduced it happened sometime between roughly April 2017 (when we branched for 2.0) and October 2017 when we already see master slower.

Or perhaps there is something different about how we are making measurements for 2.0 from master/2.1 in a way that critically effects this test but not most other tests. IIRC the "stability prefix" we use for actual measurements may involve setting thread affinity and that might have a dramatic distorting effect on multithreaded tests like this one.

Need to do some more digging.

[AndyAyersMS]

Hmm, can't repro the local numbers above. Think I was looking at the wrong results files.

Trying to be careful this time: locally master/2.1 and 2.0 look comparable, both around 880ms. The stability prefix does not seem to have any effect on either set of runs.

Run commands from automation seem comparable. But results are quite different, both in absolute time and also comparative times.

2.0

START "CORECLR_PERF_RUN" /B /WAIT /HIGH /AFFINITY 0x2
corerun.exe PerfHarness.dll "C:\J\w\perf_perflab_---9e4a1ef8\sandbox\spectralnorm-3.exe"
--perf:runid "Perf-Off" --perf:collect stopwatch

2.1

START "CORECLR_PERF_RUN" /B /WAIT /HIGH /AFFINITY 0x2
C:\j\w\perf_perflab_---0a4d2934\bin\sandbox\corerun.exe PerfHarness.dll C:\j\w\perf_perflab_
  ---0a4d2934\bin\sandbox\spectralnorm-3.exe 
--perf:outputdir C:\j\w\perf_perflab_
  ---0a4d2934\bin\sandbox_logs\Microbenchmarks\Off\spectralnorm-3 
--perf:runid Perf-Off --perf:collect stopwatch

So I can't yet explain why automation is so much slower than a local run, or why it sees 2.1 as so much slower than 2.0.

Am going to rerun on a machine with fewer cores. That might change the absolute times, but it is harder to imagine it would change the relative times.

[AndyAyersMS]

Similar results on my laptop (2 physical cores, 4 with HT), both run in around 1060ms, affinity has no real impact, fairly low spread in results.

If we look at raw CI perf runs there's not much results spread either, despite the small number of iterations. So the runs on the perf machines are self-consistent and not very noisy.

2.0:

 Test Name                              | Metric   | Iterations |  AVERAGE | STDEV.S |      MIN |      MAX
:-------------------------------------- |:-------- |:----------:| --------:| -------:| --------:| --------:
 BenchmarksGame.SpectralNorm_3.RunBench | Duration |     4      | 2603.707 |   9.222 | 2592.974 | 2612.897

And as I noted above the historical 2.0 results show it has more or less always run at this speed (ignoring some occasional glitches):

2.1:

 spectralnorm-3.exe                     | Metric   | Unit | Iterations |  Average | STDEV.S |      Min |      Max
:-------------------------------------- |:-------- |:----:|:----------:| --------:| -------:| --------:| --------:
 BenchmarksGame.SpectralNorm_3.RunBench | Duration | msec |     4      | 3253.389 |   9.614 | 3244.267 | 3264.946

And likewise the master/2.1 results have always more or less run at the same speed (note we run perf tests in master much more frequently than on release branches, so we have a lot of data):

Unfortunately the official CI perf runs with HW perf counter data don't seem comparable; likely we did work during the 2.1 cycle to reduce overhead and so it makes the 2.1 vs 2.0 measurements here incomparable.

So I think the next step here is to get access to the actual perf HW and see if we can repro these results running manually; if so we can get some profiles and figure out what is going on.

@nategraf @jorive can you help with this?

[jorive]

@AndyAyersMS Please let me know if you need me to reserve a machine in the lab for investigation.

[AndyAyersMS]

Yes, I need access to a lab machine.

[AndyAyersMS]

Did some runs on the perf lab HW, and I can repro the regression there. It is tied to the stability prefix, in particular to setting thread affinity:

spectralnorm-3	Metric	Unit	Iterations	Mean	STDEV.S	Min	Max
2.0 no prefix	Duration	msec	16	639.894	4.617	637.742	656.926
2.1 no prefix	Duration	msec	15	667.185	6.502	661.895	687.407
2.0 with prefix	Duration	msec	4	2599.272	11.594	2586.324	2610.575
2.1 with prefix	Duration	msec	4	3248.472	8.076	3239.435	3259.090

I don't know yet why this only happens on the perf machines and what is different in 2.1 than in 2.0. But it is likely not a jit regression.

I played around a bit with varying the affinity mask for the 2.1 perf runs. Can't really explain these results either. More cores is generally better, but not in any simple fashion.

Perf lab machine is a i7-4790 (1 socket, 4 cores, 8 cpus) running Win16 server. My laptop processor has same physical configuration but is running Win 10 and doesn't show this behavior.

So this could be an OS thing or the way the Server OS interacts with the task scheduler?

@stephentoub any ideas on what to look at here? Did we change something about how tasks are distributed in 2.1 vs 2.0, and/or made the behavior more OS version dependent?

Note this benchmark fires up 100 Environment.ProcessorCount tasks then waits for them one by one in the order they were created. Seems like a wait all would be more appropriate and waiting serially like this might explain the odd behavior below...?

Affinity mask	Average	STDEV.S	Min	Max
0x1	3248.244	8.379	3241.980	3260.136
0x2 (stability prefix)	3250.356	9.840	3241.167	3261.601
0x4	3245.788	9.951	3236.338	3257.570
0x3	2592.315	57.257	2545.437	2672.468
0x6	1807.702	250.600	1627.199	2298.042
0x7	1801.594	13.978	1779.896	1821.446
0xE	1749.836	12.811	1731.187	1766.686
0xF	1483.385	370.838	1325.545	2319.622
0xAA	915.915	253.019	805.230	1660.661
0xEE	854.612	162.752	791.240	1367.983
0xEF	839.430	158.993	771.751	1340.725
0xFE	945.872	280.420	817.504	1785.285
0xFF	639.217	0.666	637.626	640.427

[stephentoub]

@stephentoub Stephen Toub FTE any ideas on what to look at here? Did we change something about how tasks are distributed in 2.1 vs 2.0, and/or made the behavior more OS version dependent?

Not to my knowledge, though there have been some changes related to spinning, which maybe could impact this? cc: @kouvel

[AndyAyersMS]

Oops, misread the code, the test actually creates Environment.ProcessorCount tasks. So that might explain a bit more about the odd impact of affinity.

[AndyAyersMS]

A crude linear model for an 8 CPU machine would look something like the following (with N ~ 370, K ~ 270, fitting to the endpoints):

Cpus	Predicted	Observed	Model
1	8N + K	3250	3250
2	4N + K	1800, 2590	1750
3	3N + K	1800, 1740	1380
4-7	2N + K	915, 1480	1010
8	1N + K	640	640

So it is in the ballpark...

[AndyAyersMS]

Also work is divided up into 8 chunks, but the last chunk gets all the leftovers too. So for the default length 100 we have 7 tasks each running 12 iterations, and one task running 16. So for cases where number of tasks is not divisible by number of available CPUs we would expect ~33% variance as the overall time depends on when the longer task is run. And we sort of see that above.

Official benchmark games run rules start with length 5550 so the task size discrepancy is less there.

[AndyAyersMS]

Did some profiling and verified we are indeed running on just one CPU in both cases.

And it does indeed look like the spin wait cost is higher in master/2.1 than in 2.0. Again this is taken from the odd case where we've affinitized down to one CPU -- not sure it is interesting in general.

I will look at the non-affinitized case next as it still seems to run a bit slower than it did in 2.0.

2.0 profile (with /affinity 0x2):

2.1/master profile (with /affinity 0x2):

@jorive as we discussed privately we should stop setting CPU affinity for the various benchmarks that run on multiple CPUs. I'll open an issue for you on this soon with a list of the tests to exclude.

[kouvel]

Most of the ThreadNative::SpinWait time seems to come from Barrier.DiscontinuousWait -> ManualResetEventSlim.Wait. The spin strategy used there (SpinWait struct's spin strategy) has changed in multiple ways, including to normalize the minimum delay per Thread.SpinWait(1) to the delay on Skylake processors (which significantly increased the pause instruction's delay), to change the back-off scheme, and to cap the delay to a max.

According to profiles with and without affinitizing the test seems to spend a significant amount of time spinning.

On pre-Skylake processors, the first few iterations of a spin-wait would be longer than before, and subsequent iterations would be shorter to much shorter than before. In this particular case, the test seems to synchronize threads on a barrier very frequently, and the spin-wait likely succeeds within those first few iterations, which have a longer delay now. As a result, this is taking longer on pre-Skylake processors.

On Skylake processors, the first few iterations would be shorter than before due to spin strategy changes, so the time spent spinning is less and the test runs faster.

The changes above are by design and the behavior seen here is also in line with expectations.

[kouvel]

Affinity is/was not taken into account for spinning in most places in coreclr/corefx, only the logical processor count. It would probably only matter for when the process is affinitized to one CPU, but I'm not sure if that is a common scenario.