TechEmpower Performance

[benaadams]

Last 2 CI runs on TE (https://tfb-status.techempower.com/) have had a performance regression for corert:

References package

<PackageReference Include="Microsoft.DotNet.ILCompiler" Version="1.0.0-alpha-*" />

Project source https://github.com/TechEmpower/FrameworkBenchmarks/tree/master/frameworks/CSharp/aspnetcore-corert/PlatformBenchmarks

Also have increased error rate, which might be related?

[jkotas]

This is the window where the regression occurred:

Last good run: started 2018-08-11 at 2:10 PM

First bad run: last updated 2018-08-17 at 5:44 PM

[benaadams]

Looks even worse

started 2018-08-22 at 8:17 AM
last updated 2018-08-25 at 11:06 AM
completed 2018-08-25 at 11:06 AM

[jkotas]

There is a strong correlation between the error rate and throughput regression. Results from recent runs:

73.3% - 394 errors
41.1% - 3,508 errors
32.5% - 4,185 errors
20.9% - 6,824 errors
37.4% - 961 errors

So once the non-deterministic errors are fixed, the throughput regression is likely going to be fixed as well.

[benaadams]

Seem to be socket read errors (on client) at higher connection counts

4096 connections (read 961), 16384 connections (read 4366)

https://tfb-status.techempower.com/unzip/results.2018-08-30-17-08-55-680.zip/results/20180827214749/aspcore-corert/plaintext

---------------------------------------------------------
 Running Primer plaintext
 wrk -H 'Host: 10.0.0.1' -H 'Accept: text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7' -H 'Connection: keep-alive' --latency -d 5 -c 8 --timeout 8 -t 8 http://10.0.0.1:8080/plaintext
---------------------------------------------------------
Running 5s test @ http://10.0.0.1:8080/plaintext
  8 threads and 8 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    15.55ms   23.48ms 150.63ms   82.77%
    Req/Sec   554.36    468.23     8.61k    95.76%
  Latency Distribution
     50%    0.85ms
     75%   25.65ms
     90%   54.82ms
     99%   85.18ms
  22129 requests in 5.10s, 2.76MB read
Requests/sec:   4339.63
Transfer/sec:    555.17KB
---------------------------------------------------------
 Running Warmup plaintext
 wrk -H 'Host: 10.0.0.1' -H 'Accept: text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7' -H 'Connection: keep-alive' --latency -d 15 -c 512 --timeout 8 -t 28 http://10.0.0.1:8080/plaintext
---------------------------------------------------------
Running 15s test @ http://10.0.0.1:8080/plaintext
  28 threads and 512 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    92.55ms  150.25ms   1.44s    90.59%
    Req/Sec   468.64    464.70     4.88k    85.17%
  Latency Distribution
     50%   47.89ms
     75%  120.55ms
     90%  234.66ms
     99%  747.71ms
  171645 requests in 15.08s, 21.44MB read
Requests/sec:  11380.25
Transfer/sec:      1.42MB
---------------------------------------------------------
 Concurrency: 256 for plaintext
 wrk -H 'Host: 10.0.0.1' -H 'Accept: text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7' -H 'Connection: keep-alive' --latency -d 15 -c 256 --timeout 8 -t 28 http://10.0.0.1:8080/plaintext -s pipeline.lua -- 16
---------------------------------------------------------
Running 15s test @ http://10.0.0.1:8080/plaintext
  28 threads and 256 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    85.00ms  152.05ms   1.33s    93.02%
    Req/Sec     8.63k     8.28k   83.07k    85.42%
  Latency Distribution
     50%   45.38ms
     75%   78.34ms
     90%  165.06ms
     99%  900.08ms
  3361952 requests in 15.08s, 420.01MB read
Requests/sec: 222969.07
Transfer/sec:     27.86MB
STARTTIME 1535425208
ENDTIME 1535425224
---------------------------------------------------------
 Concurrency: 1024 for plaintext
 wrk -H 'Host: 10.0.0.1' -H 'Accept: text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7' -H 'Connection: keep-alive' --latency -d 15 -c 1024 --timeout 8 -t 28 http://10.0.0.1:8080/plaintext -s pipeline.lua -- 16
---------------------------------------------------------
Running 15s test @ http://10.0.0.1:8080/plaintext
  28 threads and 1024 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   233.00ms  264.25ms   2.50s    85.99%
    Req/Sec    11.44k    20.76k  180.80k    93.01%
  Latency Distribution
     50%  135.54ms
     75%  326.33ms
     90%  585.84ms
     99%    1.16s 
  3741264 requests in 15.09s, 467.40MB read
Requests/sec: 247889.31
Transfer/sec:     30.97MB
STARTTIME 1535425226
ENDTIME 1535425241
---------------------------------------------------------
 Concurrency: 4096 for plaintext
 wrk -H 'Host: 10.0.0.1' -H 'Accept: text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7' -H 'Connection: keep-alive' --latency -d 15 -c 4096 --timeout 8 -t 28 http://10.0.0.1:8080/plaintext -s pipeline.lua -- 16
---------------------------------------------------------
Running 15s test @ http://10.0.0.1:8080/plaintext
  28 threads and 4096 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   136.58ms  212.19ms   1.76s    83.93%
    Req/Sec   117.50k    73.85k  440.57k    60.34%
  Latency Distribution
     50%   28.52ms
     75%  169.15ms
     90%  493.60ms
     99%  813.21ms
  39524246 requests in 15.08s, 4.82GB read
  Socket errors: connect 0, read 961, write 0, timeout 0
Requests/sec: 2620758.33
Transfer/sec:    327.41MB
STARTTIME 1535425243
ENDTIME 1535425258
---------------------------------------------------------
 Concurrency: 16384 for plaintext
 wrk -H 'Host: 10.0.0.1' -H 'Accept: text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7' -H 'Connection: keep-alive' --latency -d 15 -c 16384 --timeout 8 -t 28 http://10.0.0.1:8080/plaintext -s pipeline.lua -- 16
---------------------------------------------------------
Running 15s test @ http://10.0.0.1:8080/plaintext
  28 threads and 16384 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   137.22ms  201.23ms   1.88s    87.30%
    Req/Sec   121.48k   109.05k  449.76k    66.27%
  Latency Distribution
     50%   52.10ms
     75%  152.97ms
     90%  415.88ms
     99%  947.93ms
  38597632 requests in 15.10s, 4.71GB read
  Socket errors: connect 0, read 4366, write 0, timeout 0
Requests/sec: 2556082.09
Transfer/sec:    319.33MB
STARTTIME 1535425260
ENDTIME 1535425275

[benaadams]

Concurrency: 4096  Socket errors: connect 0, read 550, write 0, timeout 0
Concurrency: 16384 Socket errors: connect 0, read 4054, write 0, timeout 0

started 2018-09-02 at 7:41 PM
last updated 2018-09-05 at 9:55 PM
completed 2018-09-05 at 9:55 PM
elapsed time ~74 hours

---------------------------------------------------------
 Running Primer plaintext
 wrk -H 'Host: 10.0.0.1' -H 'Accept: text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7' -H 'Connection: keep-alive' --latency -d 5 -c 8 --timeout 8 -t 8 http://10.0.0.1:8080/plaintext
---------------------------------------------------------
Running 5s test @ http://10.0.0.1:8080/plaintext
  8 threads and 8 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    16.59ms   24.65ms  95.14ms   81.68%
    Req/Sec   696.56    305.40     1.94k    75.25%
  Latency Distribution
     50%  772.00us
     75%   29.31ms
     90%   59.01ms
     99%   85.46ms
  27748 requests in 5.01s, 3.47MB read
Requests/sec:   5541.57
Transfer/sec:    708.93KB
---------------------------------------------------------
 Running Warmup plaintext
 wrk -H 'Host: 10.0.0.1' -H 'Accept: text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7' -H 'Connection: keep-alive' --latency -d 15 -c 512 --timeout 8 -t 28 http://10.0.0.1:8080/plaintext
---------------------------------------------------------
Running 15s test @ http://10.0.0.1:8080/plaintext
  28 threads and 512 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    80.53ms  124.26ms   1.02s    92.94%
    Req/Sec   385.04    417.17     2.63k    87.95%
  Latency Distribution
     50%   49.10ms
     75%  110.16ms
     90%  182.52ms
     99%  744.32ms
  144640 requests in 15.09s, 18.07MB read
Requests/sec:   9584.51
Transfer/sec:      1.20MB
---------------------------------------------------------
 Concurrency: 256 for plaintext
 wrk -H 'Host: 10.0.0.1' -H 'Accept: text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7' -H 'Connection: keep-alive' --latency -d 15 -c 256 --timeout 8 -t 28 http://10.0.0.1:8080/plaintext -s pipeline.lua -- 16
---------------------------------------------------------
Running 15s test @ http://10.0.0.1:8080/plaintext
  28 threads and 256 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   112.17ms  230.82ms   1.60s    92.85%
    Req/Sec     8.88k     7.99k   75.20k    81.55%
  Latency Distribution
     50%   46.78ms
     75%   82.82ms
     90%  208.45ms
     99%    1.29s 
  3360976 requests in 15.08s, 419.89MB read
Requests/sec: 222848.54
Transfer/sec:     27.84MB
STARTTIME 1535960939
ENDTIME 1535960954
---------------------------------------------------------
 Concurrency: 1024 for plaintext
 wrk -H 'Host: 10.0.0.1' -H 'Accept: text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7' -H 'Connection: keep-alive' --latency -d 15 -c 1024 --timeout 8 -t 28 http://10.0.0.1:8080/plaintext -s pipeline.lua -- 16
---------------------------------------------------------
Running 15s test @ http://10.0.0.1:8080/plaintext
  28 threads and 1024 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   192.06ms  189.81ms   2.73s    79.98%
    Req/Sec    12.45k    31.31k  354.72k    93.37%
  Latency Distribution
     50%  128.03ms
     75%  286.45ms
     90%  471.87ms
     99%  755.26ms
  4169152 requests in 15.09s, 520.86MB read
Requests/sec: 276257.21
Transfer/sec:     34.51MB
STARTTIME 1535960956
ENDTIME 1535960971
---------------------------------------------------------
 Concurrency: 4096 for plaintext
 wrk -H 'Host: 10.0.0.1' -H 'Accept: text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7' -H 'Connection: keep-alive' --latency -d 15 -c 4096 --timeout 8 -t 28 http://10.0.0.1:8080/plaintext -s pipeline.lua -- 16
---------------------------------------------------------
Running 15s test @ http://10.0.0.1:8080/plaintext
  28 threads and 4096 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   138.05ms  230.64ms   1.46s    85.21%
    Req/Sec   112.89k    72.23k  433.94k    55.74%
  Latency Distribution
     50%   28.31ms
     75%  121.27ms
     90%  535.78ms
     99%  915.32ms
  36713904 requests in 15.09s, 4.48GB read
  Socket errors: connect 0, read 550, write 0, timeout 0
Requests/sec: 2433087.85
Transfer/sec:    303.97MB
STARTTIME 1535960973
ENDTIME 1535960989
---------------------------------------------------------
 Concurrency: 16384 for plaintext
 wrk -H 'Host: 10.0.0.1' -H 'Accept: text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7' -H 'Connection: keep-alive' --latency -d 15 -c 16384 --timeout 8 -t 28 http://10.0.0.1:8080/plaintext -s pipeline.lua -- 16
---------------------------------------------------------
Running 15s test @ http://10.0.0.1:8080/plaintext
  28 threads and 16384 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   150.05ms  224.65ms   2.00s    89.38%
    Req/Sec    92.81k    87.29k  423.27k    74.75%
  Latency Distribution
     50%   65.55ms
     75%  159.30ms
     90%  402.48ms
     99%    1.09s 
  34246800 requests in 15.08s, 4.18GB read
  Socket errors: connect 0, read 4054, write 0, timeout 0
Requests/sec: 2270471.81
Transfer/sec:    283.65MB
STARTTIME 1535960991
ENDTIME 1535961006

[jkotas]

I have tried to reproduce these errors locally (everything running on same machine), no luck so far.

[benaadams]

@sebastienros can you reproduce the errors in the aspnet environment?

Is the corert dockerfile https://github.com/TechEmpower/FrameworkBenchmarks/tree/master/frameworks/CSharp/aspnetcore-corert

[MichalStrehovsky]

I think I'm hitting a local repro with this on Windows:

private static void Main()
{
    Task[] tasks = new Task[4096];
    for (int i = 0; i < tasks.Length; i++)
        tasks[i] = Task.Run(() =>
        {
            var client = new System.Net.WebClient();
            for (int req = 0; req < 4096; req++)
            {
                 client.DownloadString("http://localhost:8080/plaintext");
             }
         });
    Task.WaitAll(tasks);
}

Sometimes this gives "System.Net.Sockets.SocketException: 'No connection could be made because the target machine actively refused it'" on the client side. But I don't really know what to do with it next.

[sebastienros]

@benaadams I will try to repro on our different environments.

[benaadams]

Seems to have recovered, and no errors

[MichalStrehovsky]

Hmmm. We should watch this, but this would be a nice surprise if it sticks. We haven't actually done any targeted fixes.

[MichalStrehovsky]

Starting to look better. I see we are spending a bunch of time in RhSpinWait and Jan pointed me towards some fixes on the CoreCLR side that were specifically done to fix spinning on Skylake machines (that Techempower uses). Catching up with CoreCLR might be down to porting those fixes.