Regression in connections creation performance

[sebastienros]

I detected a regression due to this PR #53340 on "connection close" scenarios where we measure the speed of creating connections. It was discovered while investigating ssl handshakes performance comparisons with HttpSys. We discovered the difference was not due to the handshake itself.

On a 12 v-cores windows machines (aspnet-perf-win) it reduces RPS from 14K to 5K and latency goes from 2ms to 6ms. The load generator sends a Connection: close header to force new connections on every request. Can also be measured on Linux.

I can gather traces for the runs before and after the change. Let me know if you want to see ThreadTime/NetworkTCPIP in these since it impacts the traces size and perf differences. These benchmarks are not CPU bound and show a lot of BLOCKED time. The NetworkTCPIP stack might be unnecessary at this level.

@karelz @halter73 @geoffkizer

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.

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

Issue Details

---

I detected a regression due to this PR #53340 on "connection close" scenarios where we measure the speed of creating connections. It was discovered while investigating ssl handshakes performance comparisons with HttpSys. We discovered the difference was not due to the handshake itself.

On a 12 v-cores windows machines (aspnet-perf-win) it reduces RPS from 14K to 5K and latency goes from 2ms to 6ms. The load generator sends a Connection: close header to force new connections on every request. Can also be measured on Linux.

I can gather traces for the runs before and after the change. Let me know if you want to see ThreadTime/NetworkTCPIP in these since it impacts the traces size and perf differences. These benchmarks are not CPU bound and show a lot of BLOCKED time. The NetworkTCPIP stack might be unnecessary at this level.

@karelz @halter73 @geoffkizer

Author:	sebastienros
Assignees:	-
Labels:	area-System.Net.Sockets, tenet-performance, untriaged
Milestone:	-

[geoffkizer]

Wow, that's a big regression. The linked PR did shuffle around some of the internal handling here, so perhaps that introduced an issue.

Since we are seeing a lot of BLOCKED time, it sounds like we have some sort of contention issue. Can you tell from the traces where the contention is occurring? I looked at the code, but don't see anything obvious here; there are a bunch of interlocked ops but no explicit blocking that I see.

[karelz]

Given that this is non-trivial regression, we should fix it sooner in 7.0 and then consider backporting it to 6.0 based on fix risk and assessed + observed impact on customers.

[geoffkizer]

I did notice one issue that could cause increased memory usage. Fix is here: #61258

@sebastienros Can you try that out and see if it helps?

This seems like a small issue so I doubt it would be the root cause here, but it's worth a shot.

[sebastienros]

Crank command lines to repro and get traces:

Before (build 6.0.0-preview.6.21279.1+ff72cc9)

crank --config https://github.com/aspnet/Benchmarks/blob/main/src/BenchmarksApps/HelloWorldMiddleware/benchmarks.yml?raw=true --scenario connectionclose --profile aspnet-perf-win --application.framework net6.0 --chart --variable warmup=3 --variable duration=8 --variable connections=32  --application.aspnetcoreversion 6.0.0-preview.6.21279.2 --application.runtimeversion 6.0.0-preview.6.21279.1 --application.sdkVersion 6.0.100-preview.6.21276.12 --application.options.collectCounters true --application.collect true

After (build 6.0.0-preview.6.21279.3+b5c91e4)

crank --config https://github.com/aspnet/Benchmarks/blob/main/src/BenchmarksApps/HelloWorldMiddleware/benchmarks.yml?raw=true --scenario connectionclose --profile aspnet-perf-win --application.framework net6.0 --chart --variable warmup=3 --variable duration=8 --variable connections=32  --application.aspnetcoreversion 6.0.0-preview.6.21279.2 --application.runtimeversion 6.0.0-preview.6.21279.3 --application.sdkVersion 6.0.100-preview.6.21276.12 --application.options.collectCounters true --application.collect true

To remove ThreadTime from traces as it makes them much bigger, use this argument and remove +ThreadTime

--application.collectArguments "BufferSizeMB=1024;CircularMB=4096;TplEvents=None;Providers=Microsoft-Diagnostics-DiagnosticSource:0:0;KernelEvents=default+ThreadTime-NetworkTCPIP"

To test local changes add this argument:

--application.options.outputFiles "c:\build\socketsdll-release\*.*"

Note that collecting a trace impacts the RPS significantly, so to compare local changes impact I recommend to disable it.

[geoffkizer]

I did a run with #61258 and it does not seem to be the root cause here. Further investigation is needed.

[geoffkizer]

I did some runs on Linux (aspnet-perf-lin) and I see bimodal behavior there:

Before		After
req/s	CPU	req/s	CPU
12844	96	17217	92
6715	51	6659	49
14583	93	20078	91
15310	93	6616	50
6601	50	15051	93

This is weird and should be investigated further, but it's not a regression.

Windows results seem to be consistent, with Before around 17k and After around 6-7k. However, these results are similar enough to the two modes above that I wonder if something inadvertantly triggered the Windows behavior to switch from being consistently in the good mode, to consistently in the bad mode.

More investigation is needed here.

[karelz]

Triage: The PR shouldn't have caused this type of regression.
Linux was bimodal even before the PR, Windows after the PR is always "bad", This is weird, might be test issue, ASP.NET issue or Runtime issue -- we need to learn more.
Warning: Depends on HW.

Next step: Create micro-benchmark here (e.g. remove ASP.NET from the repro).