Entity Framework Core: SqlException with "Execution Timeout Expired" despite setting highe-CodePudding

I have rather simple code, like this:

private void Insert(IList<T> data)
{
    using (MyDbContext dbContext = MyDbContextFactory.CreateDbContext())
    {
        dbContext.AddRange(data);
        dbContext.SaveChanges();
    }
}

This mostly works, but from time to time (though I'm only trying to insert 50 rows... even though they may contain slightly larger BLOBs), it fails with a stacktrace like this:

Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.

System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out

at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction) in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlInternalConnection.cs:line 820  
at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParser.cs:line 1572  
at Microsoft.Data.SqlClient.TdsParserStateObject.ThrowExceptionAndWarning(Boolean callerHasConnectionLock, Boolean asyncClose) in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParserStateObject.cs:line 1070  
at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error) in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParserStateObject.cs:line 2744  
at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync() in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParserStateObject.cs:line 2258  
at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket() in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParserStateObject.cs:line 2182  
at Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer() in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParserStateObject.cs:line 1222  
at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte& value) in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParserStateObject.cs:line 1450  
at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParser.cs:line 2190  
at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj) in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParser.cs:line 2088  
at Microsoft.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParserStateObject stateObj, Boolean isDelegateControlRequest) in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParser.cs:line 9384  
at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String transactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest) in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlInternalConnectionTds.cs:line 1311  
at Microsoft.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransaction(TransactionRequest transactionRequest, String name, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest) in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlInternalConnectionTds.cs:line 1091  
at Microsoft.Data.SqlClient.SqlInternalTransaction.Commit() in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\sqlinternaltransaction.cs:line 344  
at Microsoft.Data.SqlClient.SqlTransaction.Commit() in E:\SqlClientInternal\agent-1\_work\5\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlTransaction.cs:line 202  
at Microsoft.EntityFrameworkCore.Storage.RelationalTransaction.Commit()  
at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.Execute(IEnumerable`1 commandBatches, IRelationalConnection connection)  
at Microsoft.EntityFrameworkCore.Storage.RelationalDatabase.SaveChanges(IList`1 entries)  
at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(IList`1 entriesToSave)  
at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(DbContext _, Boolean acceptAllChangesOnSuccess)  
at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)  
at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(Boolean acceptAllChangesOnSuccess)  
at Microsoft.EntityFrameworkCore.DbContext.SaveChanges(Boolean acceptAllChangesOnSuccess)  
at Microsoft.EntityFrameworkCore.DbContext.SaveChanges()

This is using .NET 4.8 with Entity Framework Core 3.1.5.

We also use EFCore.BulkExtensions 3.1.1 in this project, but that code seems to be running fine.

To solve the issue, I have increased the timeout, like this:

static class MyDbContextFactory
{
    public static MyDbContext CreateDbContext()
    {
        Action<SqlServerDbContextOptionsBuilder> setDbCommandTimeout = null;
        int? dbCommandTimeout = GlobalConfiguration.DbCommandTimeout;

        if (dbCommandTimeout.HasValue)
        {
            setDbCommandTimeout = (opts => opts.CommandTimeout(dbCommandTimeout.Value));
        }

        DbContextOptions<MyDbContext> options = new DbContextOptionsBuilder<MyDbContext>()
                                                            .UseSqlServer(GlobalConfiguration.GetConnectionString(), setDbCommandTimeout)
                                                            .Options;

        return new MyDbContext(options);
    }
}

And also:

sealed class MyDbContext : DbContext
{
    public MyDbContext(DbContextOptions<SharePointExportContext> options) : base(options)
    {
    }

    // [...]
}

Even with the timeout is configured as 1200 (20 minutes), it still fails, sometimes after as little as 90 seconds or so.

Any idea what could be causing this or how I could debug it?

I'm suspecting it's actually not related to the timeout, but rather that there is some sort of deadlock or so that leads to the transaction being cancelled.

The server is running SQL Server 2016 (v13.0.4001.0).

I have even tried deleting and recreating the database, to no avail.

CodePudding user response：

I was unaware that I was running ancient versions of Microsoft.Data.SqlClient (1.1.1) and Microsoft.Data.SqlClient.SNI (1.1.0).

Upgrading Microsoft.Data.SqlClient to 4.1.0 and Microsoft.Data.SqlClient.SNI to 4.0.0 solved the problem.