Suprising lack of AIO in traces

[adamsitnik]

I've run JSON and Plaintext benchmark on a machine that supports collecting perf traces (it's not the TechEmpower machine which I am always using to run the benchmarks for this experiment) using LTTNg and what I found is lack of io_submit in the traces (I can see it when I am running my own AIO implementation).

 --path "/plaintext" --arg "-e=epoll" --arg "-t=1" --arg "-s=false" --arg "-r=false" --arg "-c=true" --arg "-a=true" --connections 256

All I find is: Tmds.LinuxAsync!Tmds.LinuxAsync.EPollAsyncEngine+LinuxAio::ExecuteOperations

@tmds is there any execution path that besides passing -a=true AIO could be disabled or not working? I had a similar issue in my implementation when IOQueue ProcessReceives was creating 0 bytes reads.

BTW All the ThreadsAggregated on a single screen:

[tmds]

I'm taking a look.

[tmds]

This is interesting...

Tmds.LinuxAsync/src/Tmds.LinuxAsync.Transport/Internal/SocketConnection.cs

Lines 193 to 199 in 201db8c

	// Wait for data before allocating a buffer.
	await _receiver.WaitForDataAsync();
	// Ensure we have some reasonable amount of buffer space
	var buffer = input.GetMemory(MinAllocBufferSize);
	var bytesReceived = await _receiver.ReceiveAsync(buffer);

WaitForDataAsync does a 0-byte read, which can't be batched by Linux AIO.

That read completes on the the ThreadPool.

Then ReceiveAsync performs a synchronous attempt to receive. Which is successfully, because we've already waited for the input to be ready with WaitForDataAsync.

net-effect: no usage of Linux AIO.

I don't understand how -a true/false affected these benchmarks: #24 (comment).

Even when setting c=false Linux AIO doesn't get used, because WaitForDataAsync completes on the epoll thread, but ReceiveAsync is not aware and performs a sync receive call without batching. This needs to be fixed.

When setting r/s to true, you should see some Linux AIO show up.
These may be improved when used in combination with c=false.

[adamsitnik]

WaitForDataAsync does a 0-byte read, which can't be batched by Linux AIO

That was also the case for my implementation. Now we need to figure out why no writes are batched. Are they so small that they always succeed?

BTW In my implementation, I've just removed this line and it has not regressed performance, allowed AIO to batch 1/2 of the reads. The other half of the reads most probably succeed here:

https://github.com/dotnet/runtime/blob/4f9ae42d861fcb4be2fcd5d3d55d5f227d30e723/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncContext.Unix.cs#L1513-L1517

I don't understand how -a true/false affected these benchmarks:

Unfortunately, I can't use a profiler on this machine and I have no idea why ;/

[tmds]

Are they so small that they always succeed?

Yes.

BTW In my implementation, I've just removed this line and it has not regressed performance, allowed AIO to batch 1/2 of the reads. The other half of the reads most probably succeed here:

I'm not sure what line you removed? and where the other half succeed?

Unfortunately, I can't use a profiler on this machine and I have no idea why ;/

Let's use the machines where we can get profiles for further benchmarks.

Even when setting c=false Linux AIO doesn't get used, because WaitForDataAsync completes on the epoll thread, but ReceiveAsync is not aware and performs a sync receive call without batching. This needs to be fixed.

I'll fix this tomorrow.

[adamsitnik]

Hmm I wonder how we could batch these small writes and don't affect latency in a negative way ;/

I'm not sure what line you removed? and where the other half succeed?

I mean that if I remove this line: https://github.com/dotnet/aspnetcore/blob/ab52a1d3ed3fe6e62caa4bb9144f0a6f9d2c3225/src/Servers/Kestrel/Transport.Sockets/src/Internal/SocketConnection.cs#L190 and combine in with adamsitnik/runtime#1

I get to the situation where half of the reads are batched using AIO (the rest fails to be batched, but succeeds to be sent). But none writes are batched - they are too small ;(

Let's use the machines where we can get profiles for further benchmarks.

Good point.

I'll fix this tomorrow.

Great. Please send me a list of commands as usual ;)

[tmds]

With #37, setting c=false leads to AIO getting used for the ReceiveAsync calls.

Let's take a look at the benchmark results and flame graphs if we toggle this arg:

--path "/json" --arg "-e=epoll" --arg "-t=1" --arg "-s=false" --arg "-r=false" --arg "-c=true" --arg "-a=true" --connections 256
--path "/json" --arg "-e=epoll" --arg "-t=1" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256

[adamsitnik]

The numbers are lower because they come from 12 core machine (not 28 like in TechEmpower)

--path "/json" --arg "-e=epoll" --arg "-t=1" --arg "-s=false" --arg "-r=false" --arg "-c=true" --arg "-a=true" --connections 256 

RequestsPerSecond:           396,847
Max CPU (%):                 98
WorkingSet (MB):             192
Avg. Latency (ms):           0.89
Startup (ms):                1
First Request (ms):          123.33
Latency (ms):                0.62
Total Requests:              5,978,485
Duration: (ms)               15,060
Socket Errors:               0
Bad Responses:               0
Build Time (ms):             4,502
Published Size (KB):         1,059
SDK:                         5.0.100-preview.1.20106.1
Runtime:                     5.0.0-preview.2.20120.8
ASP.NET Core:                5.0.0-preview.2.20124.10

All threads except of the single epoll thread look more or less like this:

The epoll thread:

But I still can't see aio_submit anywhere

[tmds]

But I still can't see aio_submit anywhere

You need to run the other one (c=false):

--path "/json" --arg "-e=epoll" --arg "-t=1" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256

[adamsitnik]

--path "/json" --arg "-e=epoll" --arg "-t=1" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256 

RequestsPerSecond:           204,302
Max CPU (%):                 74
WorkingSet (MB):             196
Avg. Latency (ms):           1.3
Startup (ms):                1
First Request (ms):          111.06
Latency (ms):                0.48
Total Requests:              3,084,753
Duration: (ms)               15,100
Socket Errors:               0
Bad Responses:               0
Build Time (ms):             4,502
Published Size (KB):         1,059
SDK:                         5.0.100-preview.1.20106.1
Runtime:                     5.0.0-preview.2.20120.8
ASP.NET Core:                5.0.0-preview.2.20124.10

All Threads:

All threads except of the single epoll thread look more or less like this:

And here comes the epoll|AIO thread:

[tmds]

Can you run the c=false with higher thread count (until RPS starts to decline)?

--path "/json" --arg "-e=epoll" --arg "-t=1" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256 
--path "/json" --arg "-e=epoll" --arg "-t=2" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256 
--path "/json" --arg "-e=epoll" --arg "-t=3" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256 
--path "/json" --arg "-e=epoll" --arg "-t=4" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256 
--path "/json" --arg "-e=epoll" --arg "-t=5" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256 
...

[tmds]

And verify t>1 reduces RPS when c=true:

--path "/json" --arg "-e=epoll" --arg "-t=1" --arg "-s=false" --arg "-r=false" --arg "-c=true" --arg "-a=true" --connections 256 
--path "/json" --arg "-e=epoll" --arg "-t=2" --arg "-s=false" --arg "-r=false" --arg "-c=true" --arg "-a=true" --connections 256 
--path "/json" --arg "-e=epoll" --arg "-t=3" --arg "-s=false" --arg "-r=false" --arg "-c=true" --arg "-a=true" --connections 256

No need for flamegraphs for this and the previous benchmark (as long as the results match the expectations).

[adamsitnik]

Can you run the c=false with higher thread count (until RPS starts to decline)?

Sure! BTW it looks like 4 is optimal ;)

--path "/json" --arg "-e=epoll" --arg "-t=1" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256

RequestsPerSecond:           203,003
Max CPU (%):                 74
WorkingSet (MB):             201
Avg. Latency (ms):           1.33
Startup (ms):                13
First Request (ms):          122.44
Latency (ms):                0.49
Total Requests:              3,065,325
Duration: (ms)               15,100
Socket Errors:               0
Bad Responses:               0
Build Time (ms):             8,504
Published Size (KB):         1,059
SDK:                         5.0.100-preview.1.20106.1
Runtime:                     5.0.0-preview.2.20120.8
ASP.NET Core:                5.0.0-preview.2.20125.12

--path "/json" --arg "-e=epoll" --arg "-t=2" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256

RequestsPerSecond:           401,804
Max CPU (%):                 100
WorkingSet (MB):             189
Avg. Latency (ms):           0.77
Startup (ms):                2
First Request (ms):          95.8
Latency (ms):                0.73
Total Requests:              6,067,269
Duration: (ms)               15,100
Socket Errors:               0
Bad Responses:               0
Build Time (ms):             4,502
Published Size (KB):         1,059
SDK:                         5.0.100-preview.1.20106.1
Runtime:                     5.0.0-preview.2.20120.8
ASP.NET Core:                5.0.0-preview.2.20125.12

--path "/json" --arg "-e=epoll" --arg "-t=3" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256

RequestsPerSecond:           429,515
Max CPU (%):                 100
WorkingSet (MB):             189
Avg. Latency (ms):           1.34
Startup (ms):                2
First Request (ms):          86.07
Latency (ms):                1.11
Total Requests:              6,477,079
Duration: (ms)               15,080
Socket Errors:               0
Bad Responses:               0
Build Time (ms):             4,502
Published Size (KB):         1,059
SDK:                         5.0.100-preview.1.20106.1
Runtime:                     5.0.0-preview.2.20120.8
ASP.NET Core:                5.0.0-preview.2.20125.12

--path "/json" --arg "-e=epoll" --arg "-t=4" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256

RequestsPerSecond:           437,006
Max CPU (%):                 100
WorkingSet (MB):             186
Avg. Latency (ms):           1.69
Startup (ms):                2
First Request (ms):          97.04
Latency (ms):                0.62
Total Requests:              6,595,299
Duration: (ms)               15,090
Socket Errors:               0
Bad Responses:               0
Build Time (ms):             4,502
Published Size (KB):         1,059
SDK:                         5.0.100-preview.1.20106.1
Runtime:                     5.0.0-preview.2.20120.8
ASP.NET Core:                5.0.0-preview.2.20125.12

--path "/json" --arg "-e=epoll" --arg "-t=5" --arg "-s=false" --arg "-r=false" --arg "-c=false" --arg "-a=true" --connections 256

RequestsPerSecond:           425,223
Max CPU (%):                 100
WorkingSet (MB):             188
Avg. Latency (ms):           1.84
Startup (ms):                2
First Request (ms):          96.02
Latency (ms):                0.69
Total Requests:              6,420,839
Duration: (ms)               15,100
Socket Errors:               0
Bad Responses:               0
Build Time (ms):             4,002
Published Size (KB):         1,059
SDK:                         5.0.100-preview.1.20106.1
Runtime:                     5.0.0-preview.2.20120.8
ASP.NET Core:                5.0.0-preview.2.20125.12

[adamsitnik]

And verify t>1 reduces RPS when c=true:

--path "/json" --arg "-e=epoll" --arg "-t=1" --arg "-s=false" --arg "-r=false" --arg "-c=true" --arg "-a=true" --connections 256

RequestsPerSecond:           395,257
Max CPU (%):                 98
WorkingSet (MB):             190
Avg. Latency (ms):           0.91
Startup (ms):                2
First Request (ms):          94.26
Latency (ms):                0.83
Total Requests:              5,968,283
Duration: (ms)               15,100
Socket Errors:               0
Bad Responses:               0
Build Time (ms):             6,502
Published Size (KB):         1,059
SDK:                         5.0.100-preview.1.20106.1
Runtime:                     5.0.0-preview.2.20120.8
ASP.NET Core:                5.0.0-preview.2.20125.12

--path "/json" --arg "-e=epoll" --arg "-t=2" --arg "-s=false" --arg "-r=false" --arg "-c=true" --arg "-a=true" --connections 256

RequestsPerSecond:           362,084
Max CPU (%):                 100
WorkingSet (MB):             199
Avg. Latency (ms):           1.28
Startup (ms):                2
First Request (ms):          94.48
Latency (ms):                0.26
Total Requests:              5,467,198
Duration: (ms)               15,100
Socket Errors:               0
Bad Responses:               0
Build Time (ms):             4,002
Published Size (KB):         1,059
SDK:                         5.0.100-preview.1.20106.1
Runtime:                     5.0.0-preview.2.20120.8
ASP.NET Core:                5.0.0-preview.2.20125.12

--path "/json" --arg "-e=epoll" --arg "-t=3" --arg "-s=false" --arg "-r=false" --arg "-c=true" --arg "-a=true" --connections 256 

RequestsPerSecond:           371,466
Max CPU (%):                 99
WorkingSet (MB):             189
Avg. Latency (ms):           1.39
Startup (ms):                2
First Request (ms):          93.19
Latency (ms):                0.38
Total Requests:              5,608,891
Duration: (ms)               15,100
Socket Errors:               0
Bad Responses:               0
Build Time (ms):             4,502
Published Size (KB):         1,059
SDK:                         5.0.100-preview.1.20106.1
Runtime:                     5.0.0-preview.2.20120.8
ASP.NET Core:                5.0.0-preview.2.20125.12

[tmds]

Thanks! Putting things in a table:

configuration	RPS
c=true, t=1	baseline
c=false, t=1	-48.6%
c=false, t=2	+1.7%
c=false, t=3	+8.7%
c=false, t=4	+10.6%
c=false, t=5	-7.6%

The regression at c=false, t=1 is due to the epoll thread being the bottleneck (Max CPU (%): 74).

With c=false the socket ReceiveLoop runs on the epoll thread. The WaitForDataAsync are not batcheable with AIO and cause recvfrom system calls. The ReceiveAsync are batcheable with AIO. These show as recvfrom and io_submit in the flamegraph of #36 (comment).
(With io_uring, WaitForDataAsync is also batcheable.)