request processing slows down on concurrent requests.

[livarcocc]

From @rkdrnfds on March 29, 2018 6:43

Request handling extremely slows down on concurrent requests

[Route("Test")]
public class TestController : Controller {
        [HttpGet("DoNothingGet")]
        public void DoNothingGet() { }
}

Against above controller, I tested concurrent request using shell script below

for i in {1..50}
do
curl -X GET "http://localhost:5000/Test/DoNothingGet" -H "Host: 127.0.0.1:5000" -H "X-Debug: true" -H "User-Agent: Terminal" -d "[0, 0]" &
done

For sequential request, there's almost no delay for processing requests. consuming about 1~5ms per request. but For concurrent request, handling time varies from 100ms ~ 2000ms

There's light middleware attached for logging execution time.

public class ProcessingTimeLoggingMiddleware
    {
        readonly RequestDelegate _next;
        readonly ILogger<RequestLoggingMiddleware> _logger;

        public ProcessingTimeLoggingMiddleware(
            RequestDelegate next,
            ILogger<RequestLoggingMiddleware> logger
        )
        {
            _logger = logger;
            _next = next;
        }

        public async Task Invoke(HttpContext context)
        {
            _logger.LogInformation("Start Middleware");
            var sw = Stopwatch.StartNew();

            await _next.Invoke(context);

            sw.Stop();

            _logger.LogInformation(LoggingEvents.RequestProcessingTime,
                "Processing {Path} [{StatusCode}] took {ElapsedTime}ms.",
                context.Request.Path, context.Response.StatusCode, sw.ElapsedMilliseconds
            );
        }
    }

Below are collected logs for slow request. (one of 50 requests. others also have similar logs)

March 29th 2018, 15:50:20.286 Microsoft.AspNetCore.Hosting.Internal.WebHost 
Request starting HTTP/1.1 GET http://127.0.0.1:5000/Test/DoNothingGet application/x-www-form-urlencoded 6

March 29th 2018, 15:50:20.412 Server.Middlewares.RequestLoggingMiddleware 
Start Middleware

March 29th 2018, 15:50:21.445 Server.Middlewares.RequestLoggingMiddleware 
Processing /Test/DoNothingGet [200] took 830ms

March 29th 2018, 15:50:22.439 Microsoft.AspNetCore.Hosting.Internal.WebHost 
Request finished in 2166.119ms 

I tried manipulating ThreadPool.SetMinThreads and KestrelServerOptions.Limits.MaxConcurrentConnection but nothing had any effect.

Environment data

<PackageReference Include="Microsoft.AspNetCore.Hosting" Version="2.0.0" />
    <PackageReference Include="Microsoft.AspNetCore.Mvc" Version="2.1.0-preview1-final" />
    <PackageReference Include="Microsoft.AspNetCore.Owin" Version="2.0.0" />
    <PackageReference Include="Microsoft.AspNetCore.Server.Kestrel" Version="2.0.0" />

Product Information:
 Version:            2.1.4
 Commit SHA-1 hash:  5e8add2190

Runtime Environment:
 OS Name:     Mac OS X
 OS Version:  10.13
 OS Platform: Darwin
 RID:         osx.10.12-x64
 Base Path:   /usr/local/share/dotnet/sdk/2.1.4/

Microsoft .NET Core Shared Framework Host

  Version  : 2.0.5
  Build    : 17373eb129b3b05aa18ece963f8795d65ef8ea54

Copied from original issue: dotnet/cli#8930

[Eilon]

@sebastienros - can you take a look at this?

[sebastienros]

1- Do you have Console logging enabled? If so please try without it. 2- How are you creating the concurrent load? I can see the serial one only, using curl commands.

[rkdrnfds]

1- Disabling Console logging changed nothing. 2- By attaching '&' at the end of the curl command, it runs in the background. I tested sequential request without '&', concurrent request with '&' and there's really big performance gap between the results of two.

• Changing SetMinThreads to (1024, 1024) which was 100, 100 before gave me some improvements. Now handling time of slow requests ranges 100 ~ 1500ms

• Sorry I missed to tell you that aboves ran in Debug mode with Jetbrains Rider debugger attached. without debugger, 50 concurrent request also runs super fast. But I'm still curious what makes concurrent request slower than sequential request.

[sebastienros]

We do a lot of perf testing on aspnet, the results are available here: https://aka.ms/aspnet/benchmarks, so I am quite confident there is a flaw in your testing. Can we agree on the methodology and try again your app?

• Published the application in Release mode: dotnet publish -c Release -o c:\temp\myapp
• Run the published application: dotnet c:\temp\myapp\myapp.dll
• Use a load test generator (instead of curl) that will create concurrent requests, please use Apache Bench (Linux and Windows) or Wrk (Linux only) to start a load test

In parallel I will try to reproduce your numbers locally to understand what is happening. Could you share the exact application somewhere (on github for instance) to be sure we are testing the same thing?

[rkdrnfds]

Debugger seems to be a bottleneck. without debugger, it runs with no problem. It seems inadequate to measure performance with debugger attached, so it was my fault after all.

repro github For reproduction, you can test it with jetbrain rider 2017.3.1 debugger attached.

[Eilon]

Yes, the debugger can add an enormous amount of overhead to the system. Some parts of the system change their behavior when they detect an attached debugger to offer additional diagnostic information, which slows things down.

Given that this was running with the debugger, I'm closing this issue. Thanks!

[peppy]

As a note, your debug performance issue will likely be fixed by https://github.com/dotnet/coreclr/issues/18705 (coming in 2.2)