Performance regressions in System.Numerics.Tests.Perf_BigInteger.Parse

[performanceautofiler]

Run Information

Architecture	x64
OS	ubuntu 18.04
Baseline	94e0c70eee98d00a410ac2ac6dcd28c3abc2a4e2
Compare	a5f3676cc71e176084f0f7f1f6beeecd86fbeafc
Diff	Diff

Regressions in System.Numerics.Tests.Perf_BigInteger

Benchmark	Baseline	Test	Test/Base	Test Quality	Edge Detector	Baseline IR	Compare IR	IR Ratio	Baseline ETL	Compare ETL
ToByteArray - Duration of single invocation	58.34 ns	63.10 ns	1.08	0.01	False
Parse - Duration of single invocation	1.41 μs	1.65 μs	1.17	0.02	False
Parse - Duration of single invocation	133.39 ns	142.75 ns	1.07	0.04	False

Test Report

Repro

git clone https://github.com/dotnet/performance.git
python3 .\performance\scripts\benchmarks_ci.py -f net6.0 --filter 'System.Numerics.Tests.Perf_BigInteger*'

Payloads

Baseline
Compare

Histogram

System.Numerics.Tests.Perf_BigInteger.ToByteArray(numberString: 12345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890)

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 63.09514035342691 > 61.31842219522817.
IsChangePoint: Marked as a change because one of 7/10/2022 2:23:14 PM, 7/13/2022 7:22:00 AM, 7/18/2022 2:17:16 AM falls between 7/8/2022 10:31:34 AM and 7/18/2022 2:17:16 AM.
IsRegressionStdDev: Marked as regression because -19.57606754469047 (T) = (0 -63.06821020437885) / Math.Sqrt((4.0461528903312995 / (56)) + (0.1429998919536005 / (31))) is less than -1.988267907476882 = MathNet.Numerics.Distributions.StudentT.InvCDF(0, 1, (56) + (31) - 2, .025) and -0.09415891535503756 = (57.64081370567108 - 63.06821020437885) / 57.64081370567108 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.

```#### System.Numerics.Tests.Perf_BigInteger.Parse(numberString: 12345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890)

```log

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 1.64638091481311 > 1.4789204100383715.
IsChangePoint: Marked as a change because one of 5/23/2022 3:43:39 PM, 7/2/2022 7:35:06 PM, 7/6/2022 3:55:24 AM, 7/12/2022 12:16:14 PM, 7/18/2022 2:17:16 AM falls between 7/8/2022 10:31:34 AM and 7/18/2022 2:17:16 AM.
IsRegressionStdDev: Marked as regression because -13.450997279262245 (T) = (0 -1622.803624081618) / Math.Sqrt((10269.32144450607 / (51)) + (553.0820727629088 / (36))) is less than -1.988267907476882 = MathNet.Numerics.Distributions.StudentT.InvCDF(0, 1, (51) + (36) - 2, .025) and -0.1389816193702231 = (1424.7847344357624 - 1622.803624081618) / 1424.7847344357624 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.

```#### System.Numerics.Tests.Perf_BigInteger.Parse(numberString: -2147483648)

```log

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 142.7472876905376 > 138.36476110994943.
IsChangePoint: Marked as a change because one of 7/2/2022 7:35:06 PM, 7/6/2022 3:55:24 AM, 7/12/2022 12:16:14 PM, 7/18/2022 2:17:16 AM falls between 7/8/2022 10:31:34 AM and 7/18/2022 2:17:16 AM.
IsRegressionStdDev: Marked as regression because -4.669140180936088 (T) = (0 -143.62725712142048) / Math.Sqrt((116.92965141088445 / (50)) + (4.935059494685537 / (36))) is less than -1.9886096669751727 = MathNet.Numerics.Distributions.StudentT.InvCDF(0, 1, (50) + (36) - 2, .025) and -0.05390755620131213 = (136.28069774839486 - 143.62725712142048) / 136.28069774839486 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

EDIT: Removed remainder of the original report, as the rest were noisy benchmarks

[AndyAyersMS]

Lots of this seems to be noise, but the BigInteger.Parse seems real and sustained.

Seems likely this is from #67448.

[dotnet-issue-labeler]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[ghost]

Tagging subscribers to this area: @JulieLeeMSFT, @jakobbotsch
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Run Information

Architecture	x64
OS	ubuntu 18.04
Baseline	94e0c70eee98d00a410ac2ac6dcd28c3abc2a4e2
Compare	a5f3676cc71e176084f0f7f1f6beeecd86fbeafc
Diff	Diff

Regressions in System.Numerics.Tests.Perf_BigInteger

Benchmark	Baseline	Test	Test/Base	Test Quality	Edge Detector	Baseline IR	Compare IR	IR Ratio	Baseline ETL	Compare ETL
ToByteArray - Duration of single invocation	58.34 ns	63.10 ns	1.08	0.01	False
Parse - Duration of single invocation	1.41 μs	1.65 μs	1.17	0.02	False
Parse - Duration of single invocation	133.39 ns	142.75 ns	1.07	0.04	False

Test Report

Repro

git clone https://github.com/dotnet/performance.git
python3 .\performance\scripts\benchmarks_ci.py -f net6.0 --filter 'System.Numerics.Tests.Perf_BigInteger*'

Payloads

Baseline
Compare

Histogram

System.Numerics.Tests.Perf_BigInteger.ToByteArray(numberString: 12345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890)

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 63.09514035342691 > 61.31842219522817.
IsChangePoint: Marked as a change because one of 7/10/2022 2:23:14 PM, 7/13/2022 7:22:00 AM, 7/18/2022 2:17:16 AM falls between 7/8/2022 10:31:34 AM and 7/18/2022 2:17:16 AM.
IsRegressionStdDev: Marked as regression because -19.57606754469047 (T) = (0 -63.06821020437885) / Math.Sqrt((4.0461528903312995 / (56)) + (0.1429998919536005 / (31))) is less than -1.988267907476882 = MathNet.Numerics.Distributions.StudentT.InvCDF(0, 1, (56) + (31) - 2, .025) and -0.09415891535503756 = (57.64081370567108 - 63.06821020437885) / 57.64081370567108 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.

```#### System.Numerics.Tests.Perf_BigInteger.Parse(numberString: 12345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890)

```log

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 1.64638091481311 > 1.4789204100383715.
IsChangePoint: Marked as a change because one of 5/23/2022 3:43:39 PM, 7/2/2022 7:35:06 PM, 7/6/2022 3:55:24 AM, 7/12/2022 12:16:14 PM, 7/18/2022 2:17:16 AM falls between 7/8/2022 10:31:34 AM and 7/18/2022 2:17:16 AM.
IsRegressionStdDev: Marked as regression because -13.450997279262245 (T) = (0 -1622.803624081618) / Math.Sqrt((10269.32144450607 / (51)) + (553.0820727629088 / (36))) is less than -1.988267907476882 = MathNet.Numerics.Distributions.StudentT.InvCDF(0, 1, (51) + (36) - 2, .025) and -0.1389816193702231 = (1424.7847344357624 - 1622.803624081618) / 1424.7847344357624 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.

```#### System.Numerics.Tests.Perf_BigInteger.Parse(numberString: -2147483648)

```log

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 142.7472876905376 > 138.36476110994943.
IsChangePoint: Marked as a change because one of 7/2/2022 7:35:06 PM, 7/6/2022 3:55:24 AM, 7/12/2022 12:16:14 PM, 7/18/2022 2:17:16 AM falls between 7/8/2022 10:31:34 AM and 7/18/2022 2:17:16 AM.
IsRegressionStdDev: Marked as regression because -4.669140180936088 (T) = (0 -143.62725712142048) / Math.Sqrt((116.92965141088445 / (50)) + (4.935059494685537 / (36))) is less than -1.9886096669751727 = MathNet.Numerics.Distributions.StudentT.InvCDF(0, 1, (50) + (36) - 2, .025) and -0.05390755620131213 = (136.28069774839486 - 143.62725712142048) / 136.28069774839486 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

EDIT: Removed remainder of the original report, as the rest were noisy benchmarks

Author:	performanceautofiler[bot]
Assignees:	-
Labels:	tenet-performance, tenet-performance-benchmarks, area-CodeGen-coreclr, untriaged
Milestone:	-

[JulieLeeMSFT]

Lots of this seems to be noise, but the BigInteger.Parse seems real and sustained.

Seems likely this is from #67448.

cc @tannergooding @jkotas @gfoidl.

[jkotas]

Seems likely this is from #67448.

#67448 have not touched BigInteger parsing.

[AndyAyersMS]

Implicated commit range is cf2187b...c5005e0

These tests are all now showing signs of being multi-stable. Looking at the recent swings in ToByteArray there does not seem to be a good explanation.

Looks like for the first two we are notably regressed vs 6.0.

[jakobbotsch]

I can reproduce:

BenchmarkDotNet=v0.13.1.1847-nightly, OS=ubuntu 20.04
AMD Ryzen 9 5950X, 1 CPU, 32 logical and 16 physical cores
.NET SDK=7.0.100-rc.2.22426.5
  [Host]     : .NET 7.0.0 (7.0.22.42212), X64 RyuJIT AVX2
  Job-HETZKM : .NET 7.0.0 (42.42.42.42424), X64 RyuJIT AVX2
  Job-JVOXQQ : .NET 7.0.0 (42.42.42.42424), X64 RyuJIT AVX2

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

Method	Job	Toolchain	numberString	Mean	Error	StdDev	Median	Min	Max	Ratio	RatioSD	Gen 0	Allocated	Alloc Ratio
Parse	Job-HETZKM	/c5005e_release/corerun	-2147483648	115.19 ns	0.405 ns	0.359 ns	115.10 ns	114.51 ns	115.89 ns	1.10	0.02	0.0037	136 B	1.00
Parse	Job-JVOXQQ	/cf2187_release/corerun	-2147483648	104.93 ns	1.574 ns	1.473 ns	104.88 ns	103.03 ns	107.36 ns	1.00	0.00	0.0038	136 B	1.00
Parse	Job-HETZKM	/c5005e_release/corerun	123	69.02 ns	0.199 ns	0.166 ns	68.99 ns	68.72 ns	69.26 ns	1.02	0.02	0.0028	104 B	1.00
Parse	Job-JVOXQQ	/cf2187_release/corerun	123	67.56 ns	1.366 ns	1.067 ns	67.30 ns	66.39 ns	69.61 ns	1.00	0.00	0.0031	104 B	1.00
Parse	Job-HETZKM	/c5005e_release/corerun	123456789012(...)901234567890 [200]	1,220.96 ns	3.989 ns	3.732 ns	1,220.95 ns	1,215.14 ns	1,226.83 ns	1.21	0.01	0.0294	984 B	1.00
Parse	Job-JVOXQQ	/cf2187_release/corerun	123456789012(...)901234567890 [200]	1,013.13 ns	13.798 ns	12.907 ns	1,011.42 ns	996.18 ns	1,033.38 ns	1.00	0.00	0.0280	984 B	1.00

Hottest methods according to PGO data:

System.Globalization.FormatProvider+Number.ParseNumber: 1534479778
System.Numerics.BigNumber.<NumberToBigInteger>g__ProcessChunk|10_4: 435828576
System.Text.StringBuilder.Append: 299632722
System.ReadOnlySpan`1[System.Char].get_Item: 199756370
System.Runtime.CompilerServices.CastHelpers.IsInstanceOfClass: 109083046
System.Globalization.FormatProvider+Number.MatchChars: 108957144
System.Numerics.BigNumber.<NumberToBigInteger>g__MultiplyAdd|10_3: 99877382
System.Numerics.BigNumber.<NumberToBigInteger>g__NumberBufferToBigInteger|10_2: 90797620
System.Globalization.FormatProvider+Number.IsWhite: 81717858
System.Globalization.FormatProvider+Number.AllowHyphenDuringParsing: 81717858
System.Span`1[System.UInt32].get_Item: 72638096
System.Numerics.BigNumber.NumberToBigInteger: 63558334

System.Globalization.FormatProvider+Number.ParseNumber does look to have a diff: https://www.diffchecker.com/RGI0RAh3
Seems we are no longer inlining StringBuilder.Append(char) after #67448. Indeed, if I revert the change there the regression goes away.

[jakobbotsch]

Looks like we are just barely within the inlining threshold before, and even though the new IL is smaller, some heuristics do not kick in which means we end up just barely above the threshold after:

 Invoking compiler for the inlinee method StringBuilder:Append(ushort):StringBuilder:this :
 IL to import:
 IL_0000  02                ldarg.0     
 IL_0001  7b 47 0e 00 04    ldfld        0x4000E47
 IL_0006  0a                stloc.0     
 IL_0007  02                ldarg.0     
 IL_0008  7b 45 0e 00 04    ldfld        0x4000E45
 IL_000d  0b                stloc.1     
-IL_000e  07                ldloc.1     
-IL_000f  8e                ldlen       
-IL_0010  69                conv.i4     
-IL_0011  06                ldloc.0     
-IL_0012  36 14             ble.un.s     20 (IL_0028)
+IL_000e  06                ldloc.0     
+IL_000f  07                ldloc.1     
+IL_0010  8e                ldlen       
+IL_0011  69                conv.i4     
+IL_0012  34 0f             bge.un.s     15 (IL_0023)
 IL_0014  07                ldloc.1     
 IL_0015  06                ldloc.0     
 IL_0016  03                ldarg.1     
 IL_0017  9d                stelem.i2   
 IL_0018  02                ldarg.0     
-IL_0019  02                ldarg.0     
-IL_001a  7b 47 0e 00 04    ldfld        0x4000E47
-IL_001f  17                ldc.i4.1    
-IL_0020  58                add         
-IL_0021  7d 47 0e 00 04    stfld        0x4000E47
-IL_0026  2b 09             br.s         9 (IL_0031)
-IL_0028  02                ldarg.0     
-IL_0029  03                ldarg.1     
-IL_002a  17                ldc.i4.1    
-IL_002b  28 41 39 00 06    call         0x6003941
-IL_0030  26                pop         
-IL_0031  02                ldarg.0     
-IL_0032  2a                ret         
+IL_0019  06                ldloc.0     
+IL_001a  17                ldc.i4.1    
+IL_001b  58                add         
+IL_001c  7d 47 0e 00 04    stfld        0x4000E47
+IL_0021  2b 09             br.s         9 (IL_002c)
+IL_0023  02                ldarg.0     
+IL_0024  03                ldarg.1     
+IL_0025  17                ldc.i4.1    
+IL_0026  28 41 39 00 06    call         0x6003941
+IL_002b  26                pop         
+IL_002c  02                ldarg.0     
+IL_002d  2a                ret         
 
-INLINER impTokenLookupContextHandle for StringBuilder:Append(ushort):StringBuilder:this is 0x00007FAA6B33C7E1.
+INLINER impTokenLookupContextHandle for StringBuilder:Append(ushort):StringBuilder:this is 0x00007FC8350AC7E1.
 *************** In compInitDebuggingInfo() for StringBuilder:Append(ushort):StringBuilder:this
 info.compStmtOffsetsCount    = 0
 info.compStmtOffsetsImplicit = 0005h ( STACK_EMPTY CALL_SITE )
 *************** In fgFindBasicBlocks() for StringBuilder:Append(ushort):StringBuilder:this
 weight= 31 : state 191 [ ldarg.0 -> ldfld ]
 weight=  6 : state  11 [ stloc.0 ]
 weight= 31 : state 191 [ ldarg.0 -> ldfld ]
-weight= -7 : state 200 [ stloc.1 -> ldloc.1 ]
+weight= 34 : state  12 [ stloc.1 ]
+weight= 12 : state   7 [ ldloc.0 ]
+weight=  9 : state   8 [ ldloc.1 ]
 weight=  7 : state 119 [ ldlen ]
 weight=  2 : state  93 [ conv.i4 ]
-weight= 12 : state   7 [ ldloc.0 ]
-weight=147 : state  54 [ ble.un.s ]
+weight= 85 : state  52 [ bge.un.s ]
 weight=  9 : state   8 [ ldloc.1 ]
 weight= 12 : state   7 [ ldloc.0 ]
 weight= 16 : state   4 [ ldarg.1 ]
 weight= 23 : state 134 [ stelem.i2 ]
 weight= 10 : state   3 [ ldarg.0 ]
-weight= 31 : state 191 [ ldarg.0 -> ldfld ]
+weight= 12 : state   7 [ ldloc.0 ]
 weight= 28 : state  24 [ ldc.i4.1 ]
 weight=-12 : state  76 [ add ]
 weight= 31 : state 111 [ stfld ]
 weight= 44 : state  43 [ br.s ]
 weight= 10 : state   3 [ ldarg.0 ]
 weight= 16 : state   4 [ ldarg.1 ]
 weight= 28 : state  24 [ ldc.i4.1 ]
 weight= 79 : state  40 [ call ]
 weight=-24 : state  39 [ pop ]
 weight= 10 : state   3 [ ldarg.0 ]
 weight= 19 : state  42 [ ret ]
 
-4 ldfld or stfld over arguments which are structs.  Multiplier increased to 1.
+2 ldfld or stfld over arguments which are structs.  Multiplier increased to 1.
 Inline candidate has arg that feeds range check.  Multiplier increased to 2.
-Inline candidate has 1 binary expressions with constants.  Multiplier increased to 2.5.
-Inline candidate callsite is in a loop.  Multiplier increased to 5.5.
-Caller has 115 locals.  Multiplier decreased to 4.88232.
-calleeNativeSizeEstimate=559
+Inline candidate callsite is in a loop.  Multiplier increased to 5.
+Caller has 115 locals.  Multiplier decreased to 4.43848.
+calleeNativeSizeEstimate=528
 callsiteNativeSizeEstimate=115
-benefit multiplier=4.88232
-threshold=561
-Native estimate for function size is within threshold for inlining 55.9 <= 56.1 (multiplier = 4.88232)
+benefit multiplier=4.43848
+threshold=510
+Native estimate for function size exceeds threshold for inlining 52.8 > 51 (multiplier = 4.43848)
+
+
+Inline expansion aborted, inline not profitable

cc @EgorBo, can you see anything simple we can do for the heuristics here on the JIT side?

[jakobbotsch]

The previous

Inline candidate has 1 binary expressions with constants.  Multiplier increased to 2.5.

seems odd. It is coming from this:

runtime/src/coreclr/jit/fgbasic.cpp

Lines 1414 to 1422 in 104fe14

	// Arg op ConstArg
	// Arg op Const
	else if (FgStack::IsArgument(arg0) && FgStack::IsConstantOrConstArg(arg1, impInlineInfo))
	{
	// "Arg op CNS" --> keep arg0 in the stack for the next ops
	pushedStack.Push(arg0);
	handled = true;
	compInlineResult->Note(InlineObservation::CALLEE_BINARY_EXRP_WITH_CNS);
	}

But arg0 here is not just an argument; it is a field access on an argument: this.m_ChunkLength
Not sure if this is intentional. After the change, it is reusing a local so it does not get this benefit multiplier.

In any case adjusting the heuristics for 7.0 does not seem realistic, but changing the C# source code back to make the JIT happy is not appealing either.

[JulieLeeMSFT]

@jkotas @jakobbotsch, then what should be the next step? Should we revert #67448?

[jkotas]

Sure, we can revert the offending two lines from #67448. It is not very appealing as @jakobbotsch said. However, we have hundreds of places in libraries that are tweaked in unnatural ways to make the JIT happy, one more or less is not a big deal.