Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

EntityFramework Core 3.1.0 uses synchronous API calls when using async APIs #21818

Closed
martinmine opened this issue Jul 28, 2020 · 11 comments
Closed

Comments

@martinmine
Copy link

I just switched from synchronous API to asynchronous API in EntityFramework and I could see a tremendous increase in CPU usage and response times on my service during a load test. Looking at memory dumps I have taken during high load, I can see that the following statement calls Storage.RelationalTransaction.Commit() from Update.Internal.BatchExecutor.ExecuteAsync: https://github.com/dotnet/efcore/blob/v3.1.0/src/EFCore.Relational/Update/Internal/BatchExecutor.cs#L145

 	[Managed to Native Transition]	
>	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParserStateObjectNative.ReadSyncOverAsync(int timeoutRemaining, out uint error)	Unknown
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()	Unknown
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()	Unknown
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()	Unknown
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(out byte value)	Unknown
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParser.TryRun(Microsoft.Data.SqlClient.RunBehavior runBehavior, Microsoft.Data.SqlClient.SqlCommand cmdHandler, Microsoft.Data.SqlClient.SqlDataReader dataStream, Microsoft.Data.SqlClient.BulkCopySimpleResultSet bulkCopyHandler, Microsoft.Data.SqlClient.TdsParserStateObject stateObj, out bool dataReady)	Unknown
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParser.Run(Microsoft.Data.SqlClient.RunBehavior runBehavior, Microsoft.Data.SqlClient.SqlCommand cmdHandler, Microsoft.Data.SqlClient.SqlDataReader dataStream, Microsoft.Data.SqlClient.BulkCopySimpleResultSet bulkCopyHandler, Microsoft.Data.SqlClient.TdsParserStateObject stateObj)	Unknown
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(byte[] buffer, Microsoft.Data.SqlClient.TdsEnums.TransactionManagerRequestType request, string transactionName, Microsoft.Data.SqlClient.TdsEnums.TransactionManagerIsolationLevel isoLevel, int timeout, Microsoft.Data.SqlClient.SqlInternalTransaction transaction, Microsoft.Data.SqlClient.TdsParserStateObject stateObj, bool isDelegateControlRequest)	Unknown
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(Microsoft.Data.SqlClient.SqlInternalConnection.TransactionRequest transactionRequest, string transactionName, System.Data.IsolationLevel iso, Microsoft.Data.SqlClient.SqlInternalTransaction internalTransaction, bool isDelegateControlRequest)	Unknown
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.SqlInternalTransaction.Commit()	Unknown
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.SqlTransaction.Commit()	Unknown
 	Microsoft.EntityFrameworkCore.Relational.dll!Microsoft.EntityFrameworkCore.Storage.RelationalTransaction.Commit() Line 104	C#
 	Microsoft.EntityFrameworkCore.Relational.dll!Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(System.Collections.Generic.IEnumerable<Microsoft.EntityFrameworkCore.Update.ModificationCommandBatch> commandBatches, Microsoft.EntityFrameworkCore.Storage.IRelationalConnection connection, System.Threading.CancellationToken cancellationToken) Line 145	C#
 	[Resuming Async Method]	
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 172	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<int>.AsyncStateMachineBox<Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.<ExecuteAsync>d__8>.MoveNext(System.Threading.Thread threadPoolThread) Line 617	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox box, bool allowInlining) Line 794	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 3320	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task<System.Threading.Tasks.VoidTaskResult>.TrySetResult(System.Threading.Tasks.VoidTaskResult result) Line 419	C#
 	Microsoft.EntityFrameworkCore.Relational.dll!Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(Microsoft.EntityFrameworkCore.Storage.IRelationalConnection connection, System.Threading.CancellationToken cancellationToken) Line 296	C#
 	Microsoft.EntityFrameworkCore.Relational.dll!Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(Microsoft.EntityFrameworkCore.Storage.IRelationalConnection connection, System.Threading.CancellationToken cancellationToken) Line 296	C#
 	[Resuming Async Method]	
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 172	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Threading.Tasks.VoidTaskResult>.AsyncStateMachineBox<Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.<ExecuteAsync>d__29>.MoveNext(System.Threading.Thread threadPoolThread) Line 617	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox box, bool allowInlining) Line 794	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 3320	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task<System.__Canon>.TrySetResult(System.__Canon result) Line 419	C#
 	Microsoft.EntityFrameworkCore.Relational.dll!Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(Microsoft.EntityFrameworkCore.Storage.RelationalCommandParameterObject parameterObject, System.Threading.CancellationToken cancellationToken) Line 560	C#
 	Microsoft.EntityFrameworkCore.Relational.dll!Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(Microsoft.EntityFrameworkCore.Storage.RelationalCommandParameterObject parameterObject, System.Threading.CancellationToken cancellationToken) Line 560	C#
 	[Resuming Async Method]	
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 172	C#
 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder<Microsoft.EntityFrameworkCore.Storage.RelationalDataReader>.AsyncStateMachineBox<Microsoft.EntityFrameworkCore.Storage.RelationalCommand.<ExecuteReaderAsync>d__17>.MoveNext(System.Threading.Thread threadPoolThread) Line 617	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox box, bool allowInlining) Line 794	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 3320	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.FinishSlow(bool userDelegateExecute) Line 2049	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.ExecuteWithThreadLocal(ref System.Threading.Tasks.Task currentTaskSlot, System.Threading.Thread threadPoolThread) Line 2402	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.ThreadPoolTaskScheduler.TryExecuteTaskInline(System.Threading.Tasks.Task task, bool taskWasPreviouslyQueued) Line 77	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.TaskScheduler.TryRunInline(System.Threading.Tasks.Task task, bool taskWasPreviouslyQueued) Line 201	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.TaskContinuation.InlineIfPossibleOrElseQueue(System.Threading.Tasks.Task task, bool needsProtection) Line 236	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 3332	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task<System.__Canon>.TrySetResult(System.__Canon result) Line 419	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.UnwrapPromise<Microsoft.Data.SqlClient.SqlDataReader>.TrySetFromTask(System.Threading.Tasks.Task task, bool lookForOce) Line 6697	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.UnwrapPromise<System.__Canon>.ProcessInnerTask(System.Threading.Tasks.Task task) Line 6721	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.RunContinuations(object continuationObject) Line 3338	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.FinishSlow(bool userDelegateExecute) Line 2049	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.ExecuteWithThreadLocal(ref System.Threading.Tasks.Task currentTaskSlot, System.Threading.Thread threadPoolThread) Line 2402	C#
 	System.Private.CoreLib.dll!System.Threading.ThreadPoolWorkQueue.Dispatch() Line 663	C#
 	[Async Call Stack]	
 	[External Code]	

It seems to me that this is a synchronous API-call, while it should be calling .CommitAsync in this case. It is however been fixed by a later commit here: 1e977ae#diff-c5e724774bdd22fa0e9f3c2143e74d1b

This is not backported to 3.x of EF-Core but seems to be target for 5.0. How come it calls the synchronous API under the hood? Is there any reason for this and could we possibly backport the fix to 3.x?

Steps to reproduce

Call Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(Microsoft.EntityFrameworkCore.Storage.RelationalCommandParameterObject parameterObject, System.Threading.CancellationToken cancellationToken) that will produce similar stack trace to the one above.

Further technical details

EF Core version: v3.1.0
Database provider: Microsoft.EntityFrameworkCore.SqlServer
Target framework: .NET Core 3.1
Operating system: Windows Server 2012 R2
Relates to this issue in IdentityServer4: IdentityServer/IdentityServer4#4672

@roji
Copy link
Member

roji commented Jul 28, 2020

This was indeed fixed for 5.0 in #20694 (by the commit mentioned above), so this issue is asking to backport that to 3.1.

However, @martinmine, I'm not sure how a switch from async to sync APIs could cause a dramatic increase in CPU usage - in 3.1 both ultimately call into the same synchronous DbTransaction.Commit... In other words, you're indeed not expected to get any benefit from using async API (because it's actually async-over-sync, rather than async all the way), but you're definitely not supposed to see a meaningful regression either.

Could you please carefully check on that and report back?

@martinmine
Copy link
Author

Thanks for such a quick response @roji!

In my case, I have my .NET Core app running on two application servers towards one SQL Server. And the SQL Server is at times acting slow. The impact on the slow SQL server resulted in some cases unstable response times up to 2-3 seconds, compared to having a stable 45ms response time with using synchronous APIs in EF. With the async API I can see that bursts of traffic can suddenly go through my service with first a large spike in response time that then steadily declines over time including my service suddenly consuming up to 60% CPU on both machines.

If the underlying APIs are synchronous, this behavior would be expected and I am experiencing symptoms of thread pool starvation:
Let's say my database would do a failover and halt processing queries for around 30 seconds. Since my application use async whenever possible, the steady flow of incoming HTTP requests to my application would rapidly drain my thread pool as due to its async nature, each thread would end up waiting for the result of the blocking API call DbTransaction.Commit() (or whatever blocking call that involves the SQL server). Once the database has finally recovered from the failover and starts returning data to me, the thread pool is empty and there is no available thread to do further processing and send the final response to those sending the HTTP requests. My application is then experiencing thread pool starvation.
Using synchronous APIs, I am not experiencing this issue as then my application would wait for the response from the SQL server before continuing processing the next incoming HTTP request. Even though this is inefficient in terms of utilizing resources, it does not eat up my thread pool at the same rate as using the async APIs in EF if the database is acting up.

How come EF does not use the asynchronous APIs?

@roji
Copy link
Member

roji commented Jul 29, 2020

@martinmine your analysis sounds correct to me... If indeed you're executing sync operations from TP threads, and those operations block for a long time (because of failovers), that could indeed cause TP starvation as you describe.

How come EF does not use the asynchronous APIs?

For transaction management (e.g. commit), the async System.Data APIs have only recently been added, in .NET Core 3.0 (dotnet/runtime#28596), which is why EF Core 3.1 doesn't yet use them. Note that EF Core 5.0 (currently in development) already does use them - as you found above. Note also that SqlClient itself hasn't yet implemented the async transaction APIs (dotnet/SqlClient#113), which I hope they do soon.

So at the end of the day, this is a somewhat new API that is still propagating throughout the various components in the ecosystem...

@martinmine
Copy link
Author

I see. I have also narrowed down my problem to the following lines of code:

public override async Task<Client> FindClientByIdAsync(string clientId)
{
    var baseQuery = Context.Clients.Where(x => x.ClientId == clientId);

    var client = await baseQuery.FirstOrDefaultAsync();

    await baseQuery.SelectMany(x => x.AllowedCorsOrigins).LoadAsync();
    await baseQuery.SelectMany(x => x.AllowedGrantTypes).LoadAsync();
    await baseQuery.SelectMany(x => x.AllowedScopes).LoadAsync();
    await baseQuery.SelectMany(x => x.Claims).LoadAsync();
    await baseQuery.SelectMany(x => x.ClientSecrets).LoadAsync();
    await baseQuery.SelectMany(x => x.IdentityProviderRestrictions).LoadAsync();
    await baseQuery.SelectMany(x => x.PostLogoutRedirectUris).LoadAsync();
    await baseQuery.SelectMany(x => x.Properties).LoadAsync();
    await baseQuery.SelectMany(x => x.RedirectUris).LoadAsync();

    return client.ToModel();
}

So in my case, the more awaitable tasks I have that requires to be done for each request, the more threads it will require for my request to get processed.

So if I understand you correctly, you wouldn't recommend the usage of async with Microsoft.Data.SqlClient until proper async has been implemented in it?

@roji
Copy link
Member

roji commented Jul 29, 2020

So in my case, the more awaitable tasks I have that requires to be done for each request, the more threads it will require for my request to get processed.

Not necessarily - the code above only has one query running at any point, so the thread gets released when completing each LoadAsync before going on to the next.

Importantly, I also don't see any transactions in this code: EF Core 3.1 does call async underlying APIs, transaction management is the exception (again, because those APIs were only recently added).

So if I understand you correctly, you wouldn't recommend the usage of async with Microsoft.Data.SqlClient until proper async has been implemented in it?

I wouldn't necessary say that. Again, keep in mind that the problem we're discussing is limited to transaction management; other operations should be async. You can specifically concentrate on code sites where transactions are being managed, and see how to work around the problem, e.g. by not executing that code on TP threads, or by having enough TP threads available up-front to support your load.

I agree this is an unfortunate situation - ideally all components here would support async properly, but we're not quite there yet...

@martinmine
Copy link
Author

I understand. Do you have any suggestions why the query I run performs so poorly in that case? Would it be what I experience is the overhead of async? (It is however the artifact of a workaround that was proposed in this sage: #18022)

@roji
Copy link
Member

roji commented Jul 29, 2020

@martinmine it's difficult to know without seeing some code - if you can put together a minimal repro for me to look at, I can investigate further.

If you really do suspect that BeginTransaction/Commit/Rollback specifically hang for long periods of time (you can probably verify this using SqlClient's DiagnosticSource support, or your own logging), and you know they are executing from TP threads, then indeed this could be the source of TP starvation and extremely poor perf (you should be able to diagnose TP starvation from dotnet counters or similar). I'd first make sure I understand exactly where the slowdown is coming from, using these diagnostic tools, to rule out that this is something unrelated.

@ErikEJ
Copy link
Contributor

ErikEJ commented Jul 29, 2020

Why are you not simply using Includes?

@roji
Copy link
Member

roji commented Jul 29, 2020

@ErikEJ I suspect this is to avoid the cartesian explosion that occurs with single query related entity loading. This is the workaround we proposed in #18022 to do split querying.

@martinmine
Copy link
Author

It is true that I am using this pattern to avoid the cartesian explosion, otherwise I would have used Includes as @ErikEJ suggests.
I've managed to strip down my application to a very tiny app with instructions on how to provoke the performance difference: https://github.com/martinmine/EFCoreAsyncBenchmark

@ajcvickers
Copy link
Member

Closing as there is nothing actionable on EF Core and the SqlClient issue is tracked in their repo.

@ajcvickers ajcvickers reopened this Oct 16, 2022
@ajcvickers ajcvickers closed this as not planned Won't fix, can't repro, duplicate, stale Oct 16, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants