Request not being aborted after closing the connection is causing high CPU

[arekpalinski]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

We experience an issue with unresponsiveness of RavenDB server (https://github.com/ravendb/ravendb) after a set of certain operations is cancelled. The operations in question are the streaming of query results (https://ravendb.net/docs/article-page/5.4/csharp/client-api/session/querying/how-to-stream-query-results).

The client application is creating 100 tasks and each of them is getting 2M records from a database. Under the covers each creates an HTTP request. The server handles the requests in a streaming manner and writes the results to HttpContext.Response.

The relevant server side code is here:
https://github.com/ravendb/ravendb/blob/917bbe60b099cd710de1f04cd27be8442251f790/src/Raven.Server/Documents/Handlers/Streaming/StreamingHandler.cs#L227-L267

Kestrel configuration:
https://github.com/ravendb/ravendb/blob/917bbe60b099cd710de1f04cd27be8442251f790/src/Raven.Server/RavenServer.cs#L185

When the streaming queries are handled have the following utilization:

• ~100 of connections ("18384" is pid of Raven.Server process):

C:\Users\arek>netstat -ano | find /c "18384"
112

• The CPU is 20% - 60% on my end (it's 12-core machine, 32GB of memory)

• It's ~9GB of managed memory

ravendb> stats
Showing stats, press any key to close...
    working set     | native mem      | managed mem     | mmap size          
 *  10.57 GBytes    | 29 MBytes       | 9.29 GBytes     | 4.54 GBytes

The issue

The issue is happening once the client app is closed, Then we have very high CPU and memory usage is increasing. The server becomes unresponsive. After attaching the debugger we can see that the query results are still being written to the response (the underling stream is Microsoft.AspNetCore.ResponseCompression.ResponseCompressionBody) and all operations continue as usual. We have a cancellation token hooked up to HttpContext.RequestAborted but it's not cancelled:
https://github.com/ravendb/ravendb/blob/917bbe60b099cd710de1f04cd27be8442251f790/src/Raven.Server/Documents/DatabaseRequestHandler.cs#L140

• The number of connections drops immediately:

C:\Users\arek>netstat -ano | find /c "18384"
12

• CPU usage is over 90%

• The process started to consume additional 2GB of managed memory

ravendb> stats
Showing stats, press any key to close...
    working set     | native mem      | managed mem     | mmap size       
 *  12.64 GBytes    | 28.29 MBytes    | 11.45 GBytes    | 4.54 GBytes

After some time (once all streaming operations completes I believe) the CPU get back to normal.

Expected Behavior

• The cancellation token HttpContext.RequestAborted should be cancelled if the underlying connection no longer exists
• We expected to get some error on attempt to flush (we use default KestrelServerOptions.Limits.MaxResponseBufferSize which is 64KB) so we would stop the operation. Instead it appears to write to the memory so fast that it causes very high CPU usage.

Steps To Reproduce

• checkout branch https://github.com/arekpalinski/ravendb/tree/streaming-issue

• start Raven.Server project

• create a database named test

• go to the database and import below .ravendump file (https://ravendb.net/docs/article-page/5.4/csharp/studio/database/tasks/import-data/import-data-file):

  • file to import: https://drive.google.com/file/d/10pbv43kI6q9KM9xRC91ybfy5LctURv_X/view?usp=sharing

• run project Tryouts which will create the actual requests

• stop it by pressing q

We have reproduce it locally on Win11. But the same was experienced on WinServer2022 and Ubuntu 22.04.

Exceptions (if any)

No response

.NET Version

7.0.14

Anything else?

No response

[amcasey]

We have a cancellation token hooked up to HttpContext.RequestAborted but it's not cancelled

Can you tell whether the token indicates that cancellation has occurred? That is, whether the token is not updated or it's not consumed?

[amcasey]

Are you able to debug/profile to determine which code is executing between the disconnection and the release of resources?

Is this behavior new in 7.0? (e.g. were you using 6.0 successfully before?)

Are you able to test on 8.0?

Hi @arekpalinski. We have added the "Needs: Author Feedback" label to this issue, which indicates that we have an open question for you before we can take further action. This issue will be closed automatically in 7 days if we do not hear back from you by then - please feel free to re-open it if you come back to this issue after that time.

[arekpalinski]

Below is a sample stacktrace which shows that the query streaming operation is continuing its execution at the time when the connection no longer exists:

>	Sparrow.dll!Sparrow.Json.AsyncBlittableJsonTextWriter.FlushAsync(System.Threading.CancellationToken token) Line 55	C#
 	Raven.Server.dll!Raven.Server.Documents.Queries.StreamJsonDocumentQueryResultWriter.AddResultAsync(Raven.Server.Documents.Document res, System.Threading.CancellationToken token) Line 57	C#
 	Raven.Server.dll!Raven.Server.Documents.Queries.StreamDocumentQueryResult.AddResultAsync(Raven.Server.Documents.Document result, System.Threading.CancellationToken token) Line 20	C#
 	Raven.Server.dll!Raven.Server.Documents.Indexes.Index.QueryInternal<Raven.Server.Documents.Queries.StreamDocumentQueryResult>(Raven.Server.Documents.Queries.StreamDocumentQueryResult resultToFill, Raven.Server.Documents.Queries.IndexQueryServerSide query, Raven.Server.Documents.Indexes.QueryOperationContext queryContext, bool pulseDocsReadingTransaction, Raven.Server.ServerWide.OperationCancelToken token) Line 3324	C#
 	[Resuming Async Method]	
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 137	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Threading.Tasks.VoidTaskResult>.AsyncStateMachineBox<Raven.Server.Documents.Indexes.Index.<QueryInternal>d__243<Raven.Server.Documents.Queries.StreamDocumentQueryResult>>.MoveNext(System.Threading.Thread threadPoolThread) Line 133	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.TaskAwaiter.OutputWaitEtwEvents.AnonymousMethod__12_0(System.Action innerContinuation, System.Threading.Tasks.Task innerTask) Line 135	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action action, bool allowInlining) Line 162	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 2760	C#
 	Raven.Server.dll!Raven.Server.Documents.Queries.StreamDocumentQueryResult.AddResultAsync(Raven.Server.Documents.Document result, System.Threading.CancellationToken token) Line 25	C#
 	[Resuming Async Method]	
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 137	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Threading.Tasks.VoidTaskResult>.AsyncStateMachineBox<Raven.Server.Documents.Queries.StreamDocumentQueryResult.<AddResultAsync>d__1>.MoveNext(System.Threading.Thread threadPoolThread) Line 133	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.TaskAwaiter.OutputWaitEtwEvents.AnonymousMethod__12_0(System.Action innerContinuation, System.Threading.Tasks.Task innerTask) Line 135	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action action, bool allowInlining) Line 162	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 2760	C#
 	Raven.Server.dll!Raven.Server.Documents.Queries.StreamJsonDocumentQueryResultWriter.AddResultAsync(Raven.Server.Documents.Document res, System.Threading.CancellationToken token) Line 58	C#
 	[Resuming Async Method]	
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 137	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Threading.Tasks.VoidTaskResult>.AsyncStateMachineBox<Raven.Server.Documents.Queries.StreamJsonDocumentQueryResultWriter.<AddResultAsync>d__8>.MoveNext(System.Threading.Thread threadPoolThread) Line 133	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.TaskAwaiter.OutputWaitEtwEvents.AnonymousMethod__12_0(System.Action innerContinuation, System.Threading.Tasks.Task innerTask) Line 135	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action action, bool allowInlining) Line 162	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 2760	C#
 	Sparrow.dll!Sparrow.Json.AsyncBlittableJsonTextWriter.FlushAsync(System.Threading.CancellationToken token) Line 58	C#
 	[Resuming Async Method]	
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 137	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<int>.AsyncStateMachineBox<Sparrow.Json.AsyncBlittableJsonTextWriter.<FlushAsync>d__4>.MoveNext(System.Threading.Thread threadPoolThread) Line 133	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.TaskAwaiter.OutputWaitEtwEvents.AnonymousMethod__12_0(System.Action innerContinuation, System.Threading.Tasks.Task innerTask) Line 135	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action action, bool allowInlining) Line 162	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 2760	C#
 	Microsoft.AspNetCore.ResponseCompression.dll!Microsoft.AspNetCore.ResponseCompression.ResponseCompressionBody.WriteAsync(byte[] buffer, int offset, int count, System.Threading.CancellationToken cancellationToken)	Unknown
 	[Resuming Async Method]	
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 137	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Threading.Tasks.VoidTaskResult>.AsyncStateMachineBox<Microsoft.AspNetCore.ResponseCompression.ResponseCompressionBody.<WriteAsync>d__40>.MoveNext(System.Threading.Thread threadPoolThread) Line 133	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.TaskAwaiter.OutputWaitEtwEvents.AnonymousMethod__12_0(System.Action innerContinuation, System.Threading.Tasks.Task innerTask) Line 135	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action action, bool allowInlining) Line 162	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 2760	C#
 	Microsoft.AspNetCore.ResponseCompression.dll!Microsoft.AspNetCore.ResponseCompression.ResponseCompressionBody.WriteAsync(System.ReadOnlyMemory<byte> buffer, System.Threading.CancellationToken cancellationToken)	Unknown
 	[Resuming Async Method]	
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 137	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Threading.Tasks.VoidTaskResult>.AsyncStateMachineBox<Microsoft.AspNetCore.ResponseCompression.ResponseCompressionBody.<WriteAsync>d__41>.MoveNext(System.Threading.Thread threadPoolThread) Line 133	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.TaskAwaiter.OutputWaitEtwEvents.AnonymousMethod__12_0(System.Action innerContinuation, System.Threading.Tasks.Task innerTask) Line 135	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action action, bool allowInlining) Line 162	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 2760	C#
 	System.IO.Compression.dll!System.IO.Compression.DeflateStream.WriteAsyncMemory.__Core|65_0(System.ReadOnlyMemory<byte> buffer, System.Threading.CancellationToken cancellationToken)	Unknown
 	[Resuming Async Method]	
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 137	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Threading.Tasks.VoidTaskResult>.AsyncStateMachineBox<System.IO.Compression.DeflateStream.<<WriteAsyncMemory>g__Core|65_0>d>.MoveNext(System.Threading.Thread threadPoolThread) Line 133	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.TaskAwaiter.OutputWaitEtwEvents.AnonymousMethod__12_0(System.Action innerContinuation, System.Threading.Tasks.Task innerTask) Line 135	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action action, bool allowInlining) Line 162	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 2760	C#
 	System.IO.Compression.dll!System.IO.Compression.DeflateStream.WriteDeflaterOutputAsync(System.Threading.CancellationToken cancellationToken)	Unknown
 	[Resuming Async Method]	
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 137	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Threading.Tasks.VoidTaskResult>.AsyncStateMachineBox<System.IO.Compression.DeflateStream.<WriteDeflaterOutputAsync>d__66>.MoveNext(System.Threading.Thread threadPoolThread) Line 133	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.TaskAwaiter.OutputWaitEtwEvents.AnonymousMethod__12_0(System.Action innerContinuation, System.Threading.Tasks.Task innerTask) Line 135	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action action, bool allowInlining) Line 162	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 2760	C#
 	Microsoft.AspNetCore.Server.Kestrel.Core.dll!Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.PipeWriterHelpers.TimingPipeFlusher.TimeFlushAsyncAwaited(System.Threading.Tasks.ValueTask<System.IO.Pipelines.FlushResult> pipeFlushTask, Microsoft.AspNetCore.Server.Kestrel.Core.MinDataRate minRate, Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.IHttpOutputAborter outputAborter, System.Threading.CancellationToken cancellationToken)	Unknown
 	[Resuming Async Method]	
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 137	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.IO.Pipelines.FlushResult>.AsyncStateMachineBox<Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.PipeWriterHelpers.TimingPipeFlusher.<TimeFlushAsyncAwaited>d__9>.MoveNext(System.Threading.Thread threadPoolThread) Line 133	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.TaskAwaiter.OutputWaitEtwEvents.AnonymousMethod__12_0(System.Action innerContinuation, System.Threading.Tasks.Task innerTask) Line 135	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.System.Threading.IThreadPoolWorkItem.Execute() Line 94	C#
 	System.Private.CoreLib.dll!System.Threading.ThreadPoolWorkQueue.Dispatch() Line 692	C#
 	System.Private.CoreLib.dll!System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() Line 1177	C#
 	[Async Call Stack]	
 	[Async] Raven.Server.dll!Raven.Server.Documents.Indexes.Index.StreamQuery(Microsoft.AspNetCore.Http.HttpResponse response, Raven.Server.Documents.Queries.IStreamQueryResultWriter<Raven.Server.Documents.Document> writer, Raven.Server.Documents.Queries.IndexQueryServerSide query, Raven.Server.Documents.Indexes.QueryOperationContext queryContext, Raven.Server.ServerWide.OperationCancelToken token) Line 3099	C#
 	[Async] Raven.Server.dll!Raven.Server.Documents.Queries.StaticIndexQueryRunner.ExecuteStreamQuery(Raven.Server.Documents.Queries.IndexQueryServerSide query, Raven.Server.Documents.Indexes.QueryOperationContext queryContext, Microsoft.AspNetCore.Http.HttpResponse response, Raven.Server.Documents.Queries.IStreamQueryResultWriter<Raven.Server.Documents.Document> writer, Raven.Server.ServerWide.OperationCancelToken token) Line 51	C#
 	[Async] Raven.Server.dll!Raven.Server.Documents.Queries.QueryRunner.ExecuteStreamQuery(Raven.Server.Documents.Queries.IndexQueryServerSide query, Raven.Server.Documents.Indexes.QueryOperationContext queryContext, Microsoft.AspNetCore.Http.HttpResponse response, Raven.Server.Documents.Queries.IStreamQueryResultWriter<Raven.Server.Documents.Document> writer, Raven.Server.ServerWide.OperationCancelToken token) Line 119	C#
 	[Async] Raven.Server.dll!Raven.Server.Documents.Handlers.Streaming.StreamingHandler.StreamQueryPost() Line 287	C#
 	[Async] Raven.Server.dll!Raven.Server.Routing.RequestRouter.HandlePath(Raven.Server.Web.RequestHandlerContext reqCtx) Line 378	C#
 	[Async] Raven.Server.dll!Raven.Server.RavenServerStartup.RequestHandler(Microsoft.AspNetCore.Http.HttpContext context) Line 178	C#
 	[Async] Microsoft.AspNetCore.ResponseCompression.dll!Microsoft.AspNetCore.ResponseCompression.ResponseCompressionMiddleware.InvokeCore(Microsoft.AspNetCore.Http.HttpContext context)	Unknown
 	[Async] Microsoft.AspNetCore.Server.Kestrel.Core.dll!Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests<Microsoft.AspNetCore.Hosting.HostingApplication.Context>(Microsoft.AspNetCore.Hosting.Server.IHttpApplication<Microsoft.AspNetCore.Hosting.HostingApplication.Context> application)	Unknown
 	[Async] Microsoft.AspNetCore.Server.Kestrel.Core.dll!Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequestsAsync<Microsoft.AspNetCore.Hosting.HostingApplication.Context>(Microsoft.AspNetCore.Hosting.Server.IHttpApplication<Microsoft.AspNetCore.Hosting.HostingApplication.Context> application)	Unknown
 	[Async] Microsoft.AspNetCore.Server.Kestrel.Core.dll!Microsoft.AspNetCore.Server.Kestrel.Core.Internal.HttpConnection.ProcessRequestsAsync<Microsoft.AspNetCore.Hosting.HostingApplication.Context>(Microsoft.AspNetCore.Hosting.Server.IHttpApplication<Microsoft.AspNetCore.Hosting.HostingApplication.Context> httpApplication)	Unknown
 	[Async] Microsoft.AspNetCore.Server.Kestrel.Core.dll!Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.KestrelConnection<Microsoft.AspNetCore.Connections.ConnectionContext>.ExecuteAsync()	Unknown

Then we can chek in the debugger that the underlying HTTP context's RequestAborted token doesn't indicate the cancellation:

This is the first time we noticed an issue like that. I don't know if this is new dotnet 7.0 behavior.

[arekpalinski]

The same is experienced on .net 8.0:

We can even see with the usage of netstat that there is no connection for the port 57886:

[amcasey]

Thanks for the updates! I'll see if I can figure out exactly what triggers RequestAborted.

[amcasey]

This appears to be the relevant implementation of RequestAborted and this appears to be the method that triggers it (unless it's explicitly clobbered, which I assume it isn't in your case).

It might be interesting to put a breakpoint in CancelRequestAbortedToken to confirm that it's not being called. (I do appreciate that you provided repro steps, but setting up a DB server populated from an opaque binary blob is not something we'd generally do for an investigation.)

[amcasey]

Since you seem to have a convenient repro, I'd also be tempted to turn the logging for Microsoft.AspNetCore up to Debug to get some messages about connection lifetimes.

[arekpalinski]

I have repeated the repro with Microsoft.AspNetCore logging set up to Info. The below screenshot shows the moment after the app generating the query streaming requests has been closed:

In the logs we can see that all the requests completed with status 200. Please find attached the logs:
info-logs-2023-12-08.000.log

[arekpalinski]

Next, I repeated the same test with Debug log level. Please find attached the logs:
2023-12-08.000.log

[arekpalinski]

I do appreciate that you provided repro steps, but setting up a DB server populated from an opaque binary blob is not something we'd generally do for an investigation

The binary blob isn't necessary. I have attached it as it's easier to just import it to RavenDB. Although it's just a sample built-in data set that can be easily extended to be ~2M of documents.

You can achieve the same data set by doing:

1. Download RavenDB Server from https://ravendb.net/download (vesion 5.4 / 6.0 doesn't matter)
2. Open RavenDB Studio (http://localhost:8080) and create "test" database
3. Go to "test" database and create "Sample data":
   
4. Go to "Documents" -> "Patch" and execute the following script which will create more "Orders" documents:

from "Orders" update {
    for (var i = 0; i < 20; i++)
    {
        put("orders/", this)
    }
}

Execute it a few times until you have ~2M of Orders documents