Count() times out on IQueryable

[stesvis]

I am performing a query to the Customers table with some filters:

var customers = Context.Customers
                .AsNoTracking()
                .Include(x => x.Client)
                .Include(x => x.CreatedByUser)
                .Include(x => x.TattleDevices)
                .Where(x =>
                    x.ClientId == clientId
                    && x.Status == Status.Active);

Then I want to get the count (for pagination labels):

var totalCount = customers.Count();

And when the query returns a high number (3-4 thousands records), it often times out with this error (from the logs):

EXCEPTION TYPE: Microsoft.Data.SqlClient.SqlException
 EXCEPTION MESSAGE: 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 (258): The wait operation timed out.
   at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParser.CheckResetConnection(TdsParserStateObject stateObj)
   at Microsoft.Data.SqlClient.TdsParserStateObject.WritePacket(Byte flushMode, Boolean canAccumulate)
   at Microsoft.Data.SqlClient.TdsParserStateObject.ExecuteFlush()
   at Microsoft.Data.SqlClient.TdsParser.TdsExecuteRPC(SqlCommand cmd, _SqlRPC[] rpcArray, Int32 timeout, Boolean inSchema, SqlNotificationRequest notificationRequest, TdsParserStateObject stateObj, Boolean isCommandProc, Boolean sync, TaskCompletionSource`1 completion, Int32 startRpc, Int32 startParam)
   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)
   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)
   at Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReader(RelationalCommandParameterObject parameterObject)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.InitializeReader(Enumerator enumerator)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.MoveNext()
   at System.Linq.Enumerable.TryGetSingle[TSource](IEnumerable`1 source, Boolean& found)
   at lambda_method2338(Closure , QueryContext )
   at System.Linq.Queryable.Count[TSource](IQueryable`1 source)
   at LiveDispatchApi.Services.Customers.CustomersService.Filter(Int32 clientId, Int32& recordsTotal, Nullable`1 takeFrom, Nullable`1 takeCount, String searchValue, Nullable`1 orderByIndex, String orderDirection) in R:\NorthStar\live-dispatch-api\LiveDispatchApi\Services\Customers\CustomersService.cs:line 41
   at LiveDispatchApi.Controllers.v3._1.CustomersController.Filter(Int32 clientId, SearchRequest request) in R:\NorthStar\live-dispatch-api\LiveDispatchApi\Controllers\v3.1\CustomersController.cs:line 30
ClientConnectionId:68b91fd8-cd84-47b1-b6a6-e358b4df7639
Error Number:-2,State:0,Class:11
 STACK TRACE:    at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParser.CheckResetConnection(TdsParserStateObject stateObj)
   at Microsoft.Data.SqlClient.TdsParserStateObject.WritePacket(Byte flushMode, Boolean canAccumulate)
   at Microsoft.Data.SqlClient.TdsParserStateObject.ExecuteFlush()
   at Microsoft.Data.SqlClient.TdsParser.TdsExecuteRPC(SqlCommand cmd, _SqlRPC[] rpcArray, Int32 timeout, Boolean inSchema, SqlNotificationRequest notificationRequest, TdsParserStateObject stateObj, Boolean isCommandProc, Boolean sync, TaskCompletionSource`1 completion, Int32 startRpc, Int32 startParam)
   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)
   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)
   at Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReader(RelationalCommandParameterObject parameterObject)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.InitializeReader(Enumerator enumerator)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.MoveNext()
   at System.Linq.Enumerable.TryGetSingle[TSource](IEnumerable`1 source, Boolean& found)
   at lambda_method2338(Closure , QueryContext )
   at System.Linq.Queryable.Count[TSource](IQueryable`1 source)
   at LiveDispatchApi.Services.Customers.CustomersService.Filter(Int32 clientId, Int32& recordsTotal, Nullable`1 takeFrom, Nullable`1 takeCount, String searchValue, Nullable`1 orderByIndex, String orderDirection) in R:\NorthStar\live-dispatch-api\LiveDispatchApi\Services\Customers\CustomersService.cs:line 41
   at LiveDispatchApi.Controllers.v3._1.CustomersController.Filter(Int32 clientId, SearchRequest request) in R:\NorthStar\live-dispatch-api\LiveDispatchApi\Controllers\v3.1\CustomersController.cs:line 30

 INNER EXCEPTION: Microsoft.Data.SqlClient.SqlException Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. Void OnError(Microsoft.Data.SqlClient.SqlException, Boolean, System.Action`1[System.Action])
Win32Exception The wait operation timed out.

IMPORTANT: The same approach never times out in the old Entity Framework 6, I only noticed it in EF Core 6 because I am rebuilding it with the new .NET Core.

Any ideas?

Provider and version information

EF Core version: 6.0.9
Database provider: Microsoft.EntityFrameworkCore.SqlServer
Target framework: .NET 6.0
Operating system: Windows
IDE: Visual Studio 2022 17.3.2

[roji]

Can you please post the SQL EF is generating? You can do this by turning on logging (see docs).

[stesvis]

Can you please post the SQL EF is generating? You can do this by turning on logging (see docs.

DECLARE @__clientId_0 int = 1;

SELECT [c].[Id], [c].[Address1], [c].[Address2], [c].[City], [c].[ClientId], [c].[Comment1], [c].[Comment2], [c].[Company], [c].[ContactName], [c].[Country], [c].[CreatedByUserId], [c].[CreatedDate], [c].[CreatedDateUtc], [c].[DeletedDate], [c].[DeletedDateUtc], [c].[Email], [c].[Geolocation], [c].[Ltd], [c].[MemberNumber], [c].[Notes], [c].[PermanentInstructions], [c].[Phone], [c].[PostalCode], [c].[Province], [c].[RamCard], [c].[Route], [c].[SerialNumber], [c].[Status], [c].[TankSize], [c0].[Id], [c0].[Address1], [c0].[Address2], [c0].[City], [c0].[Country], [c0].[CreatedByUserId], [c0].[CreatedDate], [c0].[CreatedDateUtc], [c0].[DeletedDate], [c0].[DeletedDateUtc], [c0].[DisplayName], [c0].[Email], [c0].[ExpiryDate], [c0].[Fee], [c0].[Guid], [c0].[HasDoneImport], [c0].[IsDemo], [c0].[LeadEmail], [c0].[Name], [c0].[Notes], [c0].[ParentClientId], [c0].[Phone], [c0].[PostalCode], [c0].[Province], [c0].[Status], [c0].[TempGuid], [c0].[TypeId], [c0].[ViewOnlyFee], [a].[Id], [a].[AccessFailedCount], [a].[ConcurrencyStamp], [a].[CreatedDate], [a].[CreatedDateUtc], [a].[Email], [a].[EmailConfirmed], [a].[FirstName], [a].[LastActivityDate], [a].[LastActivityDateUtc], [a].[LastName], [a].[LockoutEnabled], [a].[LockoutEnd], [a].[NormalizedEmail], [a].[NormalizedUserName], [a].[PasswordHash], [a].[PhoneNumber], [a].[PhoneNumberConfirmed], [a].[SecurityStamp], [a].[TwoFactorEnabled], [a].[UserName], [t].[Id], [t].[CreatedByUserId], [t].[CreatedDate], [t].[CreatedDateUtc], [t].[CustomerId], [t].[DeletedDate], [t].[DeletedDateUtc], [t].[IsDirectDrop], [t].[Latitude], [t].[Longitude], [t].[Name], [t].[Notes], [t].[ProductId], [t].[Status], [t].[TattleId], [t].[UniqueId]
FROM [Customers] AS [c]
INNER JOIN [Clients] AS [c0] ON [c].[ClientId] = [c0].[Id]
INNER JOIN [AspNetUsers] AS [a] ON [c].[CreatedByUserId] = [a].[Id]
LEFT JOIN [TattleDevices] AS [t] ON [c].[Id] = [t].[CustomerId]
WHERE ([c].[ClientId] = @__clientId_0) AND ([c].[Status] = N'A')
ORDER BY [c].[Id], [c0].[Id], [a].[Id]

[roji]

@stesvis that doesn't look like a LINQ query which ends with a Count - can you please double-check which query exactly you're executing? The query with Count should be only projecting the count out.

For regular, non-Count queries, you may want to take a look at single vs. split queries, especially if each Customer typically has lots of Clients and AspNetUsers.

[stesvis]

@roji I added this to my DbContext but nothing gets logged to the output window, any idea?

        protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        {
            optionsBuilder.LogTo(Console.WriteLine);
        }

[roji]

You'll have to post a runnable code sample, it's hard to help given just a code snippet.

[stevendarby]

For regular, non-Count queries, you may want to take a look at single vs. split queries, especially if each Customer typically has lots of Clients and AspNetUsers.

Each Customer only has one Client and one AspNetUser; they're reference navigations. Due to this bug #29182 split query may be slower in this instance.

[stesvis]

@roji got the query finally:

dbug: 2022-09-28 16:02:33.893 CoreEventId.QueryCompilationStarting[10111] (Microsoft.EntityFrameworkCore.Query) 
      Compiling query expression: 
      'DbSet<Customer>()
          .AsNoTracking()
          .Include(x => x.Client)
          .Include(x => x.CreatedByUser)
          .Include(x => x.TattleDevices)
          .Where(x => x.ClientId == __clientId_0 && x.Status == "A" && True)
          .OrderBy(x => x.Company.Trim())
          .Count()'
dbug: 2022-09-28 16:02:33.913 CoreEventId.QueryExecutionPlanned[10107] (Microsoft.EntityFrameworkCore.Query) 
      Generated query execution expression: 
      'queryContext => new SingleQueryingEnumerable<int>(
          (RelationalQueryContext)queryContext, 
          RelationalCommandCache.SelectExpression(
              Projection Mapping:
                  EmptyProjectionMember -> 0
              SELECT COUNT(*)
              FROM Customers AS c
              WHERE ((c.ClientId == @__clientId_0) && (c.Status == N'A')) && CAST(1 AS bit)), 
          Func<QueryContext, DbDataReader, ResultContext, SingleQueryResultCoordinator, int>, 
          LiveDispatchApi.Data.ApplicationDbContext, 
          False, 
          False, 
          True
      )
          .Single()'
dbug: 2022-09-28 16:02:33.922 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command) 
      Creating DbCommand for 'ExecuteReader'.
dbug: 2022-09-28 16:02:33.924 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command) 
      Created DbCommand for 'ExecuteReader' (2ms).
dbug: 2022-09-28 16:02:33.928 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection) 
      Opening connection to database 'LiveDispatch' on server 'localhost'.
dbug: 2022-09-28 16:02:33.931 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection) 
      Opened connection to database 'LiveDispatch' on server 'localhost'.
dbug: 2022-09-28 16:02:33.934 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command) 
      Executing DbCommand [Parameters=[@__clientId_0='?' (DbType = Int32)], CommandType='Text', CommandTimeout='30']
      SELECT COUNT(*)
      FROM [Customers] AS [c]
      WHERE ([c].[ClientId] = @__clientId_0) AND ([c].[Status] = N'A')
info: 2022-09-28 16:02:33.944 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
      Executed DbCommand (10ms) [Parameters=[@__clientId_0='?' (DbType = Int32)], CommandType='Text', CommandTimeout='30']
      SELECT COUNT(*)
      FROM [Customers] AS [c]
      WHERE ([c].[ClientId] = @__clientId_0) AND ([c].[Status] = N'A')
dbug: 2022-09-28 16:02:33.947 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command) 
      A data reader was disposed.
dbug: 2022-09-28 16:02:33.949 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection) 
      Closing connection to database 'LiveDispatch' on server 'localhost'.
dbug: 2022-09-28 16:02:33.951 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection) 
      Closed connection to database 'LiveDispatch' on server 'localhost'.

[roji]

@stesvis your logs above indicate that the query took 10ms (SELECT COUNT(*)...) - are you sure this is the query causing the slowdown? Is it reproducible, i.e. do you get the slow execution every time you run the application, or just occasionally? If it's the latter, there could be a network issue causing the occasional timeout; otherwise, double-check your assumption, there may be a different query actually causing the slowdown.

[stesvis]

@stesvis your logs above indicate that the query took 10ms (SELECT COUNT(*)...) - are you sure this is the query causing the slowdown? Is it reproducible, i.e. do you get the slow execution every time you run the application, or just occasionally? If it's the latter, there could be a network issue causing the occasional timeout; otherwise, double-check your assumption, there may be a different query actually causing the slowdown.

That's the query. I was testing it locally and had a breakpoint on var totalCount = customers.Count(); and that was timing out when I executed it.
Like i said it didn't timeout always, but I'd say often.

[roji]

@stesvis there's not really much I can do to help... Since the timeout doesn't always occur, that points towards some environmental issue, e.g. your network being flaky in some way. If it occurs often, I'd try to first see the actual timeout occuring in the EF logs as above, including the timing - that would provide clear proof of the issue. At that point you can investigate if there was a network outage or similar at the same time, or possibly some database availability issue...

[stesvis]

@stesvis there's not really much I can do to help... Since the timeout doesn't always occur, that points towards some environmental issue, e.g. your network being flaky in some way. If it occurs often, I'd try to first see the actual timeout occuring in the EF logs as above, including the timing - that would provide clear proof of the issue. At that point you can investigate if there was a network outage or similar at the same time, or possibly some database availability issue...

But if i am debugging this locally how can I be a network issue?
I just tried again, this time it took 14s...

      Executed DbCommand (14,681ms) [Parameters=[@__clientId_0='?' (DbType = Int32)], CommandType='Text', CommandTimeout='30']
      SELECT COUNT(*)
      FROM [Customers] AS [c]
      WHERE ([c].[ClientId] = @__clientId_0) AND ([c].[Status] = N'A')

I don't understand how this only happens with EF Core and not with EF6.

[roji]

Can you please post the SQL being generated by EF6, to rule out any SQL differences that may be the source of the difference?

[stesvis]

Can you please post the SQL being generated by EF6, to rule out any SQL differences that may be the source of the difference?

This is the equivalent query generated by the same method in EF6:

SELECT 
    [GroupBy1].[A1] AS [C1]
    FROM ( SELECT 
        COUNT(1) AS [A1]
        FROM [dbo].[Customers] AS [Extent1]
        WHERE ([Extent1].[ClientId] = @p__linq__0) AND (N'A' = [Extent1].[Status]) AND (N'A' = [Extent1].[Status]) AND ((@p__linq__1 IS NULL) OR (( CAST(LEN(@p__linq__1) AS int)) = 0) OR (( NOT (([Extent1].[Company] IS NULL) OR ((LEN([Extent1].[Company])) = 0))) AND (( CAST(CHARINDEX(LOWER(@p__linq__2), LOWER([Extent1].[Company])) AS int)) > 0)) OR (@p__linq__3 IS NULL) OR (( CAST(LEN(@p__linq__3) AS int)) = 0) OR (( NOT (([Extent1].[ContactName] IS NULL) OR ((LEN([Extent1].[ContactName])) = 0))) AND (( CAST(CHARINDEX(LOWER(@p__linq__4), LOWER([Extent1].[ContactName])) AS int)) > 0)) OR (@p__linq__5 IS NULL) OR (( CAST(LEN(@p__linq__5) AS int)) = 0) OR (( NOT (([Extent1].[MemberNumber] IS NULL) OR ((LEN([Extent1].[MemberNumber])) = 0))) AND (( CAST(CHARINDEX(LOWER(@p__linq__6), LOWER([Extent1].[MemberNumber])) AS int)) > 0)) OR (@p__linq__7 IS NULL) OR (( CAST(LEN(@p__linq__7) AS int)) = 0) OR (( NOT (([Extent1].[Phone] IS NULL) OR ((LEN([Extent1].[Phone])) = 0))) AND (( CAST(CHARINDEX(LOWER(@p__linq__8), LOWER([Extent1].[Phone])) AS int)) > 0)) OR (@p__linq__9 IS NULL) OR (( CAST(LEN(@p__linq__9) AS int)) = 0) OR (( NOT (([Extent1].[Email] IS NULL) OR ((LEN([Extent1].[Email])) = 0))) AND (( CAST(CHARINDEX(LOWER(@p__linq__10), LOWER([Extent1].[Email])) AS int)) > 0)) OR (@p__linq__11 IS NULL) OR (( CAST(LEN(@p__linq__11) AS int)) = 0) OR (( NOT (([Extent1].[Comment1] IS NULL) OR ((LEN([Extent1].[Comment1])) = 0))) AND (( CAST(CHARINDEX(LOWER(@p__linq__12), LOWER([Extent1].[Comment1])) AS int)) > 0)) OR (@p__linq__13 IS NULL) OR (( CAST(LEN(@p__linq__13) AS int)) = 0) OR (( NOT (([Extent1].[Comment2] IS NULL) OR ((LEN([Extent1].[Comment2])) = 0))) AND (( CAST(CHARINDEX(LOWER(@p__linq__14), LOWER([Extent1].[Comment2])) AS int)) > 0)) OR (@p__linq__15 IS NULL) OR (( CAST(LEN(@p__linq__15) AS int)) = 0) OR (( NOT (([Extent1].[SerialNumber] IS NULL) OR ((LEN([Extent1].[SerialNumber])) = 0))) AND (( CAST(CHARINDEX(LOWER(@p__linq__16), LOWER([Extent1].[SerialNumber])) AS int)) > 0)))
    )  AS [GroupBy1]


-- p__linq__0: '2040' (Type = Int32, IsNullable = false)

-- p__linq__1: 'null' (Type = String, Size = 4000)

-- p__linq__2: 'null' (Type = String, Size = 4000)

-- p__linq__3: 'null' (Type = String, Size = 4000)

-- p__linq__4: 'null' (Type = String, Size = 4000)

-- p__linq__5: 'null' (Type = String, Size = 4000)

-- p__linq__6: 'null' (Type = String, Size = 4000)

-- p__linq__7: 'null' (Type = String, Size = 4000)

-- p__linq__8: 'null' (Type = String, Size = 4000)

-- p__linq__9: 'null' (Type = String, Size = 4000)

-- p__linq__10: 'null' (Type = String, Size = 4000)

-- p__linq__11: 'null' (Type = String, Size = 4000)

-- p__linq__12: 'null' (Type = String, Size = 4000)

-- p__linq__13: 'null' (Type = String, Size = 4000)

-- p__linq__14: 'null' (Type = String, Size = 4000)

-- p__linq__15: 'null' (Type = String, Size = 4000)

-- p__linq__16: 'null' (Type = String, Size = 4000)

-- Executing at 2022-09-29 12:00:23 PM -06:00

-- Completed in 134 ms with result: GlimpseDbDataReader

[ajcvickers]

@stesvis It seems highly unlikely that this is related to EF Core rather than some other environment difference. Can you post two complete samples, one with EF6 and one with EF Core, so we can compare concrete differences?

[stesvis]

@stesvis It seems highly unlikely that this is related to EF Core rather than some other environment difference. Can you post two complete samples, one with EF6 and one with EF Core, so we can compare concrete differences?

I finally found the problem. But this might be a VS2022 issue.
It randomly timed out and I discovered that it always happened when I had some other programs open.
So I checked the task manager and noticed that I was using > 90% memory.

Specifically VS2022 was taking 3.6GB, which I think is a lot but I've used VS2019 until a couple of weeks ago.
Once I closed all the other apps to let the memory go down, the query completed in less than 100ms every time.