JsonResult causes thread pool exhaustion via synchronous flushes

[Tratcher]

From @lorenzos70 on September 16, 2018 11:35

Hello,

I have a .net 4.6.2 project (for my web apis) that is referencing, among other libraries, Microsoft.AspNetCore 2.1.3. I recently upgraded it from version 1.1. Since the upgrade I experienced the following issues on my production win 2016 server:

• my api logs often show the following messages:

  1. Connection id ""xxxxxx"", Request id ""yyyyyy"": the connection was closed because the response was not read by the client at the specified minimum data rate

  2. the request timed out because it was not sent by the client at a minimum of 240 bytes/second".

  3. [Warning] Connection processing ended abnormally.
     Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was aborted
     at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
     at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
     at System.IO.Pipelines.Pipe.GetReadAsyncResult()
     at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
     at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.
     d__1881.MoveNext()--- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol. <ProcessRequestsAsync>d__1871.MoveNext()

• The apis become unresponsive (they are hosted on iis 10 on a windows 2016 server)

• IIS logs show, at the same time, 502 errors while trying to call the api endoints

• I also noticed heavy peaks of the CPU.

Remarks: the web api load has not increased and there haven't been any other major changes, apart from the upgrade of the Microsoft.AspNetCore that I mentioned above, so I am still trying to figure out what the problem could be. Any advice that could point me to the right direction?
Thanks
Lorenzo

Copied from original issue: aspnet/KestrelHttpServer#2936

[Tratcher]

From @benaadams on September 16, 2018 13:32

Upgrade to 2.1.4 and revisit aspnet/Announcements#316

[Tratcher]

From @lorenzos70 on September 16, 2018 13:57

Hi Ben,

thanks for you reply: I tried but I realized that in my api project, which has been created using .NET 4.6 + .NET core (see first screenshot), the Nuget Packages manager doesn't show any release after the 2.1.3 (see second screenshot).

I also noticed that the upgrade to 2.1.4 is instead available for "pure" .NET core projects. Do I need to install anything on my developer machine?

[Tratcher]

From @benaadams on September 16, 2018 14:0

Ah, good point. Add a reference to (or upgrade) System.IO.Pipelines to 4.5.1 instead

[Tratcher]

From @lorenzos70 on September 16, 2018 14:11

Ok, thanks; I just added the System.IO.Pipelines refrerence (seems it wasn't installed before).

[Tratcher]

From @benaadams on September 16, 2018 14:16

seems it wasn't installed before

It would have been brought in as a dependent reference from one of the other libraries.

Not sure if it will fix the data rate issue you are seeing; but it could fix the CPU spikes; and at a stretch they could be related. So see if it still happens.

[Tratcher]

From @lorenzos70 on September 16, 2018 15:56

Thanks again Ben; do you think that referencing the System.IO.Pipelines directly as I did (but still having the Microsoft.AspNetCore 2.1.3 referenced, which seems not using it) will make Kestrel to load it anyway?

[Tratcher]

From @benaadams on September 16, 2018 16:3

Yes, Kestrel uses System.IO.Pipelines and adding a reference to 4.5.1 will cause it to use the patched version instead.

[Tratcher]

From @lorenzos70 on September 17, 2018 8:31

Unfortunately the problem occurred again even after the upgrade; I enabled the failed requests trace (see below) and I noticed that the response body's data buffers are read fine up to a certain point, and then the 502.3 error is raised by the AspNetCoreModule (so it seems that is not the database query that is running slow, but the way the retrieved data is processed by the underlying layers).
Moreover, the api logs also reveal the following error: Connection id ""xxxxyyyyy"" bad request data: "Reading the request body timed out due to data arriving too slowly. See MinRequestBodyDataRate".

[Tratcher]

From @lorenzos70 on September 18, 2018 11:49

Hi ben,

just to let you know that I found this: https://github.com/aspnet/KestrelHttpServer/issues/2104 which seems to describe exactly my situation. I indeed have some error handling methods that call something like this:
string _result = ReadRequest(context).GetAwaiter().GetResult();

Could this cause the mentioned prtoblems? Adding something like this to main():

        var host = new WebHostBuilder()
            .UseKestrel()
             .UseLibuv(options =>
             {
                 options.ThreadCount = 1000;
             })
             .UseContentRoot(Directory.GetCurrentDirectory())
            .UseIISIntegration()
            .UseStartup<Startup>()
            .UseApplicationInsights()
            .Build();

could also help mitigate the problem?
Thanks again

[Tratcher]

From @benaadams on September 18, 2018 13:20

Wondering if the synchronous Read could deadlock the read for regular sockets; which will then get killed off due to its data rate dropping to 0 byte/s /cc @halter73

[Tratcher]

From @halter73 on September 18, 2018 21:5

    options.ThreadCount = 1000;

This will create 1000 managed threads outside the ThreadPool which is way too much. Generally, we find the best performance comes from having about logical core count / 2 libuv threads. I don't recommend changing the libuv ThreadCount unless you've done extensive benchmarking proving it's better for all your scenarios.

As far as synchronous reads go, I'd advise against it since it can contribute to ThreadPool starvation. ThreadPool starvation (or even having 1000 libuv threads) is a possible cause request body rate timeouts if the starvation is so bad that read callbacks don't get scheduled in a timely manner.

I don't think a synchronous read could cause a deadlock in 2.1. There was a synchronous read deadlock in our 2.2 preview with HTTP/2 but that's in code that doesn't exist in 2.1. For HTTP/1.x, we always dispatch for reads unless you use a pubternal API to set the ApplicationSchedulingMode to Inline which you should never do if you're mixing sync and async I/O.

[Tratcher]

From @noelstieglitz on September 18, 2018 21:8

I started seeing a similar, sporadic issues yesterday in one Azure App Service and now am seeing it in a second:

Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException: Reading the request body timed out due to data arriving too slowly. See MinRequestBodyDataRate. at Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException.Throw(RequestRejectionReason reason) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1MessageBody.PumpAsync() at System.IO.Pipelines.PipeCompletion.ThrowLatchedException() at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result) at System.IO.Pipelines.Pipe.GetReadAsyncResult() at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.MessageBody.ReadAsync(Memory1 buffer, CancellationToken cancellationToken) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.ReadAsyncInternal(Memory1 buffer, CancellationToken cancellationToken) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.Read(Byte[] buffer, Int32 offset, Int32 count) at System.IO.StreamReader.ReadBuffer() at System.IO.StreamReader.ReadToEnd() at ServiceStack.Text.JsonSerializer.DeserializeFromStream(Type type, Stream stream) at ServiceStack.Serialization.JsonDataContractSerializer.DeserializeFromStream(Type type, Stream stream) at ServiceStack.Host.Handlers.ServiceStackHandlerBase.CreateContentTypeRequest(IRequest httpReq, Type requestType, String contentType)

I've only seen it happen on http POST operations. I upgraded one of the App Service's code base to use 2.1.4 (and verified no transitive dependencies were pointing to the affected versions) and am still seeing the issue. So far, it's not been reproducible locally, but it is sporadic, so I'll keep trying.
As a workaround, I could configure kestrel to increase the MinRequestBodyDataRate, but that's obviously not a long term solution.

This issue is reminiscent of #2151 .

[Tratcher]

From @halter73 on September 18, 2018 21:36

@noelstieglitz How long were you running your app without seeing issues before seeing issues yesterday? Did anything else notable change regarding your app around the time you starting seeing the request body rate timeouts?

Also, what makes this reminiscent #2151 to you? One thing that helped us resolve #2151 was getting info from the reporter about how to reproduce the issue on our own hardware allowing us to investigate the issue more rapidly without losing time going back and forth getting more and more diagnostics from a third party.

One thing you can try that might help if the issue is that read callbacks are getting dispatched slowly due to ThreadPool starvation or similar is to change the gracePeriod component of the MinRequestBodyDataRate MinDataRate value. The default is 5 seconds, but it can be increased to whatever you want without changing the actual rate that's expected for large reads.

[Tratcher]

From @lorenzos70 on September 19, 2018 14:2

@halter73 I think I may have some more details about the root of my 502.3 api errors in my environment: I run a stress test on a specific asp.net core web api using the code suggested by @benaadams on a previous issue.

When the number of requests per minute hit 100 or more I noticed that the problems started to appear: api unresponsive, requests ending up in a 502.3 error, logs showing "Connection id ""0HLGU6OA7QP1G"", Request id ""0HLGU6OA7QP1G:00000001"": the connection was closed because the response was not read by the client at the specified minimum data rate", kestrel to be restarted in order to wake the server up again.

The api returns a json array and it seems that the errors starts when the total size of the returned json objects (i.e. considering the number of requests by the size of the single response payload) exceeds a certain limit. This assumptions is due to the fact that, when stressing the very same api executing the very same code, with the only modification of returning an empty array instead of the calculated json object the test runs smoothly and no errors whatsoever show up. I am not very expert with the IIS and kestrel internals, so do you think that what I am saying makes sense? What is the parameter I could modify, apart from scaling up the servers?

[Tratcher]

It sounds like that throughput error is a symptom of your application having higher layer performance issues. If it can't handle 100 r/m then there is a significant bottleneck in the design. What to check next:

• How large is the response when you start having that problem? It's possible you are saturating your network bandwidth, though this should require responses in the GB range.
• Is the response very computationally expensive to generate? A profiler would be able to show you this. If your application is overtaxing the CPU then other parts of the system may start to fail. Making the generation more efficient or scaling up the application are your options here.
• Another version of this is that you may be generating and serializing the response inefficiently with regards to blocking threads. This can cause a lot of problems for other parts of the application trying to use the thread pool. If you attach a debugger and break then you would see a lot of threads blocked on wait handles.