We are experiencing timeout exceptions with EF Core.
We have some queries that are working and some that are not. We are making use of Azure Container apps with an on-premise SQL Server.
Code: this is the query we are executing, it's one of the queries that are not working:
IQueryable<Disbursement> response = _dataContext.Disbursements
.Where(w => w.DisbursementDate <= disbursementDate && !w.DeletedFlag && !w.Paid && w.MethodId == methodId && w.AccountId == accountId)
.OrderByDescending(o => o.CreatedOnDateUtc);
var result = response.Skip((page - 1) * pageSize)
.Take(pageSize)
.ToList();
Here is an example of a working query
IQueryable<AccountBillingModel> response = _dataContext.Disbursements.Where(w => w.DisbursementDate <= disbursementDate && !w.DeletedFlag && !w.Paid && w.MethodId == methodId)
.Select(s => s.AccountId)
.Distinct()
.Select(s => new AccountBillingModel
{
AccountId = s
});
return await response.ToListAsync();
Here is the model
public class Disbursement
{
public Guid Id { get; set; }
public Guid TransactionId { get; set; }
public Guid AccountId { get; set; }
public Guid MethodId { get; set; }
public string ExternalItemId { get; set; } = string.Empty;
public string Description { get; set; } = string.Empty;
public int Quantity { get; set; }
public double PriceExcluding { get; set; }
public bool Paid { get; set; }
public DateTime DisbursementDate { get; set; }
public DateTime? DisbursementRunDate { get; set; }
public DateTime? AmendedOnDateUtc { get; set; }
public bool DeletedFlag { get; set; } = false;
public DateTime CreatedOnDateUtc { get; set; } = DateTime.UtcNow;
}
DbContext:
public class DataContext : DbContext
{
public DataContext(DbContextOptions options) : base(options) { }
public DbSet<Disbursement> Disbursements { get; set; }
}
If we run this code locally on our machines using docker it works.
We have tried.
Entity Framework Core 8
Entity Framework Core 6
.NET Core 6
.NET Core 8
We have even tried changing the async calls such as ToListAsync() to normal ToList() with no success
What we have seen is if we make the model smaller, ie removing some of the columns the query works, basically like the second query that always works is only selecting one column.
Once we reach around 10 columns we start experiencing the timeouts. We see the same when we leave the model as is but only specify 10 columns as part of a Select()
Table definition:
CREATE TABLE [dbo].[Disbursements]
(
[Id] UNIQUEIDENTIFIER CONSTRAINT [DF_Disbursements_Id] DEFAULT (newid()) NOT NULL,
[AccountId] UNIQUEIDENTIFIER NOT NULL,
[MethodId] UNIQUEIDENTIFIER NOT NULL,
[ExternalItemId] NVARCHAR(50) NOT NULL,
[Description] NVARCHAR(150) NOT NULL,
[Quantity] INT NOT NULL,
[PriceExcluding] FLOAT (53) NOT NULL,
[DisbursementDate] DATETIME NOT NULL,
[Paid] BIT CONSTRAINT [DF_Disbursements_Paid] DEFAULT ((0)) NOT NULL,
[AmendedOnDateUtc] DATETIME NULL,
[CreatedOnDateUtc] DATETIME NOT NULL,
[DeletedFlag] BIT CONSTRAINT [DF_Disbursements_DeletedFlag] DEFAULT ((0)) NOT NULL,
[DisbursementRunDate] DATETIME NULL,
CONSTRAINT [PK_Disbursements] PRIMARY KEY CLUSTERED ([Id] ASC)
);
Stacktrace
An exception occurred while iterating over the results of a query for context type \u0027****\u0027.\nMicrosoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.\n ---\u003E System.ComponentModel.Win32Exception (258): Unknown error 258\n
at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action\u00601 wrapCloseInAction)\n
at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)\n
at Microsoft.Data.SqlClient.TdsParserStateObject.ThrowExceptionAndWarning(Boolean callerHasConnectionLock, Boolean asyncClose)\n
at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)\n
at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()\n
at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()\n
at Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()\n
at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte\u0026 value)\n
at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean\u0026 dataReady)\n
at Microsoft.Data.SqlClient.SqlDataReader.TryConsumeMetaData()\n
at Microsoft.Data.SqlClient.SqlDataReader.get_MetaData()\n
at Microsoft.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)\n
at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean isAsync, Int32 timeout, Task\u0026 task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)\n
at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, TaskCompletionSource\u00601 completion, Int32 timeout, Task\u0026 task, Boolean\u0026 usedCache, Boolean asyncWrite, Boolean inRetry, String method)\n
at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)\n
at Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior)\n
at Microsoft.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)\n
at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReader(RelationalCommandParameterObject parameterObject)\n
at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable\u00601.Enumerator.InitializeReader(Enumerator enumerator)\n
at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable\u00601.Enumerator.\u003C\u003Ec.\u003CMoveNext\u003Eb__19_0(DbContext _, Enumerator enumerator)\n
at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func\u00603 operation, Func\u00603 verifySucceeded)\n
at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable\u00601.Enumerator.MoveNext()\nClientConnectionId:038757a9-2247-477d-98c5-31eacfa8d39d\nError Number:-2,State:0,Class:11",
"Exception": "Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.\n ---\u003E System.ComponentModel.Win32Exception (258): Unknown error 258\n
at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action\u00601 wrapCloseInAction)\n
at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)\n
at Microsoft.Data.SqlClient.TdsParserStateObject.ThrowExceptionAndWarning(Boolean callerHasConnectionLock, Boolean asyncClose)\n
at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)\n
at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()\n
at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()\n
at Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()\n
at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte\u0026 value)\n
at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean\u0026 dataReady)\n
at Microsoft.Data.SqlClient.SqlDataReader.TryConsumeMetaData()\n
at Microsoft.Data.SqlClient.SqlDataReader.get_MetaData()\n
at Microsoft.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)\n
at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean isAsync, Int32 timeout, Task\u0026 task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)\n
at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, TaskCompletionSource\u00601 completion, Int32 timeout, Task\u0026 task, Boolean\u0026 usedCache, Boolean asyncWrite, Boolean inRetry, String method)\n
at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)\n
at Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior)\n
at Microsoft.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)\n
at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReader(RelationalCommandParameterObject parameterObject)\n
at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable\u00601.Enumerator.InitializeReader(Enumerator enumerator)\n
at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable\u00601.Enumerator.\u003C\u003Ec.\u003CMoveNext\u003Eb__19_0(DbContext _, Enumerator enumerator)\n
at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func\u00603 operation, Func\u00603 verifySucceeded)\n
at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable\u00601.Enumerator.MoveNext()\nClientConnectionId:038757a9-2247-477d-98c5-31eacfa8d39d\nError Number:-2,State:0,Class:11
We have also run traces on the server, we can see the login happening and then after a while a logout happens, on the working query we can see the login, query and then the logout directly after that.
Here is an example of SQL generated by one of the broken queries, it is a join, but in 99.99% of situations it is always a 1 to 1 result
SELECT [t0].[id],
[t0].[accountid],
[t0].[amendedondateutc],
[t0].[billrundate],
[t0].[billingdate],
[t0].[contractid],
[t0].[corrolationid],
[t0].[createdondateutc],
[t0].[creditnotenumber],
[t0].[deletedflag],
[t0].[description],
[t0].[invoicenumber],
[t0].[invoicesent],
[t0].[methodid],
[t0].[ordernumber],
[t0].[paid],
[t0].[partyid],
[t0].[status],
[t0].[tenantid],
[t0].[tokenid],
[t1].[id],
[t1].[amendedondateutc],
[t1].[createdondateutc],
[t1].[deletedflag],
[t1].[description],
[t1].[externalitemid],
[t1].[invoicedescription],
[t1].[note],
[t1].[priceexcluding],
[t1].[quantity],
[t1].[transactiondate],
[t1].[transactionid]
FROM (SELECT TOP(1) [t].[id],
[t].[accountid],
[t].[amendedondateutc],
[t].[billrundate],
[t].[billingdate],
[t].[contractid],
[t].[corrolationid],
[t].[createdondateutc],
[t].[creditnotenumber],
[t].[deletedflag],
[t].[description],
[t].[invoicenumber],
[t].[invoicesent],
[t].[methodid],
[t].[ordernumber],
[t].[paid],
[t].[partyid],
[t].[status],
[t].[tenantid],
[t].[tokenid]
FROM [dbo].[transactions] AS [t]
WHERE [t].[id] = '*****') AS [t0]
LEFT JOIN [dbo].[transactionitems] AS [t1]
ON [t0].[id] = [t1].[transactionid]
ORDER BY [t0].[id]
The issue is discussed in detail on this GitHub issue: https://github.com/dotnet/SqlClient/issues/647.
In short... It is caused by the underlying networking infrastructure. Packets are "truncated" on the network layer, which causes the SqlClient to resubmit the unacknowledged bytes in a new packet, which gets truncated again. The process continues until the request times out.
You can work around this issue by lowering the packet size in the connection string. You do this by appending ;Packet Size=512 to the connection string. 512 is the minimum size of this property, but you can play around with this value.
Do note that by lowering the packet size, you will degrade performance as it will increase CPU usage on both the client and server.
See https://learn.microsoft.com/en-us/dotnet/api/system.data.sqlclient.sqlconnection.packetsize?view=dotnet-plat-ext-8.0 for more info on SqlConnection.PacketSize property.