Regression in Caching TechEmpower benchmark

[adamsitnik]

I wanted to provide some nice benchmark results for @maryamariyan who is currently writing the blog post about Microsoft.Extensions* improvements we did for .NET 6.

To my surprise, the CachingPlatform-intel-win has regressed from 290k+ to 270k RPS. CachingPlatform-intel (which is running on Linux) regressed from 270k+ to 255k RPS.

The regression happened on the 12th of April:

Power BI

I have taken a brief look at the profiles and it seems that it has been caused by #50778 which got also confirmed by the perf bot in DrewScoggins/performance-2#5151

The Caching benchmark is very specific, as due to caching the values are fetched from the database only once, and most of the time (40%+) is spent in... JSON serialization ;)

The JSON serialization logic can be found here:

https://github.com/aspnet/Benchmarks/blob/6e7bff20860c92fd22b511bfd160f6f153e7e96e/src/BenchmarksApps/Kestrel/PlatformBenchmarks/BenchmarkApplication.MultipleQueries.cs#L17-L39

In the case of this particular benchmark, we are serializing an array of one hundred instances of World, which is a very small class:

https://github.com/aspnet/Benchmarks/blob/6e7bff20860c92fd22b511bfd160f6f153e7e96e/src/BenchmarksApps/Kestrel/PlatformBenchmarks/Data/CachedWorld.cs

@eiriktsarpalis @layomia @steveharter is there any chance that you could take a look?

edit: struct -> class

[ghost]

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

Issue Details

---

I wanted to provide some nice benchmark results for @maryamariyan who is currently writing the blog post about Microsoft.Extensions* improvements we did for .NET 6.

To my surprise, the CachingPlatform-intel-win has regressed from 290k+ to 270k RPS. CachingPlatform-intel (which is running on Linux) regressed from 270k+ to 255k RPS.

The regression happened on the 12th of April:

Power BI

I have taken a brief look at the profiles and it seems that it has been caused by #50778 which got also confirmed by the perf bot in DrewScoggins/performance-2#5151

The Caching benchmark is very specific, as due to caching the values are fetched from the database only once, and most of the time (40%+) is spent in... JSON serialization ;)

The JSON serialization logic can be found here:

https://github.com/aspnet/Benchmarks/blob/6e7bff20860c92fd22b511bfd160f6f153e7e96e/src/BenchmarksApps/Kestrel/PlatformBenchmarks/BenchmarkApplication.MultipleQueries.cs#L17-L39

In the case of this particular benchmark, we are serializing an array of one hundred instances of Word, which is a very small struct:

https://github.com/aspnet/Benchmarks/blob/6e7bff20860c92fd22b511bfd160f6f153e7e96e/src/BenchmarksApps/Kestrel/PlatformBenchmarks/Data/World.cs#L8-L14

@eiriktsarpalis @layomia @steveharter is there any chance that you could take a look?

Author:	adamsitnik
Assignees:	-
Labels:	area-System.Text.Json, tenet-performance
Milestone:	-

[eiriktsarpalis]

Are you sure that the regression is observed in the serialization logic that you shared? It is expected that the new feature should record regressions in async serialization since it now has to do more work (and indeed the report in DrewScoggins/performance-2#5151 concerns async serialization).

I don't believe that the change should impact sync serialization substantially: the only changes impacting that codepath are the following: JsonSerializer.Write.Helpers.cs and WriteStack.cs.

[adamsitnik]

Are you sure that the regression is observed in the serialization logic that you shared?

I am not 100% sure that it's caused by #50778 (I've taken only a brief look at the profiles) but I am quite sure that it's related to JSON serialization as I can repro it locally using the following microbenchmark:

[BenchmarkCategory(Categories.Libraries)]
public class TechEmpower
{
    public sealed class CachedWorld
    {
        public int Id { get; set; }
        public int RandomNumber { get; set; }
    }

    private static readonly JsonSerializerOptions SerializerOptions = new JsonSerializerOptions();
    private CachedWorld[] _array;
    private Utf8JsonWriter _utf8JsonWriter;
    private ArrayBufferWriter<byte> _arrayBufferWriter;

    [GlobalSetup]
    public void Setup()
    {
        var random = new Random(0);

        _array = Enumerable.Range(0, 100).Select(_ => new CachedWorld() { Id = random.Next(1, 10001), RandomNumber = random.Next(1, 10001) }).ToArray();
        _arrayBufferWriter = new ArrayBufferWriter<byte>();
        _utf8JsonWriter = new Utf8JsonWriter(_arrayBufferWriter, new JsonWriterOptions { SkipValidation = true });
    }

    [Benchmark]
    public void Serialize()
    {
        _arrayBufferWriter.Clear();
        _utf8JsonWriter.Reset(_arrayBufferWriter);

        JsonSerializer.Serialize<CachedWorld[]>(_utf8JsonWriter, _array, SerializerOptions);
    }
}

dotnet run -c Release -f net5.0 --filter *TechEmpower* --runtimes net5.0 net6.0

I get the following numbers:

Method	Runtime	Mean	Ratio	Allocated
Serialize	.NET 5.0	14.63 us	1.00	312 B
Serialize	.NET 6.0	16.95 us	1.16	376 B

It's 16% slower than .NET 5. Since JSON serialization takes sth around 40% of CPU time for the Caching benchmark, it translates to 6.4% of CPU time which would explain the regression we can see (6.4% of 290k = 18.5k RPS)

I've run this microbenchmark with a profiler attached and a hardcoded number of invocations per iterations (to compare apples to apples):

dotnet run -c Release -f net5.0 --filter *TechEmpower* --runtimes net5.0 net6.0 --invocationCount 16000 --profiler ETW 

Filtered the trace files to the last iteration (to minimize the chance of Tiered JIT getting into play) and got the following results:

.NET 5:

.NET 6:

Does it somehow help? Can you see any potential sources of the regression?

[eiriktsarpalis]

I'm almost certain that it is unrelated to #50778 but we need to run a bisect to be absolutely sure. cc @layomia @steveharter

[adamsitnik]

As soon as we merge aspnet/Benchmarks#1683 (comment) we can close this issue.

[sebastienros]

I confirm the regression was due to this change in STJ.

Repro commands between two consecutive builds:

crank --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/scenarios/platform.benchmarks.yml --scenario caching --profile aspnet-citrine-lin --application.runtimeVersion 6.0.0-preview.4.21212.3 --application.framework net6.0 --application.aspnetCoreVersion 6.0.0-preview.4.21211.1 --application.source.branchOrCommit "#29baaf29e2c775f282cdbfb7ec03dcebbc29bcc7" --iterations 5 --variable warmup=0 --exclude 1 --exclude-order "load:wrk/rps/mean"

crank --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/scenarios/platform.benchmarks.yml --scenario caching --profile aspnet-citrine-lin --application.runtimeVersion 6.0.0-preview.4.21212.4 --application.framework net6.0 --application.aspnetCoreVersion 6.0.0-preview.4.21211.1 --application.source.branchOrCommit "#29baaf29e2c775f282cdbfb7ec03dcebbc29bcc7" --iterations 5 --variable warmup=0 --exclude 1 --exclude-order "load:wrk/rps/mean"

Which then points to these commits:
1119725...8d102e3

I then ran runtime version before this change, and pushed only System.Text.Json.dll to confirm this was the reason of the regression.

Results are consistently going from 264K to 255K rps.

[steveharter]

Overlaps with #56993 which also uses the raw Utf8JsonWriter.

[steveharter]

Please re-verify based on #57327. Thanks

[adamsitnik]

Please re-verify based on #57327.

@sebastienros do we need to wait until aspnet/benchmarks https://dotnetcli.blob.core.windows.net/dotnet/Sdk/main/latest.version points to RC1, or is there some way of testing it sooner than that?

@steveharter thanks for the fix!