Problem using transactions on sql server

[KorpEduardoSikora]

Description

I'm experiencing an issue with my Unit Of Work transactions and batch operations.
The error is occurring in the following scenario:

The code

1.  using (_unitOfWork.Begin()) // This starts the transaction on Db contexts
2.  {
3.      await _licenseUsageInRealTime
4.                .DeleteAsync(e => e.TenantId == input.TenantId && e.User != null &&  input.SoftwareUtilized.Contains(e.SoftwareIdentifier)); 
5.                // This is my extension that basically applies the .Where() and call the batch .DeleteAsync()  
6.        
7.        foreach (var licenseUsage in licenseUsagesToInsert)
8.            await _licenseUsageInRealTime.InsertAsync(licenseUsage);
9.    
10.     await _unitOfWork.CompleteAsync();
11.  } // When disposed, the transaction is rolled back (if it was not previously completed) 
12.    // and the connection with sql server is closed.

The code above works perfectly... and it is called multiple times a minute, and could be invoked in parallel by multiple customers...

The problem

So... the "perfectly" is not always perfect...
The problem I'm facing and that I've been trying to fix for days happens when:

1. Some request comes and the method above is invoked
2. The transaction is initialized on line 1
3. The BatchDelete is invoked on the line 4
4. Somehow it seems like the code is stuck right on the batch delete command. (so the transaction stays active)
5. Then a new request comes in and the method above is invoked again.
6. A new transaction is initialized on line 1
7. When the BatchDelete is invoked again on the line 4, it is never executed because the first transaction is still active, then after 30 seconds the SQL Timeout exception is thrown.

Somehow the first operation gets stuck on line 4, so the transaction is completed and the dispose method of the "Using" is never invoked and the transactions does not get rolled back. The Sql never throws a time out exception for the first request, only the following ones.

PS: The transaction is "lazy-applied", this means it is only applied when the DBContext is used / when a query to the database is invoked.

Exception

Here is the stack trace from the thrown exception:

2020-01-22T19:36:43.767282278Z Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.,
2020-01-22T19:36:43.767296303Z  ---> System.ComponentModel.Win32Exception (258): Unknown error 258,
2020-01-22T19:36:43.767301916Z    at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction),
2020-01-22T19:36:43.767306395Z    at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose),
2020-01-22T19:36:43.767310773Z    at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady),
2020-01-22T19:36:43.767315532Z    at Microsoft.Data.SqlClient.SqlDataReader.TryConsumeMetaData(),
2020-01-22T19:36:43.767319823Z    at Microsoft.Data.SqlClient.SqlDataReader.get_MetaData(),
2020-01-22T19:36:43.767324060Z    at Microsoft.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted),
2020-01-22T19:36:43.767328600Z    at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean isAsync, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest),
2020-01-22T19:36:43.767333287Z    at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry, String method),
2020-01-22T19:36:43.767338045Z    at Microsoft.Data.SqlClient.SqlCommand.ExecuteScalar(),
2020-01-22T19:36:43.767342169Z    at Z.EntityFramework.Extensions.BatchDelete.Execute[T](IQueryable`1 query),
2020-01-22T19:36:43.767346220Z    at System.Threading.Tasks.Task`1.InnerInvoke(),
2020-01-22T19:36:43.767350616Z    at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state),
2020-01-22T19:36:43.767363604Z --- End of stack trace from previous location where exception was thrown ---,
2020-01-22T19:36:43.767368124Z    at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread),
2020-01-22T19:36:43.767372237Z --- End of stack trace from previous location where exception was thrown ---,
2020-01-22T19:36:43.767376376Z    at Viasoft.Core.EntityFrameworkCore.Extensions.BatchExtensions.EntityFrameworkCoreBatchExtensions.BatchHardDeleteAsync[TEntity](IRepository`1 repository, Expression`1 predicate),
2020-01-22T19:36:43.767380769Z    at Viasoft.Licensing.CustomerLicensing.Domain.Services.LicenseUsageInRealTime.LicenseUsageInRealTimeService.ImportLicenseUsage(LicenseUsageInRealTimeImportInput input) in /home/jenkins/agent/workspace/.CustomerLicensing_release_1.0.x/Viasoft.Licensing.CustomerLicensing.Domain/Services/LicenseUsageInRealTime/LicenseUsageInRealTimeService.cs:line 62,
2020-01-22T19:36:43.767385451Z ClientConnectionId:f65a237b-a441-4d77-87f6-8fea07caadfc,
2020-01-22T19:36:43.767389518Z Error Number:-2,State:0,Class:11,
2020-01-22T19:36:43.768324426Z fail: Microsoft.AspNetCore.Server.Kestrel[13],
2020-01-22T19:36:43.768336602Z       Connection id "0HLSV88EPHLUM", Request id "0HLSV88EPHLUM:00000002": An unhandled exception was thrown by the application.,
2020-01-22T19:36:43.768416105Z Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.,
2020-01-22T19:36:43.768429420Z  ---> System.ComponentModel.Win32Exception (258): Unknown error 258,
2020-01-22T19:36:43.768434780Z    at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction),
2020-01-22T19:36:43.768439250Z    at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose),
2020-01-22T19:36:43.768455728Z    at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady),
2020-01-22T19:36:43.768474499Z    at Microsoft.Data.SqlClient.SqlDataReader.TryConsumeMetaData(),
2020-01-22T19:36:43.768555229Z    at Microsoft.Data.SqlClient.SqlDataReader.get_MetaData(),
2020-01-22T19:36:43.768625588Z    at Microsoft.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted),
2020-01-22T19:36:43.768709530Z    at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean isAsync, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest),
2020-01-22T19:36:43.768719733Z    at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry, String method),
2020-01-22T19:36:43.768731178Z    at Microsoft.Data.SqlClient.SqlCommand.ExecuteScalar(),
2020-01-22T19:36:43.768735747Z    at Z.EntityFramework.Extensions.BatchDelete.Execute[T](IQueryable`1 query),
2020-01-22T19:36:43.768739866Z    at System.Threading.Tasks.Task`1.InnerInvoke(),
2020-01-22T19:36:43.768768319Z    at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state),
2020-01-22T19:36:43.768778724Z --- End of stack trace from previous location where exception was thrown ---,
2020-01-22T19:36:43.768887916Z    at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread),
2020-01-22T19:36:43.768898926Z --- End of stack trace from previous location where exception was thrown ---,
2020-01-22T19:36:43.768903201Z    at Viasoft.Core.EntityFrameworkCore.Extensions.BatchExtensions.EntityFrameworkCoreBatchExtensions.BatchHardDeleteAsync[TEntity](IRepository`1 repository, Expression`1 predicate),
2020-01-22T19:36:43.768945758Z    at Viasoft.Licensing.CustomerLicensing.Domain.Services.LicenseUsageInRealTime.LicenseUsageInRealTimeService.ImportLicenseUsage(LicenseUsageInRealTimeImportInput input) in /home/jenkins/agent/workspace/.CustomerLicensing_release_1.0.x/Viasoft.Licensing.CustomerLicensing.Domain/Services/LicenseUsageInRealTime/LicenseUsageInRealTimeService.cs:line 62,
2020-01-22T19:36:43.769055088Z    at Viasoft.Licensing.CustomerLicensing.Host.Controllers.LicenseUsageInRealTimeController.Import(LicenseUsageInRealTimeImportInput input) in /home/jenkins/agent/workspace/.CustomerLicensing_release_1.0.x/Viasoft.Licensing.CustomerLicensing.Host/Controllers/LicenseUsageInRealTimeController.cs:line 33,
2020-01-22T19:36:43.769065315Z    at lambda_method(Closure , Object ),
2020-01-22T19:36:43.769069635Z    at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.AwaitableObjectResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments),
2020-01-22T19:36:43.769113263Z    at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask),
2020-01-22T19:36:43.769221366Z    at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted),
2020-01-22T19:36:43.769231323Z    at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context),
2020-01-22T19:36:43.769235762Z    at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted),
2020-01-22T19:36:43.769289461Z    at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted),
2020-01-22T19:36:43.769358849Z    at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted),
2020-01-22T19:36:43.769373609Z    at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope),
2020-01-22T19:36:43.769387169Z    at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger),
2020-01-22T19:36:43.769391962Z    at Viasoft.Core.AspNetCore.UnitOfWork.UnitOfWorkControllerMiddleware.Invoke(HttpContext httpContext, IUnitOfWork unitOfWork),
2020-01-22T19:36:43.769451437Z    at Viasoft.Core.AspNetCore.Provisioning.ProvisioningMiddleware.Invoke(HttpContext httpContext, IAsyncStartupTaskMediator asyncStartupTaskMediator),
2020-01-22T19:36:43.769458552Z    at Viasoft.Core.AspNetCore.AmbientData.AmbientDataMiddleware.Invoke(HttpContext httpContext, IAmbientDataResolver ambientDataResolver),
2020-01-22T19:36:43.769494466Z    at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext),
2020-01-22T19:36:43.769504329Z    at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider),
2020-01-22T19:36:43.769591021Z    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application),
2020-01-22T19:36:43.769600666Z ClientConnectionId:f65a237b-a441-4d77-87f6-8fea07caadfc,
2020-01-22T19:36:43.769604744Z Error Number:-2,State:0,Class:11,

Fiddle or Project

In the following days I'll try to create a simple app that reproduces this scenario.
The real problem is, this is only happening in a production environment. I could not reproduce this using two machines invoking 1000 requests each when debugging it.

Further technical details

• Dotnet core: 3.1.1
• EF Core version: 3.1.1
• EF Plus version: 3.0.32
• Database Provider: SQL Server

Any ideas on what might be happening?? I'll give more details if needed!!

Thanks in advance.

[JonathanMagnan]

Hello @KorpEduardoSikora ,

It seems to be a block/deadlock problem caused by the transaction.

Increasing the timeout could solve the problem, but that solution is bad since it will lead to even more issues in this case.

One possible solution would be to lock the table during the Delete operation.

For example:

ctx.Items.Delete(x => x.UseTableLock = true);

btw, a good idea to allow a predicate directly in the Delete method. We might add this as well ;)

Best Regards,

Jon

---

Performance Libraries
context.BulkInsert(list, options => options.BatchSize = 1000);
Entity Framework Extensions • Entity Framework Classic • Bulk Operations • Dapper Plus

Runtime Evaluation
Eval.Execute("x + y", new {x = 1, y = 2}); // return 3
C# Eval Function • SQL Eval Function

[KorpEduardoSikora]

Hello @JonathanMagnan

I tried the solution you suggested, and for almost a week it seemed to solved the problem.
But it started to happen again.. So now I'm back where I started >.<

I'm open for more suggestions, and if I find anything on my side I'll let you know..

Thanks!!

[JonathanMagnan]

Do your company have tools that can show you some blocking or deadlock issue on your SQL Server?

Our SQL might be the cause, but another one could be the cause as well which we need to better understand what's happening in your database when this issue occurs.

[kewinbrand]

Hey @JonathanMagnan ,

Turns out that the problem was with Microsoft.Data.SqlClient. They introduced a bug with their new package and was fixed in 1.1.1. See dotnet/SqlClient#262.

After I upgraded to 1.1.1 all problems gone away.

Thank you