Regressions in System.Xml.Linq.Perf_XName (FullPGO)

Run Information

Architecture	x64
OS	Windows 10.0.18362
Baseline	215c328e039b3a6b6bfdc6514253307105f25816
Compare	ca6716a658137b55d29b3ce100d5d14eb0edd67e
Diff	Diff

Regressions in System.Xml.Linq.Perf_XName

Benchmark	Baseline	Test	Test/Base	Test Quality	Edge Detector	Baseline IR	Compare IR	IR Ratio	Baseline ETL	Compare ETL
NonEmptyNameSpaceToString - Duration of single invocation	19.80 ns	24.26 ns	1.22	0.18	False

Test Report

Repro

git clone https://github.com/dotnet/performance.git
py .\performance\scripts\benchmarks_ci.py -f net6.0 --filter 'System.Xml.Linq.Perf_XName*'

Details

Payloads

Baseline
Compare

Histogram

System.Xml.Linq.Perf_XName.NonEmptyNameSpaceToString

Description of detection logic

IsRegressionChecked: Marked as regression because the three check build points were 0.05 greater than the baseline.
IsImprovementBase: Marked as not an improvement because the compare was not 5% less than the baseline, or the value was too small.
IsRegressionBase: Marked as regression because the compare was 5% greater than the baseline, and the value was not too small.
IsRegressionChecked: Marked as regression because the three check build points were 0.05 greater than the baseline.
IsRegressionWindowed: Marked as regression because 24.260317557881482 > 21.467619909142417.
IsChangePoint: Marked as a change because one of 1/31/2022 1:37:35 PM, 2/1/2022 5:51:01 AM falls between 1/23/2022 2:39:24 PM and 2/1/2022 5:51:01 AM.
IsRegressionStdDev: Marked as regression because -27.429216259968307 (T) = (0 -23.97864052999163) / Math.Sqrt((0.403977404141772 / (75)) + (0.059125059664990244 / (4))) is less than -1.991254395387924 = MathNet.Numerics.Distributions.StudentT.InvCDF(0, 1, (75) + (4) - 2, .025) and -0.19395673620667156 = (20.08334121567448 - 23.97864052999163) / 20.08334121567448 is less than -0.05.
IsImprovementBase: Marked as not an improvement because the compare was not 5% less than the baseline, or the value was too small.
IsChangeEdgeDetector: Marked not as a regression because Edge Detector said so.

Docs

Profiling workflow for dotnet/runtime repository
Benchmarking workflow for dotnet/runtime repository

@AndyAyersMS

@AndyAyersMS, are you still looking into this? Should we assign a different owner in GC team?

I'll take over from here since this is prospectively a GC issue. Investigation in Progress.

Data

Without GC Normalization

There seems to be a regression within a 5% margin:

Benchmark Name	Baseline	Comparand	Baseline Mean Duration	Comparand Mean Duration	Δ Mean Duration	Δ% Mean Duration	Baseline number of iterations	Comparand number of iterations	Δ number of iterations	Δ% number of iterations	Baseline gc count	Comparand gc count	Δ gc count	Δ% gc count	Baseline median	Comparand median	Δ median	Δ% median	Baseline non induced gc count	Comparand non induced gc count	Δ non induced gc count	Δ% non induced gc count	Baseline total allocated (mb)	Comparand total allocated (mb)	Δ total allocated (mb)	Δ% total allocated (mb)	Baseline total pause time (msec)	Comparand total pause time (msec)	Δ total pause time (msec)	Δ% total pause time (msec)	Baseline gc pause time %	Comparand gc pause time %	Δ gc pause time %	Δ% gc pause time %	Baseline JIT_WriteBarrier	Comparand JIT_WriteBarrier	Δ JIT_WriteBarrier	Δ% JIT_WriteBarrier	Baseline JIT_ByRefWriteBarrier	Comparand JIT_ByRefWriteBarrier	Δ JIT_ByRefWriteBarrier	Δ% JIT_ByRefWriteBarrier
System.Xml.Linq.Perf_XName.NonEmptyNameSpaceToString	segments	writebarrier_3	19.37	19.85	0.48	2.48	18	15	-3	-16.67	2612	2497	-115	-4.4	19.27	19.62	0.35	1.8	2376	2257	-119	-5.01	25090.88	23737.18	-1353.7	-5.4	11.29	11.26	-0.03	-0.3	2.4	2.5	0.11	4.42	0	344	344	∞	0	0	0	NaN
System.Xml.Linq.Perf_XName.NonEmptyNameSpaceToString	segments	regions	19.37	19.46	0.09	0.44	18	15	-3	-16.67	2612	2530	-82	-3.14	19.27	19.27	-0.01	-0.03	2376	2290	-86	-3.62	25090.88	24207.49	-883.39	-3.52	11.29	11.41	0.12	1.07	2.4	2.58	0.19	7.74	0	0	0	NaN	0	0	0	NaN

Baseline - Segments

BenchmarkDotNet=v0.13.1.1847-nightly, OS=Windows 11 (10.0.22000.856/21H2)
Intel Core i9-10900K CPU 3.70GHz, 1 CPU, 20 logical and 10 physical cores
.NET SDK=7.0.100-preview.7.22377.5
[Host] : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2
Job-FQYTMY : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2

EnvironmentVariables=COMPlus_GCName=clrgc.dll PowerPlanMode=00000000-0000-0000-0000-000000000000 IterationTime=250.0000 ms
MaxIterationCount=20 MinIterationCount=15 WarmupCount=1

Method	Mean	Error	StdDev	Median	Min	Max	Gen 0	Allocated
NonEmptyNameSpaceToString	19.37 ns	0.438 ns	0.469 ns	19.27 ns	18.87 ns	20.32 ns	0.0076	80 B

Regions

BenchmarkDotNet=v0.13.1.1847-nightly, OS=Windows 11 (10.0.22000.856/21H2)
Intel Core i9-10900K CPU 3.70GHz, 1 CPU, 20 logical and 10 physical cores
.NET SDK=7.0.100-preview.7.22377.5
[Host] : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2
Job-HLWNHM : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2

PowerPlanMode=00000000-0000-0000-0000-000000000000 IterationTime=250.0000 ms MaxIterationCount=20
MinIterationCount=15 WarmupCount=1

Method	Mean	Error	StdDev	Median	Min	Max	Gen 0	Allocated
NonEmptyNameSpaceToString	19.46 ns	0.352 ns	0.329 ns	19.27 ns	19.09 ns	19.97 ns	0.0076	80 B

Regions w/ More Precise Writebarrier

BenchmarkDotNet=v0.13.1.1847-nightly, OS=Windows 11 (10.0.22000.856/21H2)
Intel Core i9-10900K CPU 3.70GHz, 1 CPU, 20 logical and 10 physical cores
.NET SDK=7.0.100-preview.7.22377.5
[Host] : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2
Job-QBQSZP : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2

EnvironmentVariables=COMPlus_GCWriteBarrier=3,COMPlus_EnableWriteXorExecute=0 PowerPlanMode=00000000-0000-0000-0000-000000000000 IterationTime=250.0000 ms
MaxIterationCount=20 MinIterationCount=15 WarmupCount=1

Method	Mean	Error	StdDev	Median	Min	Max	Gen 0	Allocated
NonEmptyNameSpaceToString	19.85 ns	0.429 ns	0.401 ns	19.62 ns	19.45 ns	20.66 ns	0.0076	80 B

With GC Normalization

Benchmark Name	Baseline	Comparand	Baseline Mean Duration	Comparand Mean Duration	Δ Mean Duration	Δ% Mean Duration	Baseline number of iterations	Comparand number of iterations	Δ number of iterations	Δ% number of iterations	Baseline gc count	Comparand gc count	Δ gc count	Δ% gc count	Baseline median	Comparand median	Δ median	Δ% median	Baseline non induced gc count	Comparand non induced gc count	Δ non induced gc count	Δ% non induced gc count	Baseline total allocated (mb)	Comparand total allocated (mb)	Δ total allocated (mb)	Δ% total allocated (mb)	Baseline total pause time (msec)	Comparand total pause time (msec)	Δ total pause time (msec)	Δ% total pause time (msec)	Baseline gc pause time %	Comparand gc pause time %	Δ gc pause time %	Δ% gc pause time %	Baseline JIT_WriteBarrier	Comparand JIT_WriteBarrier	Δ JIT_WriteBarrier	Δ% JIT_WriteBarrier	Baseline JIT_ByRefWriteBarrier	Comparand JIT_ByRefWriteBarrier	Δ JIT_ByRefWriteBarrier	Δ% JIT_ByRefWriteBarrier
System.Xml.Linq.Perf_XName.NonEmptyNameSpaceToString	segments	regions	108.59	322.66	214.06	197.12	128	128	0	0	4	4	0	0	100	0	-100	-100	0	0	0	NaN	1.89	1.88	-0	-0.23	1.52	1.52	0.01	0.39	1.89	1.83	-0.06	-3.41	0	0	0	NaN	0	0	0	NaN
System.Xml.Linq.Perf_XName.NonEmptyNameSpaceToString	segments	writebarrier_3	108.59	178.52	69.92	64.39	128	128	0	0	4	4	0	0	100	50	-50	-50	0	0	0	NaN	1.89	1.88	-0.01	-0.34	1.52	1.52	0.01	0.41	1.89	2.02	0.13	7.11	0	0	0	NaN	0	0	0	NaN

Baseline - Segments

BenchmarkDotNet=v0.13.1.1847-nightly, OS=Windows 11 (10.0.22000.856/21H2)
Intel Core i9-10900K CPU 3.70GHz, 1 CPU, 20 logical and 10 physical cores
.NET SDK=7.0.100-preview.7.22377.5
[Host] : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2
Job-QRXOHO : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2

OutlierMode=DontRemove EnvironmentVariables=COMPlus_GCName=clrgc.dll PowerPlanMode=00000000-0000-0000-0000-000000000000
Force=False InvocationCount=1 IterationCount=128
IterationTime=250.0000 ms MaxIterationCount=20 MinIterationCount=15
UnrollFactor=1 WarmupCount=1

Method	Mean	Error	StdDev	StdErr	Median	Min	Max	Q1	Q3	Op/s	Allocated
NonEmptyNameSpaceToString	108.6 ns	45.77 ns	153.7 ns	13.59 ns	100.0 ns	0.0 ns	1,000.0 ns	100.0 ns	100.0 ns	9,208,633.1	488 B

Regions

BenchmarkDotNet=v0.13.1.1847-nightly, OS=Windows 11 (10.0.22000.856/21H2)
Intel Core i9-10900K CPU 3.70GHz, 1 CPU, 20 logical and 10 physical cores
.NET SDK=7.0.100-preview.7.22377.5
[Host] : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2
Job-VEMLHO : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2

OutlierMode=DontRemove PowerPlanMode=00000000-0000-0000-0000-000000000000 Force=False
InvocationCount=1 IterationCount=128 IterationTime=250.0000 ms
MaxIterationCount=20 MinIterationCount=15 UnrollFactor=1
WarmupCount=1

Method	Mean	Error	StdDev	StdErr	Median	Min	Max	Q1	Q3	Op/s	Allocated
NonEmptyNameSpaceToString	322.7 ns	431.3 ns	1,448.5 ns	128.0 ns	0.0 ns	0.0 ns	14,300.0 ns	0.0 ns	0.0 ns	3,099,273.6	488 B

Regions w/ More Precise Writebarrier

BenchmarkDotNet=v0.13.1.1847-nightly, OS=Windows 11 (10.0.22000.856/21H2)
Intel Core i9-10900K CPU 3.70GHz, 1 CPU, 20 logical and 10 physical cores
.NET SDK=7.0.100-preview.7.22377.5
[Host] : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2
Job-LKBXKI : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2

OutlierMode=DontRemove EnvironmentVariables=COMPlus_GCWriteBarrier=3,COMPlus_EnableWriteXorExecute=0 PowerPlanMode=00000000-0000-0000-0000-000000000000
Force=False InvocationCount=1 IterationCount=128
IterationTime=250.0000 ms MaxIterationCount=20 MinIterationCount=15
UnrollFactor=1 WarmupCount=1

Method	Mean	Error	StdDev	StdErr	Median	Min	Max	Q1	Q3	Op/s	Allocated
NonEmptyNameSpaceToString	178.5 ns	155.5 ns	522.3 ns	46.17 ns	50.00 ns	0.0 ns	2,950.0 ns	50.00 ns	50.00 ns	5,601,750.5	488 B

@mangod9

We have been working through root-causing and fixing this issue and here are our conclusions:

We root caused this issue to the introduction of a higher number and size of decommits for regions (enabled in 7.0) as opposed to segments (default in 6.0).
We are working on a fix: Gradual decommit in wks #73620 that improves the numbers for these benchmarks, however, even with this fix we are not at the same level as segments in terms of mean execution time, number and size of virtual commits and decommits as before and this is something we plan to further address.
We think the next steps here are to merge the fix that improves the regression and work on further improvements in 8.0. More specifically, we should merge the fix mentioned above and move the issue to 8.0 (cc: @mangod9)
We found that running the benchmarks above using default parameters results in an inequitable for our GC evaluation comparison purposes where:
- There are an unequal number of invocations per iteration resulting in a lob sided effect on the mean. Fixed by passing in a derived invocation count by doing a dry run and making use of that invocation count for all our runs.
- Outliers are removed. Fixed by not removing outliers by setting the following in the command line args to run the microbenchmarks --outliers DontRemove.
- There are a variable number of induced GCs resulting from the unequal number of invocations and evaluation overhead runs. Fixed by removing the evaluation overhead stage.
Using a more equitable comparison repeated a number of times, we consistently observed the following:
- The regressions for the tests for regions were never above 10%.
- More consistent results that were less volatile.

Results

Benchmark	Baseline	Comparand	ΔMean	ΔMean %
System.Xml.Linq.Perf_XName.NonEmptyNameSpaceToString	segments	regions	1.56	7.62
System.Xml.Linq.Perf_XName.NonEmptyNameSpaceToString	segments	decommit_fix	0.97	4.75

Details

Intel Core i9-10900K CPU 3.70GHz, 1 CPU, 20 logical and 10 physical cores
.NET SDK=7.0.100-preview.7.22377.5
  [Host]     : .NET 7.0.0 (7.0.22.37506), X64 RyuJIT AVX2
  Job-OERVVK : .NET 8.0.0 (42.42.42.42424), X64 RyuJIT AVX2

The baseline run is based on Peter’s fix rebased on the latest main from yesterday and using the segments’ CLR GC.
The regions run is based on the latest main from yesterday.
The decommit_fix is based on Peter’s fix rebased on the latest main.
The commit hash for the main used: 82d76a4

Full comparison table with the virtual commit and decommit data: Compare.xlsx

Tracking these issues here: #73592

CC: @dotnet/gc

@mrsharm

Thanks @mrsharm. @adamsitnik checking that you agree with the analysis of ensuring the GC impact is equitable across runs and with that the regression is not too high?

I have seen this effect when comparing things too (say OSR on vs off) -- if the two variants behave differently BDN may change its measurement approach to the point where the measurement strategy becomes a contributing factor in the overall reported results.

Keeping things the "same" across the two sets of measurements often resolves this, though not always.

is this the .NET equivalent of the uncertainty principle :)

Keeping things the "same" across the two sets of measurements often resolves this, though not always.

Definitely, that's why we kept an eye on standard error and standard error normalized by the mean as well to ensure the repeatability of these experiments:

Benchmark Name	Baseline	Comparand	Δ standard error	Δ standard error / mean
System.Xml.Linq.Perf_XName.NonEmptyNameSpaceToString	segments	regions	-0.2263	-0.0114
System.Xml.Linq.Perf_XName.NonEmptyNameSpaceToString	segments	decommit_fix	-0.2705	-0.0133

Getting to this low standard error was a matter of discerning a high enough invocation count described above. The result was a consistent and equitable comparison i.e., we ran this experiment for 20+ times and got similar results.

Assume its ok to close this now since the normalized regression after the decommit fix is reasonable?

Navigation Menu

Repository navigation

Regressions in System.Xml.Linq.Perf_XName (FullPGO) #64626

Run Information