Performance regression: float.ToString(format) 20% to 3x slower

[adamsitnik]

After the changes introduced to numbers formatting the vast majority of the operations is faster. However, this is not true for float.ToString(format)which is 20% to 3x slower.

https://github.com/dotnet/performance/blob/1b4c089465cde5d8a6454a2e53b37f662f3964b0/src/benchmarks/micro/corefx/System.Runtime/Perf.Single.cs#L42-L45

Repro

git clone https://github.com/dotnet/performance.git
cd performance
# if you don't have cli installed and want python script to download the latest cli for you
py .\scripts\benchmarks_ci.py -f netcoreapp2.2 netcoreapp3.0 --filter System.Tests.Perf_Single.ToStringWithFormat
# if you do
dotnet run -p .\src\benchmarks\micro\MicroBenchmarks.csproj -c Release -f netcoreapp2.2 --filter System.Tests.Perf_Single.ToStringWithFormat --runtimes netcoreapp2.2 netcoreapp3.0

BenchmarkDotNet=v0.11.3.1003-nightly, OS=Windows 10.0.18362
Intel Xeon CPU E5-1650 v4 3.60GHz, 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=3.0.100-preview8-013262
   [Host]     : .NET Core 2.2.6 (CoreCLR 4.6.27817.03, CoreFX 4.6.27818.02), 64bit RyuJIT
   Job-BYJCMJ : .NET Core 2.2.6 (CoreCLR 4.6.27817.03, CoreFX 4.6.27818.02), 64bit RyuJIT
   Job-JSSCYO : .NET Core 3.0.0-preview8-27916-02 (CoreCLR 4.700.19.36302, CoreFX 4.700.19.36514), 64bit RyuJIT

Method	Toolchain	value	format	Mean	Ratio	Allocated Memory/Op
ToStringWithFormat	netcoreapp2.2	-3,402823E+38	E	154.8 ns	1.00	56 B
ToStringWithFormat	netcoreapp3.0	-3,402823E+38	E	193.7 ns	1.25	56 B
ToStringWithFormat	netcoreapp2.2	-3,402823E+38	F50	447.2 ns	1.00	208 B
ToStringWithFormat	netcoreapp3.0	-3,402823E+38	F50	1,475.5 ns	3.31	208 B
ToStringWithFormat	netcoreapp2.2	-3,402823E+38	G	152.7 ns	1.00	56 B
ToStringWithFormat	netcoreapp3.0	-3,402823E+38	G	215.2 ns	1.41	56 B
ToStringWithFormat	netcoreapp2.2	-3,402823E+38	G17	160.2 ns	1.00	56 B
ToStringWithFormat	netcoreapp3.0	-3,402823E+38	G17	238.2 ns	1.49	72 B
ToStringWithFormat	netcoreapp2.2	-3,402823E+38	R	245.7 ns	1.00	56 B
ToStringWithFormat	netcoreapp3.0	-3,402823E+38	R	216.4 ns	0.88	56 B
ToStringWithFormat	netcoreapp2.2	12345	E	166.6 ns	1.00	56 B
ToStringWithFormat	netcoreapp3.0	12345	E	213.2 ns	1.28	48 B
ToStringWithFormat	netcoreapp2.2	12345	F50	318.9 ns	1.00	144 B
ToStringWithFormat	netcoreapp3.0	12345	F50	448.9 ns	1.41	136 B
ToStringWithFormat	netcoreapp2.2	12345	G	146.6 ns	1.00	40 B
ToStringWithFormat	netcoreapp3.0	12345	G	183.4 ns	1.25	32 B
ToStringWithFormat	netcoreapp2.2	12345	G17	161.9 ns	1.00	40 B
ToStringWithFormat	netcoreapp3.0	12345	G17	349.4 ns	2.16	32 B
ToStringWithFormat	netcoreapp2.2	12345	R	172.8 ns	1.00	40 B
ToStringWithFormat	netcoreapp3.0	12345	R	185.1 ns	1.07	32 B
ToStringWithFormat	netcoreapp2.2	3,402823E+38	E	149.5 ns	1.00	56 B
ToStringWithFormat	netcoreapp3.0	3,402823E+38	E	188.5 ns	1.26	48 B
ToStringWithFormat	netcoreapp2.2	3,402823E+38	F50	437.2 ns	1.00	208 B
ToStringWithFormat	netcoreapp3.0	3,402823E+38	F50	1,523.3 ns	3.48	208 B
ToStringWithFormat	netcoreapp2.2	3,402823E+38	G	151.5 ns	1.00	56 B
ToStringWithFormat	netcoreapp3.0	3,402823E+38	G	212.8 ns	1.40	48 B
ToStringWithFormat	netcoreapp2.2	3,402823E+38	G17	157.9 ns	1.00	56 B
ToStringWithFormat	netcoreapp3.0	3,402823E+38	G17	237.0 ns	1.50	72 B
ToStringWithFormat	netcoreapp2.2	3,402823E+38	R	243.0 ns	1.00	56 B
ToStringWithFormat	netcoreapp3.0	3,402823E+38	R	213.8 ns	0.88	48 B

/cc @danmosemsft @tannergooding

category:cq
theme:floating-point
skill-level:expert
cost:large

[tannergooding]

I had already gone over this with @billwert over an e-mail. For reference:

Yes, this is expected.

The previous implementation didn’t properly respect precision specifiers above 17 (15 in many cases) and would actually just fill in the positions with zero, even if valid digits existed. This meant is was actually not doing the work and so it will generally show to be faster because of this.

The other factor here is that many values, like `float.MaxValue`, are really edge-case values (much like subnormal numbers like `float.Epsilon`) and so they represent extreme cases where the computation may be more expensive than the common case and so they may have regressed slightly.

For reference, over half of all representable floats are in the range of -1.0 to +1.0 and, ignoring the gap of subnormal values (which is representable values between +/- 1.175492107*10^-38, excluding +/- zero), I had seen the results to be generally faster. – This is why many applications try to normalize results to between -1.0 and +1.0.

For the R case (which is roundtripping and is used in serializers/etc) we should be faster 100% of the time, as we are now always returning the shortest string, rather than trying 15, parsing the result back, checking if it was equivalent, and then trying again at 17 if it wasn’t equivalent (and so we are always doing less work).

For the default case (‘G’, and ‘ToString’) we will be often faster, but slower in a few cases. The cases where we are slower are where the algorithm needs to do additional computation to compute more than 15 digits (the previous implementation was equivalent to G15 and so would return non-roundtrippable results in some cases; roundtripping requires computing up to 17 digits, so in some cases we will be slower).

-	15 and 17 are for double. You can largely replace these with 6 and 9 for single.

[stephentoub]

For the default case (‘G’, and ‘ToString’) we will be often faster, but slower in a few cases. The cases where we are slower are where the algorithm needs to do additional computation to compute more than 15 digits

@tannergooding, how does that map to these results in the above chart?

Method	Toolchain	value	format	Mean	Ratio	Allocated Memory/Op
ToStringWithFormat	netcoreapp2.2	12345	G	146.6 ns	1.00	40 B
ToStringWithFormat	netcoreapp3.0	12345	G	183.4 ns	1.25	32 B

[tannergooding]

how does that map to these results in the above chart?

I'll profile, but this is likely related to the fact that it is 5 digits and float was previously defaulting to 7, so this is approaching the upper limit of exactly representable integers.

[tannergooding]

Looks like this happens to be a case where we are hitting a set of code paths where the JIT isn't producing codegen that is as nice as the C++ codegen was.

The majority of time is being spent in Grisu3.TryDigitGenShortest.

• There look to be a few methods which the JIT isn't inlining when it might be better if it was.
• Math.DivRem is used in a loop and the JIT still can't rationalize it to a single div instruction, and so it incurs an additional multiplication instead to avoid incurring two divs.

There are also some minor places where codegen isn't as nice, but those don't look to be as impactful and would need further investigation.

[danmoseley]

@AndyAyersMS

[AndyAyersMS]

this happens to be a case

I take it "this" means the various runs involving 12345, and we care less about the extremes...?

Any sense of how much the jit codegen impacts the perf here? Is it likely to be all of the regression? Some?

[tannergooding]

I'll try to get more exact details tomorrow. A direct comparison is tough as the 2.2 code was C++ and the 3.0 code is C#. I don't think it is regressions in the JIT, just rather places where the JIT doesn't emit as nice of code.

[mikedn]

Math.DivRem is used in a loop and the JIT still can't rationalize it to a single div instruction, and so it incurs an additional multiplication instead to avoid incurring two divs

That's something that should be measured in isolation, it seems unlikely that when a 20-30 cycles DIV gets generated the extra 3-4 cycles MUL will have a significant impact. Especially considering that there's other code in the loop and that the value computed by DivRem is not loop carried.

[AndyAyersMS]

The only inline I see in TryDigitGenShortest that we might contemplate is BiggestPowerTen

Inlines into 060015A7 Grisu3:TryDigitGenShortest(byref,byref,byref,struct,byref,byref):bool
  [1 IL=0019 TR=000013 0600159C] [below ALWAYS_INLINE size] DiyFp:.ctor(long,int):this
  [2 IL=0040 TR=000025 0600159C] [below ALWAYS_INLINE size] DiyFp:.ctor(long,int):this
  [3 IL=0049 TR=000033 0600159F] [profitable inline] DiyFp:Subtract(byref):struct:this
    [4 IL=0019 TR=000449 0600159C] [below ALWAYS_INLINE size] DiyFp:.ctor(long,int):this
  [5 IL=0076 TR=000053 0600159C] [below ALWAYS_INLINE size] DiyFp:.ctor(long,int):this
  [0 IL=0136 TR=000092 060015A5] [FAILED: unprofitable inline] Grisu3:BiggestPowerTen(int,int,byref):int
  [6 IL=0158 TR=000116 060003FB] [below ALWAYS_INLINE size] Math:DivRem(int,int,byref):int
  [7 IL=0235 TR=000200 0600159F] [profitable inline] DiyFp:Subtract(byref):struct:this
    [8 IL=0019 TR=000531 0600159C] [below ALWAYS_INLINE size] DiyFp:.ctor(long,int):this
  [0 IL=0269 TR=000234 060015AA] [FAILED: too many il bytes] Grisu3:TryRoundWeedShortest(struct,int,long,long,long,long,long):bool
  [9 IL=0323 TR=000271 0600159C] [below ALWAYS_INLINE size] DiyFp:.ctor(long,int):this
  [10 IL=0410 TR=000353 0600159F] [profitable inline] DiyFp:Subtract(byref):struct:this
    [11 IL=0019 TR=000592 0600159C] [below ALWAYS_INLINE size] DiyFp:.ctor(long,int):this
  [0 IL=0438 TR=000383 060015AA] [FAILED: noinline per IL/cached result] Grisu3:TryRoundWeedShortest(struct,int,long,long,long,long,long):bool

It is currently about 4x away from being considered profitable by the jit.

Inline candidate has an arg that feeds a constant test.  Multiplier increased to 1.
Inline candidate callsite is boring.  Multiplier increased to 2.3.
calleeNativeSizeEstimate=1198
callsiteNativeSizeEstimate=145
benefit multiplier=2.3
threshold=333
Native estimate for function size exceeds threshold for inlining 119.8 > 33.3 (multiplier = 2.3)

Things might be different with IBC data, but I don't know offhand if this code gets hit in our IBC scenarios. Even if it did, IBC would only help the R2R codegen so eventually we'd tier away from it and lose any benefit IBC might provide.

I also don't see a lot of potential benefit from inlining BiggestPowerTen. It is only called once and has a loop that does not look like it would become any simpler if it was inlined.

[AndyAyersMS]

As far as other codegen issues -- had thought perhaps the large number of in and out params here was a contributor, but changing the DiyFp to by-value (implicit by-ref) doesn't do much. Maybe the implicit byref struct promotion rules need tweaking. Will look more closely. Likewise having out int kappa control the first loop is not great, would be slightly better perhaps to modify the sources so as to have kappa be the return value, but that would require a bunch of changes elsewhere.

The allocator splits a loop backedge on the first loop and so we end up with a return block BB06 the first loop. Would be nice to be able to avoid this as we took pains earlier to move the return out of the loop, but not sure how much it really matters. cc @CarolEidt for an example where edge splitting puts non-loop code back into a loop.

fgFindInsertPoint(regionIndex=0, putInTryRegion=true, startBlk=BB01, endBlk=BB00, nearBlk=BB05, jumpBlk=BB00, runRarely=false)
fgNewBBinRegion(jumpKind=6, tryIndex=0, hndIndex=0, putInFilter=false, runRarely=false, insertAtEnd=false): inserting after BB06
New Basic Block BB10 [0021] created.
Splitting edge from BB05 to BB05; adding BB10
   BB10 bottom: move V51 from rax to STK (Critical)
...
BB08 [0019]  2       BB02,BB04             4        [098..0E4)-> BB07 ( cond )                     i target bwd LoopPH LIR 
BB04 [0003]  1       BB08                  4      0 [113..123)-> BB08 ( cond )                     i label target bwd LIR 
BB05 [0005]  3       BB02,BB04,BB10        4        [123..193)-> BB10 ( cond )                     i Loop Loop0 label target bwd bwd-target LIR 
BB06 [0006]  1       BB05                  0.50     [193..1BC)        (return)                     i gcsafe LIR 
BB10 [0021]  1       BB05                  2        [???..???)-> BB05 (always)                     internal target bwd LIR 

[AndyAyersMS]

I'm going to mark this as future -- nothing obvious for 3.0 jumps out here. I'll keep looking though.

[tannergooding]

VTune reports the following:

[tannergooding]

In, TryDigitRunShortest, the longest portion of time is naturally the div, which is taking 2.5s of the measured time. However, the additional imul is adding an additional .15 seconds of time:

The same section from the 2.2 code in written in C++ is:

[tannergooding]

The second most expensive function, FormatSingle, is spending just over half a second clearing out a buffer:

Likewise for the other FormatSingle and the TryRunSingle call that is happening