Update of 5.6 to 5.7.1 causes lots of Timeout in include queries #1731

JohnStrim · 2025-05-23T09:23:18Z

SUMMARY

Update to this version has produced many Timeouts in EF Core

DETAILS

In our logic we are extensively using query strings for filtering, including relationships and paging which in previous versions used to perform very well (Generally under 1 sec).
When updating to version 5.7.1 we started having a lot of Timeout in Db Queries. To provide more context we were trying to include relationships that are 2 or 3 level deep from our original resource: (ex. include=products.unitGroup,products.unitGroup.units)
Also we noticed a big delay even in simple GET queries which used to return result under 200ms and now performance has up to 600ms with no appart explanation.
We've tried to do an EF Performance Update: (Include the UseQuerySplittingBehavior(QuerySplittingBehavior.SplitQuery)) but this seems to causes many Data is Null Exceptions when including relationships.
Is there any suggestions as far as configuration or minimum versions that we should be aware of to avoid this overhead?

VERSIONS USED

JsonApiDotNetCore version: 5.7.1
ASP.NET Core version: 8.0
Entity Framework Core version: 8.0.1, 9.0.5 (Tried Both)
Database provider: SQL Server

JohnStrim · 2025-05-23T10:15:38Z

Let me provide some more Context.
Here are the logs of a GET Call with a complex query string (I've removed double Log Messages that for some reason I'm getting, sensitive query data and the actual log of the db query because of data sensitivity but left the execution times:

JsonApiDotNetCore: 5.6.0

Query String of Api Call: filter=and(any(id,'XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX','XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX','XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX',XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX','XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX'),equals(isDeleted,'false'))&include=products.unitGroup.units

Execution Time in Postman: 2.1s

Logs:


[09:57:08 DBG] AuthenticationScheme: Bearer was successfully authenticated.
[09:57:08 DBG] Query string parameter 'filter' with value 'and(any(id,'XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX','XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX','XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX',XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX','XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX'),equals(isDeleted,'false'))' was accepted by FilterQueryStringParameterReader.
[09:57:08 DBG] Query string parameter 'filter' was successfully read.
[09:57:08 DBG] Query string parameter 'include' with value 'products.unitGroup.units' was accepted by IncludeQueryStringParameterReader.
[09:57:08 DBG] Query string parameter 'include' was successfully read.
[EF Query Timing] info: 05/23/2025 09:57:09.054 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
      Executed DbCommand (23ms)
      Executed DbCommand (83ms) 
[09:57:10 INF] HTTP GET /v1/priceGroups responded 200 in 2046.5377 ms

After Version Update without changing anything else...
JsonApiDotNetCore: 5.7.1

Logs:


[10:06:37 DBG] AuthenticationScheme: Bearer was successfully authenticated.
[10:06:37 DBG] Query string parameter 'filter' with value '["and(any(id,'XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX','XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX','XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX',XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX','XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX'),equals(isDeleted,'false'))"]' was accepted by FilterQueryStringParameterReader.
[10:06:37 DBG] Query string parameter 'filter' was successfully read.
[10:06:37 DBG] Query string parameter 'include' with value '["products.unitGroup.units"]' was accepted by IncludeQueryStringParameterReader.
[10:06:37 DBG] Query string parameter 'include' was successfully read.
[EF Query Timing] info: 05/23/2025 10:06:38.167 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
      Executed DbCommand (24ms) [CommandTimeout='30']
   
[10:06:38 WRN] Compiling a query which loads related collections for more than one collection navigation, either via 'Include' or through projection, but no 'QuerySplittingBehavior' has been configured. By default, Entity Framework will use 'QuerySplittingBehavior.SingleQuery', which can potentially result in slow query performance. See https://go.microsoft.com/fwlink/?linkid=2134277 for more information. To identify the query that's triggering this warning call 'ConfigureWarnings(w => w.Throw(RelationalEventId.MultipleCollectionIncludeWarning))'.

[10:07:08 ERR] Failed executing DbCommand (30,016ms) [CommandTimeout='30']

[10:07:08 ERR] An exception occurred while iterating over the results of a query for context type 'Iwcp.Rest.Infrastructure.Context.ApplicationDbContext'.
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): Unknown error 258
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__195_0(Task`1 result)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()
ClientConnectionId:a5d26c76-71da-484a-b2c3-9f13f4fc3a5f
Error Number:-2,State:0,Class:11
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): Unknown error 258
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__195_0(Task`1 result)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()
ClientConnectionId:a5d26c76-71da-484a-b2c3-9f13f4fc3a5f
Error Number:-2,State:0,Class:11

[10:07:08 ERR] Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
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): Unknown error 258
   at Task<DbDataReader> Microsoft.Data.SqlClient.SqlCommand.ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken)+(Task<SqlDataReader> result) => { }
   at void System.Threading.Tasks.ContinuationResultTaskFromResultTask<TAntecedentResult, TResult>.InnerInvoke()
   at async Task<RelationalDataReader> Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken) x 2
   at async Task<bool> Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable<T>+AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)
   at async Task<TResult> Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync<TState, TResult>(TState state, Func<DbContext, TState, CancellationToken, Task<TResult>> operation, Func<DbContext, TState, CancellationToken, Task<ExecutionResult<TResult>>> verifySucceeded, CancellationToken cancellationToken)
   at async ValueTask<bool> Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable<T>+AsyncEnumerator.MoveNextAsync()
   at async Task<List<TSource>> Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync<TSource>(IQueryable<TSource> source, CancellationToken cancellationToken) x 2
   at async Task<IReadOnlyCollection<TResource>> JsonApiDotNetCore.Repositories.EntityFrameworkCoreRepository<TResource, TId>.GetAsync(QueryLayer queryLayer, CancellationToken cancellationToken) in /_/src/JsonApiDotNetCore/Repositories/EntityFrameworkCoreRepository.cs:line 82
   at object CallSite.Target(Closure, CallSite, object)
   at TRet System.Dynamic.UpdateDelegates.UpdateAndExecute1<T0, TRet>(CallSite site, T0 arg0)
   at async Task<IReadOnlyCollection<TResource>> JsonApiDotNetCore.Repositories.ResourceRepositoryAccessor.GetAsync<TResource>(QueryLayer queryLayer, CancellationToken cancellationToken)
   at async Task<IReadOnlyCollection<TResource>> JsonApiDotNetCore.Services.JsonApiResourceService<TResource, TId>.GetAsync(CancellationToken cancellationToken) in /_/src/JsonApiDotNetCore/Services/JsonApiResourceService.cs:line 77
   at async Task<IActionResult> JsonApiDotNetCore.Controllers.BaseJsonApiController<TResource, TId>.GetAsync(CancellationToken cancellationToken) in /_/src/JsonApiDotNetCore/Controllers/BaseJsonApiController.cs:line 102
   at async Task<IActionResult> JsonApiDotNetCore.Controllers.JsonApiController<TResource, TId>.GetAsync(CancellationToken cancellationToken) in /_/src/JsonApiDotNetCore/Controllers/JsonApiController.cs:line 50
   at async ValueTask<IActionResult> Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor+TaskOfIActionResultExecutor.Execute(ActionContext actionContext, IActionResultTypeMapper mapper, ObjectMethodExecutor executor, object controller, object[] arguments)
   at async Task Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()+Awaited(?)
   at async Task Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()+Awaited(?)
   at void Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Task Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(ref State next, ref Scope scope, ref object state, ref bool isCompleted)
   at async Task Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()+Awaited(?)
   at async Task Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeNextExceptionFilterAsync()+Awaited(?)
ClientConnectionId:a5d26c76-71da-484a-b2c3-9f13f4fc3a5f
Error Number:-2,State:0,Class:11

[10:07:08 ERR] HTTP GET /v1/priceGroups responded 500 in 31796.6382 ms

Please Notice that even EF Core has now provided new warnings after the update and If I were to show you the full query you could see that it trippled in its size... Since there is no EF Core update that our team did can you help us explain this?

bkoelman · 2025-05-23T10:31:57Z

Are you using resource inheritance? It would help to share the before/after SQL for the request URL.

JohnStrim · 2025-05-23T10:37:42Z

Yes we are. products is a base resource with 5 or 6 children Resources

JohnStrim · 2025-05-23T11:01:40Z

@bkoelman Here is the generated Query in version 5.6.0:
Execution Time: 125ms


SELECT [t0].[Id], [t0].[IDCopyOf], [t0].[CreatedDate], [t0].[CreatedByID], [t0].[Description], [t0].[IsDeleted], [t0].[Name], [t0].[OrganizationId], [t0].[LastUpdate], [t0].[LastUpdateID], [t3].[Id], [t3].[ActivateAllUnits], [t3].[IDCategory], [t3].[ChargeRule], [t3].[Discriminator], [t3].[IDCopyOf], [t3].[RegDate], [t3].[CreatedById], [t3].[DemoLinkEnabled], [t3].[Derivative], [t3].[Comments], [t3].[DisplayFeaturesTab], [t3].[DisplaySupportTab], [t3].[DocumentLinkEnabled], [t3].[EnableCancellation], [t3].[EnableTermsOfUse], [t3].[FilePath], [t3].[FullDescription], [t3].[IsActivated], [t3].[IsAddon], [t3].[IsAvailableViaPriceList], [t3].[IsBundle], [t3].[IsDeleted], [t3].[IsEnabled], [t3].[IsFeatured], [t3].[IsNew], [t3].[IsProductGroup], [t3].[KeyWords], [t3].[Name], [t3].[NoIndex], [t3].[OrganizationId], [t3].[OverviewPage], [t3].[IDPriceCategory], [t3].[Source], [t3].[IDProductType], [t3].[ProrataBilling], [t3].[IDResponsibleUser], [t3].[ScreenshotLinkEnabled], [t3].[ShortDescription], [t3].[SupportOptions], [t3].[TermsOfUse], [t3].[IDUnitCategory], [t3].[ModifiedDate], [t3].[LastUpdateID], [t3].[WebCatalogueEnabled], [t3].[WebComEnabled], [t3].[WebOfferEnabled], [t3].[WebOrderEnabled], [t3].[ChargeType], [t3].[CompetitionComments], [t3].[IgnoreProrata], [t3].[IsCompetitive], [t3].[IsNegative], [t3].[IsTaxable], [t3].[NoOfDecimals], [t3].[IDPricelist], [t3].[IdProductGroup], [t3].[SKU], [t3].[IDUnitType], [t3].[BillingOption], [t3].[IDDiscountList], [t3].[AllowsCustomEndDate], [t3].[BillingModel], [t3].[EnableTrialVariations], [t3].[ExternalBilling], [t3].[ExternalBillingType], [t3].[IdExternalPricing], [t3].[FreePeriodEnabled], [t3].[IDOrgSystem], [t3].[OverageOption], [t3].[RequestType], [t3].[SyncSignature], [t3].[IDSyncStatus], [t3].[TrialDuration], [t3].[TrialDurationType], [t3].[TrialNo], [t3].[TrialType], [t3].[UserProvEnabled], [t3].[IsBillingFrequencyEnabled], [t3].[RampUpPeriods], [t3].[IDResource], [t3].[IDResourceVariation], [t3].[SupportsMonthlyBillingFrequency], [t3].[IDHostingAddOn], [t3].[Id0], [t3].[CreatedDate], [t3].[CreatedByID0], [t3].[Description], [t3].[IdCopyOf0], [t3].[IsActive], [t3].[IsDeleted0], [t3].[Name0], [t3].[OrganizationId0], [t3].[SystemType], [t3].[LastUpdate], [t3].[LastUpdateId0], [t3].[Id1], [t3].[BaseQuantity], [t3].[IDCopyOf1], [t3].[DecimalPlacesNo], [t3].[Duration], [t3].[DurationType], [t3].[IsActive0], [t3].[IsDeleted1], [t3].[Mnemonic], [t3].[Name1], [t3].[IDUnitCategory0], [t3].[Quantity], [t3].[SystemType0]
      FROM (
          SELECT TOP(25) [t].[Id], [t].[IDCopyOf], [t].[CreatedDate], [t].[CreatedByID], [t].[Description], [t].[IsDeleted], [t].[Name], [t].[OrganizationId], [t].[LastUpdate], [t].[LastUpdateID]
          FROM [tblPriceCategory] AS [t] WITH (NOLOCK)
          WHERE [t].[OrganizationId] = 1 AND [t].[Id] IN ('29bb1ded-4887-43b7-84b2-94769721edbd', '7bb75da4-14ac-44bf-923b-df513a9505bf', '49413e3e-91d4-4709-8062-6d68cb9f4961', 'c0c52261-2bf6-4650-a96b-b252a9239d8e', 'da794453-be10-4b63-94f6-4654b4c14da9') AND [t].[IsDeleted] = 0
          ORDER BY [t].[Id]
      ) AS [t0]
      OUTER APPLY (
          SELECT [t1].[Id], [t1].[ActivateAllUnits], [t1].[IDCategory], [t1].[ChargeRule], [t1].[Discriminator], [t1].[IDCopyOf], [t1].[RegDate], [t1].[CreatedById], [t1].[DemoLinkEnabled], [t1].[Derivative], [t1].[Comments], [t1].[DisplayFeaturesTab], [t1].[DisplaySupportTab], [t1].[DocumentLinkEnabled], [t1].[EnableCancellation], [t1].[EnableTermsOfUse], [t1].[FilePath], [t1].[FullDescription], [t1].[IsActivated], [t1].[IsAddon], [t1].[IsAvailableViaPriceList], [t1].[IsBundle], [t1].[IsDeleted], [t1].[IsEnabled], [t1].[IsFeatured], [t1].[IsNew], [t1].[IsProductGroup], [t1].[KeyWords], [t1].[Name], [t1].[NoIndex], [t1].[OrganizationId], [t1].[OverviewPage], [t1].[IDPriceCategory], [t1].[Source], [t1].[IDProductType], [t1].[ProrataBilling], [t1].[IDResponsibleUser], [t1].[ScreenshotLinkEnabled], [t1].[ShortDescription], [t1].[SupportOptions], [t1].[TermsOfUse], [t1].[IDUnitCategory], [t1].[ModifiedDate], [t1].[LastUpdateID], [t1].[WebCatalogueEnabled], [t1].[WebComEnabled], [t1].[WebOfferEnabled], [t1].[WebOrderEnabled], [t1].[ChargeType], [t1].[CompetitionComments], [t1].[IgnoreProrata], [t1].[IsCompetitive], [t1].[IsNegative], [t1].[IsTaxable], [t1].[NoOfDecimals], [t1].[IDPricelist], [t1].[IdProductGroup], [t1].[SKU], [t1].[IDUnitType], [t1].[BillingOption], [t1].[IDDiscountList], [t1].[AllowsCustomEndDate], [t1].[BillingModel], [t1].[EnableTrialVariations], [t1].[ExternalBilling], [t1].[ExternalBillingType], [t1].[IdExternalPricing], [t1].[FreePeriodEnabled], [t1].[IDOrgSystem], [t1].[OverageOption], [t1].[RequestType], [t1].[SyncSignature], [t1].[IDSyncStatus], [t1].[TrialDuration], [t1].[TrialDurationType], [t1].[TrialNo], [t1].[TrialType], [t1].[UserProvEnabled], [t1].[IsBillingFrequencyEnabled], [t1].[RampUpPeriods], [t1].[IDResource], [t1].[IDResourceVariation], [t1].[SupportsMonthlyBillingFrequency], [t1].[IDHostingAddOn], [t2].[Id] AS [Id0], [t2].[CreatedDate], [t2].[CreatedByID] AS [CreatedByID0], [t2].[Description], [t2].[IdCopyOf] AS [IdCopyOf0], [t2].[IsActive], [t2].[IsDeleted] AS [IsDeleted0], [t2].[Name] AS [Name0], [t2].[OrganizationId] AS [OrganizationId0], [t2].[SystemType], [t2].[LastUpdate], [t2].[LastUpdateId] AS [LastUpdateId0], [t4].[Id] AS [Id1], [t4].[BaseQuantity], [t4].[IDCopyOf] AS [IDCopyOf1], [t4].[DecimalPlacesNo], [t4].[Duration], [t4].[DurationType], [t4].[IsActive] AS [IsActive0], [t4].[IsDeleted] AS [IsDeleted1], [t4].[Mnemonic], [t4].[Name] AS [Name1], [t4].[IDUnitCategory] AS [IDUnitCategory0], [t4].[Quantity], [t4].[SystemType] AS [SystemType0]
          FROM (
              SELECT TOP(25) [t5].[Id], [t5].[ActivateAllUnits], [t5].[IDCategory], [t5].[ChargeRule], [t5].[Discriminator], [t5].[IDCopyOf], [t5].[RegDate], [t5].[CreatedById], [t5].[DemoLinkEnabled], [t5].[Derivative], [t5].[Comments], [t5].[DisplayFeaturesTab], [t5].[DisplaySupportTab], [t5].[DocumentLinkEnabled], [t5].[EnableCancellation], [t5].[EnableTermsOfUse], [t5].[FilePath], [t5].[FullDescription], [t5].[IsActivated], [t5].[IsAddon], [t5].[IsAvailableViaPriceList], [t5].[IsBundle], [t5].[IsDeleted], [t5].[IsEnabled], [t5].[IsFeatured], [t5].[IsNew], [t5].[IsProductGroup], [t5].[KeyWords], [t5].[Name], [t5].[NoIndex], [t5].[OrganizationId], [t5].[OverviewPage], [t5].[IDPriceCategory], [t5].[Source], [t5].[IDProductType], [t5].[ProrataBilling], [t5].[IDResponsibleUser], [t5].[ScreenshotLinkEnabled], [t5].[ShortDescription], [t5].[SupportOptions], [t5].[TermsOfUse], [t5].[IDUnitCategory], [t5].[ModifiedDate], [t5].[LastUpdateID], [t5].[WebCatalogueEnabled], [t5].[WebComEnabled], [t5].[WebOfferEnabled], [t5].[WebOrderEnabled], [t5].[ChargeType], [t5].[CompetitionComments], [t5].[IgnoreProrata], [t5].[IsCompetitive], [t5].[IsNegative], [t5].[IsTaxable], [t5].[NoOfDecimals], [t5].[IDPricelist], [t5].[IdProductGroup], [t5].[SKU], [t5].[IDUnitType], [t5].[BillingOption], [t5].[IDDiscountList], [t5].[AllowsCustomEndDate], [t5].[BillingModel], [t5].[EnableTrialVariations], [t5].[ExternalBilling], [t5].[ExternalBillingType], [t5].[IdExternalPricing], [t5].[FreePeriodEnabled], [t5].[IDOrgSystem], [t5].[OverageOption], [t5].[RequestType], [t5].[SyncSignature], [t5].[IDSyncStatus], [t5].[TrialDuration], [t5].[TrialDurationType], [t5].[TrialNo], [t5].[TrialType], [t5].[UserProvEnabled], [t5].[IsBillingFrequencyEnabled], [t5].[RampUpPeriods], [t5].[IDResource], [t5].[IDResourceVariation], [t5].[SupportsMonthlyBillingFrequency], [t5].[IDHostingAddOn]
              FROM [tblProduct] AS [t5] WITH (NOLOCK)
              WHERE [t5].[Discriminator] IN (3, 0, 1) AND [t0].[Id] = [t5].[IDPriceCategory]
              ORDER BY [t5].[Id]
          ) AS [t1]
          LEFT JOIN [tblUnitCategory] AS [t2] WITH (NOLOCK) ON [t1].[IDUnitCategory] = [t2].[Id]
          LEFT JOIN [tblUnit] AS [t4] WITH (NOLOCK) ON [t2].[Id] = [t4].[IDUnitCategory]
      ) AS [t3]
      ORDER BY [t0].[Id], [t3].[Id], [t3].[Id0]

Here is the generate query in version 5.7.1:
Execution Time: (I had to stop it around 4 minutes...)

SELECT [t0].[Id], [t0].[IDCopyOf], [t0].[CreatedDate], [t0].[CreatedByID], [t0].[Description], [t0].[IsDeleted], [t0].[Name], [t0].[OrganizationId], [t0].[LastUpdate], [t0].[LastUpdateID], [t15].[Id], [t15].[ActivateAllUnits], [t15].[IDCategory], [t15].[ChargeRule], [t15].[Discriminator], [t15].[IDCopyOf], [t15].[RegDate], [t15].[CreatedById], [t15].[DemoLinkEnabled], [t15].[Derivative], [t15].[Comments], [t15].[DisplayFeaturesTab], [t15].[DisplaySupportTab], [t15].[DocumentLinkEnabled], [t15].[EnableCancellation], [t15].[EnableTermsOfUse], [t15].[FilePath], [t15].[FullDescription], [t15].[IsActivated], [t15].[IsAddon], [t15].[IsAvailableViaPriceList], [t15].[IsBundle], [t15].[IsDeleted], [t15].[IsEnabled], [t15].[IsFeatured], [t15].[IsNew], [t15].[IsProductGroup], [t15].[KeyWords], [t15].[Name], [t15].[NoIndex], [t15].[OrganizationId], [t15].[OverviewPage], [t15].[IDPriceCategory], [t15].[Source], [t15].[IDProductType], [t15].[ProrataBilling], [t15].[IDResponsibleUser], [t15].[ScreenshotLinkEnabled], [t15].[ShortDescription], [t15].[SupportOptions], [t15].[TermsOfUse], [t15].[IDUnitCategory], [t15].[ModifiedDate], [t15].[LastUpdateID], [t15].[WebCatalogueEnabled], [t15].[WebComEnabled], [t15].[WebOfferEnabled], [t15].[WebOrderEnabled], [t15].[ChargeType], [t15].[CompetitionComments], [t15].[IgnoreProrata], [t15].[IsCompetitive], [t15].[IsNegative], [t15].[IsTaxable], [t15].[NoOfDecimals], [t15].[IDPricelist], [t15].[IdProductGroup], [t15].[SKU], [t15].[IDUnitType], [t15].[BillingOption], [t15].[IDDiscountList], [t15].[AllowsCustomEndDate], [t15].[BillingModel], [t15].[EnableTrialVariations], [t15].[ExternalBilling], [t15].[ExternalBillingType], [t15].[IdExternalPricing], [t15].[FreePeriodEnabled], [t15].[IDOrgSystem], [t15].[OverageOption], [t15].[RequestType], [t15].[SyncSignature], [t15].[IDSyncStatus], [t15].[TrialDuration], [t15].[TrialDurationType], [t15].[TrialNo], [t15].[TrialType], [t15].[UserProvEnabled], [t15].[IsBillingFrequencyEnabled], [t15].[RampUpPeriods], [t15].[IDResource], [t15].[IDResourceVariation], [t15].[SupportsMonthlyBillingFrequency], [t15].[IDHostingAddOn], [t15].[Id0], [t15].[CreatedDate], [t15].[CreatedByID0], [t15].[Description], [t15].[IdCopyOf0], [t15].[IsActive], [t15].[IsDeleted0], [t15].[Name0], [t15].[OrganizationId0], [t15].[SystemType], [t15].[LastUpdate], [t15].[LastUpdateId0], [t15].[Id1], [t15].[BaseQuantity], [t15].[IDCopyOf1], [t15].[DecimalPlacesNo], [t15].[Duration], [t15].[DurationType], [t15].[IsActive0], [t15].[IsDeleted1], [t15].[Mnemonic], [t15].[Name1], [t15].[IDUnitCategory0], [t15].[Quantity], [t15].[SystemType0], [t15].[c], [t15].[Id2], [t15].[BaseQuantity0], [t15].[IDCopyOf2], [t15].[DecimalPlacesNo0], [t15].[Duration0], [t15].[DurationType0], [t15].[IsActive1], [t15].[IsDeleted2], [t15].[Mnemonic0], [t15].[Name2], [t15].[IDUnitCategory1], [t15].[Quantity0], [t15].[SystemType1], [t15].[Id3], [t15].[BaseQuantity1], [t15].[IDCopyOf3], [t15].[DecimalPlacesNo1], [t15].[Duration1], [t15].[DurationType1], [t15].[IsActive2], [t15].[IsDeleted3], [t15].[Mnemonic1], [t15].[Name3], [t15].[IDUnitCategory2], [t15].[Quantity1], [t15].[SystemType2], [t15].[Id4], [t15].[BaseQuantity2], [t15].[IDCopyOf4], [t15].[DecimalPlacesNo2], [t15].[Duration2], [t15].[DurationType2], [t15].[IsActive3], [t15].[IsDeleted4], [t15].[Mnemonic2], [t15].[Name4], [t15].[IDUnitCategory3], [t15].[Quantity2], [t15].[SystemType3], [t15].[Id5], [t15].[BaseQuantity3], [t15].[IDCopyOf5], [t15].[DecimalPlacesNo3], [t15].[Duration3], [t15].[DurationType3], [t15].[IsActive4], [t15].[IsDeleted5], [t15].[Mnemonic3], [t15].[Name5], [t15].[IDUnitCategory4], [t15].[Quantity3], [t15].[SystemType4], [t15].[Id6], [t15].[BaseQuantity4], [t15].[IDCopyOf6], [t15].[DecimalPlacesNo4], [t15].[Duration4], [t15].[DurationType4], [t15].[IsActive5], [t15].[IsDeleted6], [t15].[Mnemonic4], [t15].[Name6], [t15].[IDUnitCategory5], [t15].[Quantity4], [t15].[SystemType5], [t15].[Id7], [t15].[BaseQuantity5], [t15].[IDCopyOf7], [t15].[DecimalPlacesNo5], [t15].[Duration5], [t15].[DurationType5], [t15].[IsActive6], [t15].[IsDeleted7], [t15].[Mnemonic5], [t15].[Name7], [t15].[IDUnitCategory6], [t15].[Quantity5], [t15].[SystemType6]
FROM (
    SELECT TOP(25) [t].[Id], [t].[IDCopyOf], [t].[CreatedDate], [t].[CreatedByID], [t].[Description], [t].[IsDeleted], [t].[Name], [t].[OrganizationId], [t].[LastUpdate], [t].[LastUpdateID]
    FROM [tblPriceCategory] AS [t] WITH (NOLOCK)
    WHERE [t].[OrganizationId] = 1 AND [t].[Id] IN ('29bb1ded-4887-43b7-84b2-94769721edbd', '7bb75da4-14ac-44bf-923b-df513a9505bf', '49413e3e-91d4-4709-8062-6d68cb9f4961', 'c0c52261-2bf6-4650-a96b-b252a9239d8e', 'da794453-be10-4b63-94f6-4654b4c14da9') AND [t].[IsDeleted] = 0
    ORDER BY [t].[Id]
) AS [t0]
OUTER APPLY (
    SELECT [t1].[Id], [t1].[ActivateAllUnits], [t1].[IDCategory], [t1].[ChargeRule], [t1].[Discriminator], [t1].[IDCopyOf], [t1].[RegDate], [t1].[CreatedById], [t1].[DemoLinkEnabled], [t1].[Derivative], [t1].[Comments], [t1].[DisplayFeaturesTab], [t1].[DisplaySupportTab], [t1].[DocumentLinkEnabled], [t1].[EnableCancellation], [t1].[EnableTermsOfUse], [t1].[FilePath], [t1].[FullDescription], [t1].[IsActivated], [t1].[IsAddon], [t1].[IsAvailableViaPriceList], [t1].[IsBundle], [t1].[IsDeleted], [t1].[IsEnabled], [t1].[IsFeatured], [t1].[IsNew], [t1].[IsProductGroup], [t1].[KeyWords], [t1].[Name], [t1].[NoIndex], [t1].[OrganizationId], [t1].[OverviewPage], [t1].[IDPriceCategory], [t1].[Source], [t1].[IDProductType], [t1].[ProrataBilling], [t1].[IDResponsibleUser], [t1].[ScreenshotLinkEnabled], [t1].[ShortDescription], [t1].[SupportOptions], [t1].[TermsOfUse], [t1].[IDUnitCategory], [t1].[ModifiedDate], [t1].[LastUpdateID], [t1].[WebCatalogueEnabled], [t1].[WebComEnabled], [t1].[WebOfferEnabled], [t1].[WebOrderEnabled], [t1].[ChargeType], [t1].[CompetitionComments], [t1].[IgnoreProrata], [t1].[IsCompetitive], [t1].[IsNegative], [t1].[IsTaxable], [t1].[NoOfDecimals], [t1].[IDPricelist], [t1].[IdProductGroup], [t1].[SKU], [t1].[IDUnitType], [t1].[BillingOption], [t1].[IDDiscountList], [t1].[AllowsCustomEndDate], [t1].[BillingModel], [t1].[EnableTrialVariations], [t1].[ExternalBilling], [t1].[ExternalBillingType], [t1].[IdExternalPricing], [t1].[FreePeriodEnabled], [t1].[IDOrgSystem], [t1].[OverageOption], [t1].[RequestType], [t1].[SyncSignature], [t1].[IDSyncStatus], [t1].[TrialDuration], [t1].[TrialDurationType], [t1].[TrialNo], [t1].[TrialType], [t1].[UserProvEnabled], [t1].[IsBillingFrequencyEnabled], [t1].[RampUpPeriods], [t1].[IDResource], [t1].[IDResourceVariation], [t1].[SupportsMonthlyBillingFrequency], [t1].[IDHostingAddOn], [t2].[Id] AS [Id0], [t2].[CreatedDate], [t2].[CreatedByID] AS [CreatedByID0], [t2].[Description], [t2].[IdCopyOf] AS [IdCopyOf0], [t2].[IsActive], [t2].[IsDeleted] AS [IsDeleted0], [t2].[Name] AS [Name0], [t2].[OrganizationId] AS [OrganizationId0], [t2].[SystemType], [t2].[LastUpdate], [t2].[LastUpdateId] AS [LastUpdateId0], [t3].[Id] AS [Id1], [t3].[BaseQuantity], [t3].[IDCopyOf] AS [IDCopyOf1], [t3].[DecimalPlacesNo], [t3].[Duration], [t3].[DurationType], [t3].[IsActive] AS [IsActive0], [t3].[IsDeleted] AS [IsDeleted1], [t3].[Mnemonic], [t3].[Name] AS [Name1], [t3].[IDUnitCategory] AS [IDUnitCategory0], [t3].[Quantity], [t3].[SystemType] AS [SystemType0], CASE
        WHEN [t2].[Id] IS NULL THEN CAST(1 AS bit)
        ELSE CAST(0 AS bit)
    END AS [c], [t4].[Id] AS [Id2], [t4].[BaseQuantity] AS [BaseQuantity0], [t4].[IDCopyOf] AS [IDCopyOf2], [t4].[DecimalPlacesNo] AS [DecimalPlacesNo0], [t4].[Duration] AS [Duration0], [t4].[DurationType] AS [DurationType0], [t4].[IsActive] AS [IsActive1], [t4].[IsDeleted] AS [IsDeleted2], [t4].[Mnemonic] AS [Mnemonic0], [t4].[Name] AS [Name2], [t4].[IDUnitCategory] AS [IDUnitCategory1], [t4].[Quantity] AS [Quantity0], [t4].[SystemType] AS [SystemType1], [t6].[Id] AS [Id3], [t6].[BaseQuantity] AS [BaseQuantity1], [t6].[IDCopyOf] AS [IDCopyOf3], [t6].[DecimalPlacesNo] AS [DecimalPlacesNo1], [t6].[Duration] AS [Duration1], [t6].[DurationType] AS [DurationType1], [t6].[IsActive] AS [IsActive2], [t6].[IsDeleted] AS [IsDeleted3], [t6].[Mnemonic] AS [Mnemonic1], [t6].[Name] AS [Name3], [t6].[IDUnitCategory] AS [IDUnitCategory2], [t6].[Quantity] AS [Quantity1], [t6].[SystemType] AS [SystemType2], [t7].[Id] AS [Id4], [t7].[BaseQuantity] AS [BaseQuantity2], [t7].[IDCopyOf] AS [IDCopyOf4], [t7].[DecimalPlacesNo] AS [DecimalPlacesNo2], [t7].[Duration] AS [Duration2], [t7].[DurationType] AS [DurationType2], [t7].[IsActive] AS [IsActive3], [t7].[IsDeleted] AS [IsDeleted4], [t7].[Mnemonic] AS [Mnemonic2], [t7].[Name] AS [Name4], [t7].[IDUnitCategory] AS [IDUnitCategory3], [t7].[Quantity] AS [Quantity2], [t7].[SystemType] AS [SystemType3], [t10].[Id] AS [Id5], [t10].[BaseQuantity] AS [BaseQuantity3], [t10].[IDCopyOf] AS [IDCopyOf5], [t10].[DecimalPlacesNo] AS [DecimalPlacesNo3], [t10].[Duration] AS [Duration3], [t10].[DurationType] AS [DurationType3], [t10].[IsActive] AS [IsActive4], [t10].[IsDeleted] AS [IsDeleted5], [t10].[Mnemonic] AS [Mnemonic3], [t10].[Name] AS [Name5], [t10].[IDUnitCategory] AS [IDUnitCategory4], [t10].[Quantity] AS [Quantity3], [t10].[SystemType] AS [SystemType4], [t11].[Id] AS [Id6], [t11].[BaseQuantity] AS [BaseQuantity4], [t11].[IDCopyOf] AS [IDCopyOf6], [t11].[DecimalPlacesNo] AS [DecimalPlacesNo4], [t11].[Duration] AS [Duration4], [t11].[DurationType] AS [DurationType4], [t11].[IsActive] AS [IsActive5], [t11].[IsDeleted] AS [IsDeleted6], [t11].[Mnemonic] AS [Mnemonic4], [t11].[Name] AS [Name6], [t11].[IDUnitCategory] AS [IDUnitCategory5], [t11].[Quantity] AS [Quantity4], [t11].[SystemType] AS [SystemType5], [t14].[Id] AS [Id7], [t14].[BaseQuantity] AS [BaseQuantity5], [t14].[IDCopyOf] AS [IDCopyOf7], [t14].[DecimalPlacesNo] AS [DecimalPlacesNo5], [t14].[Duration] AS [Duration5], [t14].[DurationType] AS [DurationType5], [t14].[IsActive] AS [IsActive6], [t14].[IsDeleted] AS [IsDeleted7], [t14].[Mnemonic] AS [Mnemonic5], [t14].[Name] AS [Name7], [t14].[IDUnitCategory] AS [IDUnitCategory6], [t14].[Quantity] AS [Quantity5], [t14].[SystemType] AS [SystemType6]
    FROM (
        SELECT TOP(25) [t5].[Id], [t5].[ActivateAllUnits], [t5].[IDCategory], [t5].[ChargeRule], [t5].[Discriminator], [t5].[IDCopyOf], [t5].[RegDate], [t5].[CreatedById], [t5].[DemoLinkEnabled], [t5].[Derivative], [t5].[Comments], [t5].[DisplayFeaturesTab], [t5].[DisplaySupportTab], [t5].[DocumentLinkEnabled], [t5].[EnableCancellation], [t5].[EnableTermsOfUse], [t5].[FilePath], [t5].[FullDescription], [t5].[IsActivated], [t5].[IsAddon], [t5].[IsAvailableViaPriceList], [t5].[IsBundle], [t5].[IsDeleted], [t5].[IsEnabled], [t5].[IsFeatured], [t5].[IsNew], [t5].[IsProductGroup], [t5].[KeyWords], [t5].[Name], [t5].[NoIndex], [t5].[OrganizationId], [t5].[OverviewPage], [t5].[IDPriceCategory], [t5].[Source], [t5].[IDProductType], [t5].[ProrataBilling], [t5].[IDResponsibleUser], [t5].[ScreenshotLinkEnabled], [t5].[ShortDescription], [t5].[SupportOptions], [t5].[TermsOfUse], [t5].[IDUnitCategory], [t5].[ModifiedDate], [t5].[LastUpdateID], [t5].[WebCatalogueEnabled], [t5].[WebComEnabled], [t5].[WebOfferEnabled], [t5].[WebOrderEnabled], [t5].[ChargeType], [t5].[CompetitionComments], [t5].[IgnoreProrata], [t5].[IsCompetitive], [t5].[IsNegative], [t5].[IsTaxable], [t5].[NoOfDecimals], [t5].[IDPricelist], [t5].[IdProductGroup], [t5].[SKU], [t5].[IDUnitType], [t5].[BillingOption], [t5].[IDDiscountList], [t5].[AllowsCustomEndDate], [t5].[BillingModel], [t5].[EnableTrialVariations], [t5].[ExternalBilling], [t5].[ExternalBillingType], [t5].[IdExternalPricing], [t5].[FreePeriodEnabled], [t5].[IDOrgSystem], [t5].[OverageOption], [t5].[RequestType], [t5].[SyncSignature], [t5].[IDSyncStatus], [t5].[TrialDuration], [t5].[TrialDurationType], [t5].[TrialNo], [t5].[TrialType], [t5].[UserProvEnabled], [t5].[IsBillingFrequencyEnabled], [t5].[RampUpPeriods], [t5].[IDResource], [t5].[IDResourceVariation], [t5].[SupportsMonthlyBillingFrequency], [t5].[IDHostingAddOn]
        FROM [tblProduct] AS [t5] WITH (NOLOCK)
        WHERE [t5].[Discriminator] IN (3, 0, 1) AND [t0].[Id] = [t5].[IDPriceCategory]
        ORDER BY [t5].[Id]
    ) AS [t1]
    LEFT JOIN [tblUnitCategory] AS [t2] WITH (NOLOCK) ON [t1].[IDUnitCategory] = [t2].[Id]
    LEFT JOIN [tblUnit] AS [t3] WITH (NOLOCK) ON [t2].[Id] = [t3].[IDUnitCategory]
    LEFT JOIN (
        SELECT [t8].[Id], [t8].[BaseQuantity], [t8].[IDCopyOf], [t8].[DecimalPlacesNo], [t8].[Duration], [t8].[DurationType], [t8].[IsActive], [t8].[IsDeleted], [t8].[Mnemonic], [t8].[Name], [t8].[IDUnitCategory], [t8].[Quantity], [t8].[SystemType]
        FROM (
            SELECT [t9].[Id], [t9].[BaseQuantity], [t9].[IDCopyOf], [t9].[DecimalPlacesNo], [t9].[Duration], [t9].[DurationType], [t9].[IsActive], [t9].[IsDeleted], [t9].[Mnemonic], [t9].[Name], [t9].[IDUnitCategory], [t9].[Quantity], [t9].[SystemType], ROW_NUMBER() OVER(PARTITION BY [t9].[IDUnitCategory] ORDER BY [t9].[Id]) AS [row]
            FROM [tblUnit] AS [t9] WITH (NOLOCK)
        ) AS [t8]
        WHERE [t8].[row] <= 25
    ) AS [t4] ON [t2].[Id] = [t4].[IDUnitCategory]
    LEFT JOIN [tblUnit] AS [t6] WITH (NOLOCK) ON [t2].[Id] = [t6].[IDUnitCategory]
    LEFT JOIN (
        SELECT [t12].[Id], [t12].[BaseQuantity], [t12].[IDCopyOf], [t12].[DecimalPlacesNo], [t12].[Duration], [t12].[DurationType], [t12].[IsActive], [t12].[IsDeleted], [t12].[Mnemonic], [t12].[Name], [t12].[IDUnitCategory], [t12].[Quantity], [t12].[SystemType]
        FROM (
            SELECT [t13].[Id], [t13].[BaseQuantity], [t13].[IDCopyOf], [t13].[DecimalPlacesNo], [t13].[Duration], [t13].[DurationType], [t13].[IsActive], [t13].[IsDeleted], [t13].[Mnemonic], [t13].[Name], [t13].[IDUnitCategory], [t13].[Quantity], [t13].[SystemType], ROW_NUMBER() OVER(PARTITION BY [t13].[IDUnitCategory] ORDER BY [t13].[Id]) AS [row]
            FROM [tblUnit] AS [t13] WITH (NOLOCK)
        ) AS [t12]
        WHERE [t12].[row] <= 25
    ) AS [t7] ON [t2].[Id] = [t7].[IDUnitCategory]
    LEFT JOIN [tblUnit] AS [t10] WITH (NOLOCK) ON [t2].[Id] = [t10].[IDUnitCategory]
    LEFT JOIN (
        SELECT [t16].[Id], [t16].[BaseQuantity], [t16].[IDCopyOf], [t16].[DecimalPlacesNo], [t16].[Duration], [t16].[DurationType], [t16].[IsActive], [t16].[IsDeleted], [t16].[Mnemonic], [t16].[Name], [t16].[IDUnitCategory], [t16].[Quantity], [t16].[SystemType]
        FROM (
            SELECT [t17].[Id], [t17].[BaseQuantity], [t17].[IDCopyOf], [t17].[DecimalPlacesNo], [t17].[Duration], [t17].[DurationType], [t17].[IsActive], [t17].[IsDeleted], [t17].[Mnemonic], [t17].[Name], [t17].[IDUnitCategory], [t17].[Quantity], [t17].[SystemType], ROW_NUMBER() OVER(PARTITION BY [t17].[IDUnitCategory] ORDER BY [t17].[Id]) AS [row]
            FROM [tblUnit] AS [t17] WITH (NOLOCK)
        ) AS [t16]
        WHERE [t16].[row] <= 25
    ) AS [t11] ON [t2].[Id] = [t11].[IDUnitCategory]
    LEFT JOIN [tblUnit] AS [t14] WITH (NOLOCK) ON [t2].[Id] = [t14].[IDUnitCategory]
) AS [t15]
ORDER BY [t0].[Id], [t15].[Id], [t15].[Id0], [t15].[Id1], [t15].[IDUnitCategory1], [t15].[Id2], [t15].[Id3], [t15].[IDUnitCategory3], [t15].[Id4], [t15].[Id5], [t15].[IDUnitCategory5], [t15].[Id6]

bkoelman · 2025-05-23T11:43:02Z

That looks awful :)

Possibly caused by #1641. Can you try turning off pagination in options and see if that helps?

Another thing to inspect (with pagination enabled) would be to compare QueryLayer.ToString() in EntityFrameworkCoreRepository.ApplyQueryLayer. Unfortunately, we don't log that yet, so it requires building from source.

JohnStrim · 2025-05-24T11:26:15Z

@bkoelman Tried to apply your idea of turning off Pagination by setting DefaultPageSize = null, which wouldn't apply much in our scenarios since we are using this api to fill client Datagrids that use pagination. The change did affect the query but the end result is the same, in other words still produces a Timeout...
Here are the logs:

[11:13:40 WRN] Compiling a query which loads related collections for more than one collection navigation, either via 'Include' or through projection, but no 'QuerySplittingBehavior' has been configured. By default, Entity Framework will use 'QuerySplittingBehavior.SingleQuery', which can potentially result in slow query performance. See https://go.microsoft.com/fwlink/?linkid=2134277 for more information. To identify the query that's triggering this warning call 'ConfigureWarnings(w => w.Throw(RelationalEventId.MultipleCollectionIncludeWarning))'.
[11:14:11 ERR] Failed executing DbCommand (30,032ms) [Parameters=[@__organizationId_0='?' (DbType = Int32), @__value_1='?' (DbType = Int32)], CommandType='Text', CommandTimeout='30']
SELECT [t].[Id], [t].[IDCopyOf], [t].[CreatedDate], [t].[CreatedByID], [t].[Description], [t].[IsDeleted], [t].[Name], [t].[OrganizationId], [t].[LastUpdate], [t].[LastUpdateID], [t8].[Id], [t8].[ActivateAllUnits], [t8].[IDCategory], [t8].[ChargeRule], [t8].[Discriminator], [t8].[IDCopyOf], [t8].[RegDate], [t8].[CreatedById], [t8].[DemoLinkEnabled], [t8].[Derivative], [t8].[Comments], [t8].[DisplayFeaturesTab], [t8].[DisplaySupportTab], [t8].[DocumentLinkEnabled], [t8].[EnableCancellation], [t8].[EnableTermsOfUse], [t8].[FilePath], [t8].[FullDescription], [t8].[IsActivated], [t8].[IsAddon], [t8].[IsAvailableViaPriceList], [t8].[IsBundle], [t8].[IsDeleted], [t8].[IsEnabled], [t8].[IsFeatured], [t8].[IsNew], [t8].[IsProductGroup], [t8].[KeyWords], [t8].[Name], [t8].[NoIndex], [t8].[OrganizationId], [t8].[OverviewPage], [t8].[IDPriceCategory], [t8].[Source], [t8].[IDProductType], [t8].[ProrataBilling], [t8].[IDResponsibleUser], [t8].[ScreenshotLinkEnabled], [t8].[ShortDescription], [t8].[SupportOptions], [t8].[TermsOfUse], [t8].[IDUnitCategory], [t8].[ModifiedDate], [t8].[LastUpdateID], [t8].[WebCatalogueEnabled], [t8].[WebComEnabled], [t8].[WebOfferEnabled], [t8].[WebOrderEnabled], [t8].[ChargeType], [t8].[CompetitionComments], [t8].[IgnoreProrata], [t8].[IsCompetitive], [t8].[IsNegative], [t8].[IsTaxable], [t8].[NoOfDecimals], [t8].[IDPricelist], [t8].[IdProductGroup], [t8].[SKU], [t8].[IDUnitType], [t8].[BillingOption], [t8].[IDDiscountList], [t8].[AllowsCustomEndDate], [t8].[BillingModel], [t8].[EnableTrialVariations], [t8].[ExternalBilling], [t8].[ExternalBillingType], [t8].[IdExternalPricing], [t8].[FreePeriodEnabled], [t8].[IDOrgSystem], [t8].[OverageOption], [t8].[RequestType], [t8].[SyncSignature], [t8].[IDSyncStatus], [t8].[TrialDuration], [t8].[TrialDurationType], [t8].[TrialNo], [t8].[TrialType], [t8].[UserProvEnabled], [t8].[IsBillingFrequencyEnabled], [t8].[RampUpPeriods], [t8].[IDResource], [t8].[IDResourceVariation], [t8].[SupportsMonthlyBillingFrequency], [t8].[IDHostingAddOn], [t8].[Id0], [t8].[CreatedDate], [t8].[CreatedByID0], [t8].[Description], [t8].[IdCopyOf0], [t8].[IsActive], [t8].[IsDeleted0], [t8].[Name0], [t8].[OrganizationId0], [t8].[SystemType], [t8].[LastUpdate], [t8].[LastUpdateId0], [t8].[Id1], [t8].[BaseQuantity], [t8].[IDCopyOf1], [t8].[DecimalPlacesNo], [t8].[Duration], [t8].[DurationType], [t8].[IsActive0], [t8].[IsDeleted1], [t8].[Mnemonic], [t8].[Name1], [t8].[IDUnitCategory0], [t8].[Quantity], [t8].[SystemType0], [t8].[c], [t8].[Id2], [t8].[BaseQuantity0], [t8].[IDCopyOf2], [t8].[DecimalPlacesNo0], [t8].[Duration0], [t8].[DurationType0], [t8].[IsActive1], [t8].[IsDeleted2], [t8].[Mnemonic0], [t8].[Name2], [t8].[IDUnitCategory1], [t8].[Quantity0], [t8].[SystemType1], [t8].[Id3], [t8].[BaseQuantity1], [t8].[IDCopyOf3], [t8].[DecimalPlacesNo1], [t8].[Duration1], [t8].[DurationType1], [t8].[IsActive2], [t8].[IsDeleted3], [t8].[Mnemonic1], [t8].[Name3], [t8].[IDUnitCategory2], [t8].[Quantity1], [t8].[SystemType2], [t8].[Id4], [t8].[BaseQuantity2], [t8].[IDCopyOf4], [t8].[DecimalPlacesNo2], [t8].[Duration2], [t8].[DurationType2], [t8].[IsActive3], [t8].[IsDeleted4], [t8].[Mnemonic2], [t8].[Name4], [t8].[IDUnitCategory3], [t8].[Quantity2], [t8].[SystemType3], [t8].[Id5], [t8].[BaseQuantity3], [t8].[IDCopyOf5], [t8].[DecimalPlacesNo3], [t8].[Duration3], [t8].[DurationType3], [t8].[IsActive4], [t8].[IsDeleted5], [t8].[Mnemonic3], [t8].[Name5], [t8].[IDUnitCategory4], [t8].[Quantity3], [t8].[SystemType4], [t8].[Id6], [t8].[BaseQuantity4], [t8].[IDCopyOf6], [t8].[DecimalPlacesNo4], [t8].[Duration4], [t8].[DurationType4], [t8].[IsActive5], [t8].[IsDeleted6], [t8].[Mnemonic4], [t8].[Name6], [t8].[IDUnitCategory5], [t8].[Quantity4], [t8].[SystemType5], [t8].[Id7], [t8].[BaseQuantity5], [t8].[IDCopyOf7], [t8].[DecimalPlacesNo5], [t8].[Duration5], [t8].[DurationType5], [t8].[IsActive6], [t8].[IsDeleted7], [t8].[Mnemonic5], [t8].[Name7], [t8].[IDUnitCategory6], [t8].[Quantity5], [t8].[SystemType6]
FROM [tblPriceCategory] AS [t] WITH (NOLOCK)
LEFT JOIN (
    SELECT [t0].[Id], [t0].[ActivateAllUnits], [t0].[IDCategory], [t0].[ChargeRule], [t0].[Discriminator], [t0].[IDCopyOf], [t0].[RegDate], [t0].[CreatedById], [t0].[DemoLinkEnabled], [t0].[Derivative], [t0].[Comments], [t0].[DisplayFeaturesTab], [t0].[DisplaySupportTab], [t0].[DocumentLinkEnabled], [t0].[EnableCancellation], [t0].[EnableTermsOfUse], [t0].[FilePath], [t0].[FullDescription], [t0].[IsActivated], [t0].[IsAddon], [t0].[IsAvailableViaPriceList], [t0].[IsBundle], [t0].[IsDeleted], [t0].[IsEnabled], [t0].[IsFeatured], [t0].[IsNew], [t0].[IsProductGroup], [t0].[KeyWords], [t0].[Name], [t0].[NoIndex], [t0].[OrganizationId], [t0].[OverviewPage], [t0].[IDPriceCategory], [t0].[Source], [t0].[IDProductType], [t0].[ProrataBilling], [t0].[IDResponsibleUser], [t0].[ScreenshotLinkEnabled], [t0].[ShortDescription], [t0].[SupportOptions], [t0].[TermsOfUse], [t0].[IDUnitCategory], [t0].[ModifiedDate], [t0].[LastUpdateID], [t0].[WebCatalogueEnabled], [t0].[WebComEnabled], [t0].[WebOfferEnabled], [t0].[WebOrderEnabled], [t0].[ChargeType], [t0].[CompetitionComments], [t0].[IgnoreProrata], [t0].[IsCompetitive], [t0].[IsNegative], [t0].[IsTaxable], [t0].[NoOfDecimals], [t0].[IDPricelist], [t0].[IdProductGroup], [t0].[SKU], [t0].[IDUnitType], [t0].[BillingOption], [t0].[IDDiscountList], [t0].[AllowsCustomEndDate], [t0].[BillingModel], [t0].[EnableTrialVariations], [t0].[ExternalBilling], [t0].[ExternalBillingType], [t0].[IdExternalPricing], [t0].[FreePeriodEnabled], [t0].[IDOrgSystem], [t0].[OverageOption], [t0].[RequestType], [t0].[SyncSignature], [t0].[IDSyncStatus], [t0].[TrialDuration], [t0].[TrialDurationType], [t0].[TrialNo], [t0].[TrialType], [t0].[UserProvEnabled], [t0].[IsBillingFrequencyEnabled], [t0].[RampUpPeriods], [t0].[IDResource], [t0].[IDResourceVariation], [t0].[SupportsMonthlyBillingFrequency], [t0].[IDHostingAddOn], [t1].[Id] AS [Id0], [t1].[CreatedDate], [t1].[CreatedByID] AS [CreatedByID0], [t1].[Description], [t1].[IdCopyOf] AS [IdCopyOf0], [t1].[IsActive], [t1].[IsDeleted] AS [IsDeleted0], [t1].[Name] AS [Name0], [t1].[OrganizationId] AS [OrganizationId0], [t1].[SystemType], [t1].[LastUpdate], [t1].[LastUpdateId] AS [LastUpdateId0], [t2].[Id] AS [Id1], [t2].[BaseQuantity], [t2].[IDCopyOf] AS [IDCopyOf1], [t2].[DecimalPlacesNo], [t2].[Duration], [t2].[DurationType], [t2].[IsActive] AS [IsActive0], [t2].[IsDeleted] AS [IsDeleted1], [t2].[Mnemonic], [t2].[Name] AS [Name1], [t2].[IDUnitCategory] AS [IDUnitCategory0], [t2].[Quantity], [t2].[SystemType] AS [SystemType0], CASE
        WHEN [t1].[Id] IS NULL THEN CAST(1 AS bit)
        ELSE CAST(0 AS bit)
    END AS [c], [t3].[Id] AS [Id2], [t3].[BaseQuantity] AS [BaseQuantity0], [t3].[IDCopyOf] AS [IDCopyOf2], [t3].[DecimalPlacesNo] AS [DecimalPlacesNo0], [t3].[Duration] AS [Duration0], [t3].[DurationType] AS [DurationType0], [t3].[IsActive] AS [IsActive1], [t3].[IsDeleted] AS [IsDeleted2], [t3].[Mnemonic] AS [Mnemonic0], [t3].[Name] AS [Name2], [t3].[IDUnitCategory] AS [IDUnitCategory1], [t3].[Quantity] AS [Quantity0], [t3].[SystemType] AS [SystemType1], [t4].[Id] AS [Id3], [t4].[BaseQuantity] AS [BaseQuantity1], [t4].[IDCopyOf] AS [IDCopyOf3], [t4].[DecimalPlacesNo] AS [DecimalPlacesNo1], [t4].[Duration] AS [Duration1], [t4].[DurationType] AS [DurationType1], [t4].[IsActive] AS [IsActive2], [t4].[IsDeleted] AS [IsDeleted3], [t4].[Mnemonic] AS [Mnemonic1], [t4].[Name] AS [Name3], [t4].[IDUnitCategory] AS [IDUnitCategory2], [t4].[Quantity] AS [Quantity1], [t4].[SystemType] AS [SystemType2], [t5].[Id] AS [Id4], [t5].[BaseQuantity] AS [BaseQuantity2], [t5].[IDCopyOf] AS [IDCopyOf4], [t5].[DecimalPlacesNo] AS [DecimalPlacesNo2], [t5].[Duration] AS [Duration2], [t5].[DurationType] AS [DurationType2], [t5].[IsActive] AS [IsActive3], [t5].[IsDeleted] AS [IsDeleted4], [t5].[Mnemonic] AS [Mnemonic2], [t5].[Name] AS [Name4], [t5].[IDUnitCategory] AS [IDUnitCategory3], [t5].[Quantity] AS [Quantity2], [t5].[SystemType] AS [SystemType3], [t6].[Id] AS [Id5], [t6].[BaseQuantity] AS [BaseQuantity3], [t6].[IDCopyOf] AS [IDCopyOf5], [t6].[DecimalPlacesNo] AS [DecimalPlacesNo3], [t6].[Duration] AS [Duration3], [t6].[DurationType] AS [DurationType3], [t6].[IsActive] AS [IsActive4], [t6].[IsDeleted] AS [IsDeleted5], [t6].[Mnemonic] AS [Mnemonic3], [t6].[Name] AS [Name5], [t6].[IDUnitCategory] AS [IDUnitCategory4], [t6].[Quantity] AS [Quantity3], [t6].[SystemType] AS [SystemType4], [t7].[Id] AS [Id6], [t7].[BaseQuantity] AS [BaseQuantity4], [t7].[IDCopyOf] AS [IDCopyOf6], [t7].[DecimalPlacesNo] AS [DecimalPlacesNo4], [t7].[Duration] AS [Duration4], [t7].[DurationType] AS [DurationType4], [t7].[IsActive] AS [IsActive5], [t7].[IsDeleted] AS [IsDeleted6], [t7].[Mnemonic] AS [Mnemonic4], [t7].[Name] AS [Name6], [t7].[IDUnitCategory] AS [IDUnitCategory5], [t7].[Quantity] AS [Quantity4], [t7].[SystemType] AS [SystemType5], [t9].[Id] AS [Id7], [t9].[BaseQuantity] AS [BaseQuantity5], [t9].[IDCopyOf] AS [IDCopyOf7], [t9].[DecimalPlacesNo] AS [DecimalPlacesNo5], [t9].[Duration] AS [Duration5], [t9].[DurationType] AS [DurationType5], [t9].[IsActive] AS [IsActive6], [t9].[IsDeleted] AS [IsDeleted7], [t9].[Mnemonic] AS [Mnemonic5], [t9].[Name] AS [Name7], [t9].[IDUnitCategory] AS [IDUnitCategory6], [t9].[Quantity] AS [Quantity5], [t9].[SystemType] AS [SystemType6]
    FROM [tblProduct] AS [t0] WITH (NOLOCK)
    LEFT JOIN [tblUnitCategory] AS [t1] WITH (NOLOCK) ON [t0].[IDUnitCategory] = [t1].[Id]
    LEFT JOIN [tblUnit] AS [t2] WITH (NOLOCK) ON [t1].[Id] = [t2].[IDUnitCategory]
    LEFT JOIN [tblUnit] AS [t3] WITH (NOLOCK) ON [t1].[Id] = [t3].[IDUnitCategory]
    LEFT JOIN [tblUnit] AS [t4] WITH (NOLOCK) ON [t1].[Id] = [t4].[IDUnitCategory]
    LEFT JOIN [tblUnit] AS [t5] WITH (NOLOCK) ON [t1].[Id] = [t5].[IDUnitCategory]
    LEFT JOIN [tblUnit] AS [t6] WITH (NOLOCK) ON [t1].[Id] = [t6].[IDUnitCategory]
    LEFT JOIN [tblUnit] AS [t7] WITH (NOLOCK) ON [t1].[Id] = [t7].[IDUnitCategory]
    LEFT JOIN [tblUnit] AS [t9] WITH (NOLOCK) ON [t1].[Id] = [t9].[IDUnitCategory]
    WHERE [t0].[Discriminator] IN (3, 0, 1)
) AS [t8] ON [t].[Id] = [t8].[IDPriceCategory]
WHERE [t].[OrganizationId] = @__organizationId_0 AND [t].[Id] IN ('29bb1ded-4887-43b7-84b2-94769721edbd', '7bb75da4-14ac-44bf-923b-df513a9505bf', '49413e3e-91d4-4709-8062-6d68cb9f4961', 'c0c52261-2bf6-4650-a96b-b252a9239d8e', 'da794453-be10-4b63-94f6-4654b4c14da9') AND [t].[IsDeleted] = @__value_1
ORDER BY [t].[Id], [t8].[Id], [t8].[Id0], [t8].[Id1], [t8].[Id2], [t8].[Id3], [t8].[Id4], [t8].[Id5], [t8].[Id6]

[11:14:11 ERR] An exception occurred while iterating over the results of a query for context type 'Iwcp.Rest.Infrastructure.Context.ApplicationDbContext'.
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): Unknown error 258
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__195_0(Task`1 result)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()
ClientConnectionId:baa17bd4-c795-4ca1-b6ca-4b4948c0f32f
Error Number:-2,State:0,Class:11
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): Unknown error 258
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__195_0(Task`1 result)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()
ClientConnectionId:baa17bd4-c795-4ca1-b6ca-4b4948c0f32f
Error Number:-2,State:0,Class:11

[11:14:11 ERR] Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
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): Unknown error 258
   at Task<DbDataReader> Microsoft.Data.SqlClient.SqlCommand.ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken)+(Task<SqlDataReader> result) => { }
   at void System.Threading.Tasks.ContinuationResultTaskFromResultTask<TAntecedentResult, TResult>.InnerInvoke()
   at async Task<RelationalDataReader> Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken) x 2
   at async Task<bool> Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable<T>+AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)
   at async Task<TResult> Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync<TState, TResult>(TState state, Func<DbContext, TState, CancellationToken, Task<TResult>> operation, Func<DbContext, TState, CancellationToken, Task<ExecutionResult<TResult>>> verifySucceeded, CancellationToken cancellationToken)
   at async ValueTask<bool> Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable<T>+AsyncEnumerator.MoveNextAsync()
   at async Task<List<TSource>> Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync<TSource>(IQueryable<TSource> source, CancellationToken cancellationToken) x 2
   at async Task<IReadOnlyCollection<TResource>> JsonApiDotNetCore.Repositories.EntityFrameworkCoreRepository<TResource, TId>.GetAsync(QueryLayer queryLayer, CancellationToken cancellationToken) in /_/src/JsonApiDotNetCore/Repositories/EntityFrameworkCoreRepository.cs:line 82
   at object CallSite.Target(Closure, CallSite, object)
   at TRet System.Dynamic.UpdateDelegates.UpdateAndExecute1<T0, TRet>(CallSite site, T0 arg0)
   at async Task<IReadOnlyCollection<TResource>> JsonApiDotNetCore.Repositories.ResourceRepositoryAccessor.GetAsync<TResource>(QueryLayer queryLayer, CancellationToken cancellationToken)
   at async Task<IReadOnlyCollection<TResource>> JsonApiDotNetCore.Services.JsonApiResourceService<TResource, TId>.GetAsync(CancellationToken cancellationToken) in /_/src/JsonApiDotNetCore/Services/JsonApiResourceService.cs:line 77
   at async Task<IActionResult> JsonApiDotNetCore.Controllers.BaseJsonApiController<TResource, TId>.GetAsync(CancellationToken cancellationToken) in /_/src/JsonApiDotNetCore/Controllers/BaseJsonApiController.cs:line 102
   at async Task<IActionResult> JsonApiDotNetCore.Controllers.JsonApiController<TResource, TId>.GetAsync(CancellationToken cancellationToken) in /_/src/JsonApiDotNetCore/Controllers/JsonApiController.cs:line 50
   at async ValueTask<IActionResult> Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor+TaskOfIActionResultExecutor.Execute(ActionContext actionContext, IActionResultTypeMapper mapper, ObjectMethodExecutor executor, object controller, object[] arguments)
   at async Task Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()+Awaited(?)
   at async Task Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()+Awaited(?)
   at void Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Task Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(ref State next, ref Scope scope, ref object state, ref bool isCompleted)
   at async Task Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()+Awaited(?)
   at async Task Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeNextExceptionFilterAsync()+Awaited(?)
ClientConnectionId:baa17bd4-c795-4ca1-b6ca-4b4948c0f32f
Error Number:-2,State:0,Class:11

[11:14:11 ERR] HTTP GET /v1/priceGroups responded 500 in 31345.5576 ms

Also here is the QueryLayer.ToString() when pagination is not set to null but also is not specifically set in the query string. It appears to be correct in my opinion and similar to logs we were originally getting and we sent in previous messages

QueryLayer<PriceGroup>
{
  Filter: and(any(id,'29BB1DED-4887-43B7-84B2-94769721EDBD','49413E3E-91D4-4709-8062-6D68CB9F4961','7BB75DA4-14AC-44BF-923B-DF513A9505BF','C0C52261-2BF6-4650-A96B-B252A9239D8E','DA794453-BE10-4B63-94F6-4654B4C14DA9'),equals(isDeleted,'false'))
}

JohnStrim · 2025-05-24T11:28:44Z

@bkoelman since it appears to be a bug of 5.7.0 and 5.7.1 versions may I suggest turning this issue into a bug and handling it this was? We have paused our version update until this is resolved. Please let us know if we can provide any further insight or assistance on resolving this since this is block us as well.

bkoelman · 2025-05-24T12:43:25Z

I'm surprised by that query layer (assuming it originates from JADNC v5.7.1). I would have expected to see multiple field selectors (one per derived type), with pagination inside them. But it also has no includes, so it doesn't seem to represent the original problematic request with both a filter and includes. The initial log file contains "HTTP GET /v1/priceGroups", which doesn't have query string parameters, but they may have been trimmed off in logs for redaction.

Can you confirm that the QueryLayer originates from the request URL /v1/priceGroupsfilter=and(any(id,'XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX','XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX','XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX',XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX','XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX'),equals(isDeleted,'false'))&include=products.unitGroup.units using JADNC v5.7.1? If not, please provide the appropriate one.

I don't know yet whether this is a bug or intended behavior. That doesn't mean I won't try to help you, but I need to understand the root cause first. Based on that, maybe JADNC can provide extra configuration settings to prevent this from happening, assuming the query becomes too complex for SQL Server to handle. But I'm just guessing now.

It's hard for me to track what's happening, ie. I don't know the data model and its inheritance hierarchy. Would it be possible to create a minimal repro that I can debug, in the form of a git repo? Then I can analyze the query layer, the resulting LINQ expression, and its SQL, and compare those with the old version of JADNC. I also wonder if the problem is specific to SQL Server. Seeding the minimal repro with sample data should be easy with Bogus Faker, which we already use for integration tests.

Please Notice that even EF Core has now provided new warnings after the update and If I were to show you the full query you could see that it trippled in its size...

Based on the conversations at dotnet/efcore#29182 and dotnet/efcore#29665, this warning may not be appropriate; the "solution" to activate query splitting may actually make the situation worse. I recommend ignoring this warning while trying to identify the root cause of the problem.

bkoelman · 2025-05-25T11:15:14Z

Well, I suspect the printed QueryLayer is from the CountAsync() method, not from GetAsync().

I've merged a PR that logs both QueryLayer and the resulting LINQ expression at Debug level. Turns out that earlier versions already log QueryLayer at Trace level.

See the instructions at #1732 for how to activate it. It should become available shortly for download using https://github.com/json-api-dotnet/JsonApiDotNetCore?tab=readme-ov-file#trying-out-the-latest-build.

JohnStrim · 2025-05-26T10:18:20Z

@bkoelman here is a dummy repo that demonstrates issue: https://github.com/JohnStrim/JsonApiBugReport/tree/master
See instructions on Readme how generate the scenario.
If you need anything else let me know

JohnStrim added the question label May 23, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

Update of 5.6 to 5.7.1 causes lots of Timeout in include queries #1731

Update of 5.6 to 5.7.1 causes lots of Timeout in include queries #1731

JohnStrim commented May 23, 2025

JohnStrim commented May 23, 2025

Uh oh!

bkoelman commented May 23, 2025

Uh oh!

JohnStrim commented May 23, 2025

Uh oh!

JohnStrim commented May 23, 2025

Uh oh!

bkoelman commented May 23, 2025

Uh oh!

JohnStrim commented May 24, 2025

Uh oh!

JohnStrim commented May 24, 2025

Uh oh!

bkoelman commented May 24, 2025

Uh oh!

bkoelman commented May 25, 2025

Uh oh!

JohnStrim commented May 26, 2025

Uh oh!