Missed optimization; potential compiler regression involving StringBuilder.Append(IFormatProvider, $"")

[jhudsoncedaron]

In looking at a system benchmark I ran into this troublesome result. This resists bisection and I can't account for it at all.

If I run this in LinqPad I get something that seems reasonable:

.NET 7.0.20
bytes: 14063928 elapsed 00:00:00.0767823
bytes: 15865064 elapsed 00:00:00.0711176
bytes: 14106120

But if I run this with dotnet run I get much worse:

.NET 7.0.20
bytes: 46092584 elapsed 00:00:00.0998086
bytes: 15545328 elapsed 00:00:00.0693222
bytes: 14099112

Dotnet version makes no meaningful difference

.NET 10.0.13
bytes: 46093400 elapsed 00:00:00.1416197
bytes: 15546688 elapsed 00:00:00.0924762
bytes: 14098816

Something's gone very wrong with the actual release build; as far as I can tell LinqPad is doing it right and dotnet run is doing it wrong. My bisection skills failed me; it won't bisect to anything useful.

Console.WriteLine(System.Runtime.InteropServices.RuntimeInformation.FrameworkDescription);
var value = (decimal)17.9994;
var s = new System.Diagnostics.Stopwatch();
var sb = new System.Text.StringBuilder();
s.Start();
long before1 = GC.GetAllocatedBytesForCurrentThread();
for (int i = 0; i < 1000000; i++)
	sb.Append(System.Globalization.CultureInfo.InvariantCulture, $"{value}");
s.Stop();
long after1 = GC.GetAllocatedBytesForCurrentThread();
Console.WriteLine($"bytes: {after1 - before1} elapsed {s.Elapsed}");
s.Restart();
long before2 = GC.GetAllocatedBytesForCurrentThread();
for (int i = 0; i < 10000; i++)
{
	var c = System.Globalization.CultureInfo.CurrentCulture;
	try {
		System.Globalization.CultureInfo.CurrentCulture = System.Globalization.CultureInfo.InvariantCulture;
		for (int j = 0; j < 100; j++)
			sb.Append(value);
	} finally {
		System.Globalization.CultureInfo.CurrentCulture = c;
	}
}
s.Stop();
long after2 = GC.GetAllocatedBytesForCurrentThread();
Console.WriteLine($"bytes: {after2 - before2} elapsed {s.Elapsed}");
long before3 = GC.GetAllocatedBytesForCurrentThread();
for (int j = 0; j < 1000000; j++)
	sb.Append(value);
long after3 = GC.GetAllocatedBytesForCurrentThread();
Console.WriteLine($"bytes: {after3 - before3}");

We got here on some debate on setting InvariantCulture vs the funky overload to StringBuilder.Append(). And now the benchmark results are wonky and it doesn't look like a problem in the benchmark code.

[Clockwork-Muse]

When creating benchmarks, you need to be using BenchmarkDotNet, not raw Stopwatch.

[jhudsoncedaron]

Your output for without a debugger is along the lines of the output I expected. Hmmm. Very hmmm. Of course attaching the debugger changes things, but that's not the point.

[huoyaoyuan]

Debugger do change things. Adding Thread.Sleep doesn't reproduce the same numbers. Debug build also prints different number with Release build. It's simply pointing out that the manual counter is unreliable. My result is also several times different than yours.

2. GetAllocatedBytesForCurrentThread is a liar.

It is honest, there's just something different happening in the application. There are existing reports about background GCto disrupt the statistic item.

[huoyaoyuan]

Your output for without a debugger is along the lines of the output I expected.

It's acutally Release build being expected. I tried Debug build without debugger, and it produces the same number with debugger.
It seems that something background of Debug build is encountered in the counter.

[jhudsoncedaron]

@huoyaoyuan "There are existing reports about background GCto disrupt the statistic item." Oh fun. Got links? That could easily be the piece of the puzzle I'm missing.

[huoyaoyuan]

An example is #134724. I remember there's more but can't find it. I also recall that things triggered by the JIT may also be encountered.

[huoyaoyuan]

Running correct benchmark with BenchmarkDotNet:

    [MemoryDiagnoser]
    public class Program
    {
        static void Main(string[] args)
        {
            CultureInfo.CurrentCulture = CultureInfo.InvariantCulture;
            BenchmarkSwitcher
                .FromAssembly(typeof(Program).Assembly)
                .Run(args);
        }

        decimal value = (decimal)17.1994;

        [Benchmark]
        public StringBuilder Append1()
        {
            var sb = new StringBuilder();
            sb.Append(CultureInfo.InvariantCulture, $"{value}");
            return sb;
        }

        [Benchmark]
        public StringBuilder Append2()
        {
            var sb = new StringBuilder();
            sb.Append(value);
            return sb;
        }
    }

Method	Mean	Error	StdDev	Gen0	Allocated
Append1	129.6 ns	0.89 ns	0.79 ns	0.0110	208 B
Append2	131.2 ns	1.27 ns	1.18 ns	0.0155	296 B

It's clear that the interpolation handler allocates less memory. The allocated number contains the overhead of new StringBuilder and the formatted string.

[jhudsoncedaron]

This benchmark is not correct. What is not being measured is InvariantCulture vs user's culture; what is being measured is the different means of selecting InvariantCulture. The final check on CurrentCulture was supposed to be a sanity check, not something that actually matters.

Assigning to CultureInfo.CurrentCulture used to be quite fast, but adding AsyncLocal broke its performance. So for a single hotspot a local application is always faster. However; the twofold question has appeared on the board

1. For a large scope, does the situation reverse itself and assigning to CultureInfo.CurrentCulture become faster?
2. If not; is it so close to the break-even point that for reliability of code writing is it worth it anyway.

And then the obvious benchmarking did something nutty.

[huoyaoyuan]

This benchmark is not correct. What is not being measured is InvariantCulture vs user's culture; what is being measured is the different means of selecting InvariantCulture.

It's actually measured. Setting CurrentCulture in Main doesn't take effect because the test is executed in a different process. The correct way is using GlobalSetup.

And that doesn't change the result. The performance difference is exactly the same if you are not using a culture with non-ASCII decimal point.

For a large scope, does the situation reverse itself and assigning to CultureInfo.CurrentCulture become faster?

Setting anything with larger observable scope will obviously take more overhead. Explicitly specifying the Culture in method calls is always faster. Another option is to specify process-wide DefaultThreadCurrentCulture.

[jhudsoncedaron]

"Setting anything with larger observable scope will obviously take more overhead. Explicitly specifying the Culture in method calls is always faster." Well if I actually had a StringBuilder.Append(IFormatProvider, decimal) that would probably be true; but not for this jank. In extreme, setting it once for the thread does in fact make StringBuilder.Append(decimal) faster.

[huoyaoyuan]

setting it once for the thread does in fact make StringBuilder.Append(decimal) faster.

Is there any source supporting it? Incorrect measurement are including startup cost in the measurement.

[jhudsoncedaron]

Incorrect measurement are including startup cost in the measurement.

I checked for that before posting. And to humor you I checked again just now. The startup costs are too small to reflect in the benchmark. I had pruned the startup cost check in minimization for posting as it wasn't doing anything useful.

I have in fact hit the limit of Stopwatch and to report a meaningful percentage I would have to do better.

But you know what that's not the point. I'm not here for a 10% gains one way or the other. I'm here for a compiler missed optimization.

[jhudsoncedaron]

Okay; so I have come to the end of the search; it's a missed optimization in a .NET 7 compiler.

I duped myself; because -c Debug and -c Release didn't matter on .NET 7 I never got around to trying it on .NET 10. And the only reason I was using NET 7 was for parity with LinqPad. In production we are using .NET 10.

With release:

net7>dotnet run -c Release
.NET 7.0.20
bytes: 46092584 elapsed 00:00:00.0972081
bytes: 15545328 elapsed 00:00:00.0720358
bytes: 14099112

(global.json doesn't matter; I tried it the first time without...)

\net10>dotnet run -c Release
.NET 10.0.13
bytes: 14412712 elapsed 00:00:00.0765600
bytes: 15539000 elapsed 00:00:00.0679839
bytes: 14098816

We're done here. I don't know why LinqPad is able to pick up optimizations from newer .NET versions than it builds against; but it does. And that sent me down a wrong path.