We're belatedly upgrading a successful .net Core 2.1 MVC application to .net Core 5, and everything has gone well, apart from some confusing Microsoft.Data.SqlClient.SqlException 'Execution Timeout Expired' exceptions in a number of queries that used to work perfectly well in EF Core 2.1.
This is an example of one of the queries we're having problems with
var products = await _context.ShopProducts
.Include(p => p.Category)
.Include(p => p.Brand)
.Include(p => p.CreatedBy)
.Include(p => p.LastUpdatedBy)
.Include(p => p.Variants).ThenInclude(pv => pv.ProductVariantAttributes)
.Include(p => p.Variants).ThenInclude(pv => pv.CountryOfOrigin)
.Include(p => p.Page)
.Include(p => p.CountryOfOrigin)
.OrderBy(p => p.Name)
.Where(p =>
(string.IsNullOrEmpty(searchText)
|| (
p.Name.Contains(searchText)
|| p.Description.Contains(searchText)
|| p.Variants.Any(v => v.SKU.Contains(searchText))
|| p.Variants.Any(v => v.GTIN.Contains(searchText))
|| p.Brand.BrandName.Contains(searchText)
|| p.CountryOfOriginCode == searchText
|| p.Category.Breadcrumb.Contains(searchText)
)
)
).ToPagedListAsync(page, pageSize);
And the exceptions we're getting.
Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
---> System.ComponentModel.Win32Exception (258): The wait operation timed out.
at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
at Microsoft.Data.SqlClient.TdsParserStateObject.ThrowExceptionAndWarning(Boolean callerHasConnectionLock, Boolean asyncClose)
at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
at Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
at Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByteArray(Span`1 buff, Int32 len, Int32& totalRead)
at Microsoft.Data.SqlClient.TdsParserStateObject.TryReadChar(Char& value)
at Microsoft.Data.SqlClient.TdsParser.TryReadPlpUnicodeCharsChunk(Char[] buff, Int32 offst, Int32 len, TdsParserStateObject stateObj, Int32& charsRead)
at Microsoft.Data.SqlClient.TdsParser.TryReadPlpUnicodeChars(Char[]& buff, Int32 offst, Int32 len, TdsParserStateObject stateObj, Int32& totalCharsRead)
at Microsoft.Data.SqlClient.TdsParser.TryReadSqlStringValue(SqlBuffer value, Byte type, Int32 length, Encoding encoding, Boolean isPlp, TdsParserStateObject stateObj)
at Microsoft.Data.SqlClient.TdsParser.TryReadSqlValue(SqlBuffer value, SqlMetaDataPriv md, Int32 length, TdsParserStateObject stateObj, SqlCommandColumnEncryptionSetting columnEncryptionOverride, String columnName, SqlCommand command)
at Microsoft.Data.SqlClient.SqlDataReader.TryReadColumnInternal(Int32 i, Boolean readHeaderOnly)
at Microsoft.Data.SqlClient.SqlDataReader.ReadColumnHeader(Int32 i)
at Microsoft.Data.SqlClient.SqlDataReader.IsDBNull(Int32 i)
at lambda_method1671(Closure , QueryContext , DbDataReader )
at Microsoft.EntityFrameworkCore.Query.RelationalShapedQueryCompilingExpressionVisitor.ShaperProcessingExpressionVisitor.PopulateIncludeCollection[TIncludingEntity,TIncludedEntity](Int32 collectionId, QueryContext queryContext, DbDataReader dbDataReader, SingleQueryResultCoordinator resultCoordinator, Func`3 parentIdentifier, Func`3 outerIdentifier, Func`3 selfIdentifier, IReadOnlyList`1 parentIdentifierValueComparers, IReadOnlyList`1 outerIdentifierValueComparers, IReadOnlyList`1 selfIdentifierValueComparers, Func`5 innerShaper, INavigationBase inverseNavigation, Action`2 fixup, Boolean trackingQuery)
at lambda_method1679(Closure , QueryContext , DbDataReader , ResultContext , SingleQueryResultCoordinator )
at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.MoveNext()
This query will work perfectly if the searchText parameter is not specfied, so I thought it must be something index / data related, but running the SQL generated for the query, with and without the searchText parameter, executes instantaneously when run directly on the database, so it seems to rule out the database as the problem.
Could EF Core 5 be struggling to assemble all the data into object instances? I realise we're returning a large object tree from this query, 152 columns in total, but only 10 rows due to the pageSize variable.
As it doesn't time out when no searchText is specified, and as EF Core 2.1 was able to put it all together with no problem, that doesn't seem to quite make sense either.
Any suggestions for ways to tune the query, or insights anyone has from their own EF Core 2.1 to 3.1 / 5 upgrades, or anything that leaps out from the exception stack trace would be very much appreciated.
UPDATE
Apologies for doing my debugging live on SO, but I've found that it's the p.Description.Contains(searchText) clause in the query that seems to cause the timeout. If I comment it out, the query runs successfully.
The Product.Description data is an HTML string of up to 1028 chars, with an average length of 350 chars, and again, querying this directly in SQL is no problem at all. Could it cause problems for EF in some other way though?
[DataType(DataType.Html)]
public string Description { get; set; }
Consider using Split Queries to improve performance on queries with lots of Include's.