Entity Framework Core 3.1 is throwing a timeout exception for a query that when executed directly is fast

Question

I have a paged query that throws an time-out exception when executed by EF Core 3.1.

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

The in-code construction of the query:

Context.Invoices
.Include(i => i.InvoiceLines)
.Include(i => i.InvoiceFiles).ThenInclude(_ => _.File)
.Include(i => i.InvoiceExternalReferences).ThenInclude(_ => _.ReferenceSourceLookup)
.Skip(0).Take(100).AsQueryable()

The query generated by EF Core is:

SELECT
    [t].[Id]
    ,[t].[BookingDateConfirmedUtc]
    ,[t].[BookingDateUtc]
    ,[t].[Checksum]
    ,[t].[Created]
    ,[t].[CreditedInvoiceId]
    ,[t].[CreditingInvoiceId]
    ,[t].[CustomerReference]
    ,[t].[Date]
    ,[t].[ExportDateUtc]
    ,[t].[IsArchived]
    ,[t].[Language]
    ,[t].[LastModified]
    ,[t].[Memo]
    ,[t].[ReceiverId]
    ,[t].[Reference]
    ,[t].[ReferenceFactoryId]
    ,[t].[RelationId]
    ,[t].[SapInvoiceNumber]
    ,[t].[SdBillingDocument]
    ,[t].[SenderId]
    ,[t].[SubType]
    ,[t].[TotalVatAmount]
    ,[t].[Type]
    ,[t].[User]
    ,[t].[UserId]
    ,[t].[VolumeHigh]
    ,[t].[VolumeLow]
    ,[t].[VolumeTotalHours]
    ,[i0].[Id]
    ,[i0].[Amount]
    ,[i0].[AmountRounded]
    ,[i0].[Created]
    ,[i0].[DebugData]
    ,[i0].[Description]
    ,[i0].[FromUtc]
    ,[i0].[InvoiceArticleId]
    ,[i0].[InvoiceId]
    ,[i0].[IsArchived]
    ,[i0].[LastModified]
    ,[i0].[LineNumber]
    ,[i0].[LineType]
    ,[i0].[Price]
    ,[i0].[ProjectConnectionPointId]
    ,[i0].[Quantity]
    ,[i0].[RateCardBillingLineId]
    ,[i0].[ToUtc]
    ,[i0].[Unit]
    ,[i0].[User]
    ,[i0].[UserId]
    ,[i0].[VatPercentage]
    ,[t0].[InvoiceId]
    ,[t0].[FileId]
    ,[t0].[Id]
    ,[t0].[Created]
    ,[t0].[FilePath]
    ,[t0].[FileSize]
    ,[t0].[Filename]
    ,[t0].[IsArchived]
    ,[t0].[LastModified]
    ,[t0].[Remarks]
    ,[t0].[Type]
    ,[t0].[User]
    ,[t0].[UserId]
    ,[t1].[Id]
    ,[t1].[Created]
    ,[t1].[InitialSyncDate]
    ,[t1].[InvoiceId]
    ,[t1].[IsArchived]
    ,[t1].[LastModified]
    ,[t1].[LastSyncDate]
    ,[t1].[Reference]
    ,[t1].[ReferenceSourceLookupId]
    ,[t1].[SyncStatus]
    ,[t1].[User]
    ,[t1].[UserId]
    ,[t1].[Id0]
    ,[t1].[Created0]
    ,[t1].[Dutch]
    ,[t1].[English]
    ,[t1].[French]
    ,[t1].[IsArchived0]
    ,[t1].[IsSystem]
    ,[t1].[LastModified0]
    ,[t1].[Reference0]
    ,[t1].[Type]
    ,[t1].[User0]
    ,[t1].[UserId0]
FROM
(
    SELECT
        [i].[Id]
        ,[i].[BookingDateConfirmedUtc]
        ,[i].[BookingDateUtc]
        ,[i].[Checksum]
        ,[i].[Created]
        ,[i].[CreditedInvoiceId]
        ,[i].[CreditingInvoiceId]
        ,[i].[CustomerReference]
        ,[i].[Date]
        ,[i].[ExportDateUtc]
        ,[i].[IsArchived]
        ,[i].[Language]
        ,[i].[LastModified]
        ,[i].[Memo]
        ,[i].[ReceiverId]
        ,[i].[Reference]
        ,[i].[ReferenceFactoryId]
        ,[i].[RelationId]
        ,[i].[SapInvoiceNumber]
        ,[i].[SdBillingDocument]
        ,[i].[SenderId]
        ,[i].[SubType]
        ,[i].[TotalVatAmount]
        ,[i].[Type]
        ,[i].[User]
        ,[i].[UserId]
        ,[i].[VolumeHigh]
        ,[i].[VolumeLow]
        ,[i].[VolumeTotalHours]
    FROM [Invoices] AS [i]
    WHERE [i].[IsArchived] = CAST(0 AS bit)
    ORDER BY [i].[Reference]
    OFFSET 0 ROWS FETCH NEXT 100 ROWS ONLY
) AS [t]
LEFT JOIN [InvoiceLines] AS [i0] ON [t].[Id] = [i0].[InvoiceId]
LEFT JOIN
(
    SELECT
        [i1].[InvoiceId]
        ,[i1].[FileId]
        ,[f].[Id]
        ,[f].[Created]
        ,[f].[FilePath]
        ,[f].[FileSize]
        ,[f].[Filename]
        ,[f].[IsArchived]
        ,[f].[LastModified]
        ,[f].[Remarks]
        ,[f].[Type]
        ,[f].[User]
        ,[f].[UserId]
    FROM [InvoiceFiles] AS [i1]
    INNER JOIN [Files] AS [f] ON [i1].[FileId] = [f].[Id]
) AS [t0] ON [t].[Id] = [t0].[InvoiceId]
LEFT JOIN
(
    SELECT
        [i2].[Id]
        ,[i2].[Created]
        ,[i2].[InitialSyncDate]
        ,[i2].[InvoiceId]
        ,[i2].[IsArchived]
        ,[i2].[LastModified]
        ,[i2].[LastSyncDate]
        ,[i2].[Reference]
        ,[i2].[ReferenceSourceLookupId]
        ,[i2].[SyncStatus]
        ,[i2].[User]
        ,[i2].[UserId]
        ,[l].[Id] AS [Id0]
        ,[l].[Created] AS [Created0]
        ,[l].[Dutch]
        ,[l].[English]
        ,[l].[French]
        ,[l].[IsArchived] AS [IsArchived0]
        ,[l].[IsSystem]
        ,[l].[LastModified] AS [LastModified0]
        ,[l].[Reference] AS [Reference0]
        ,[l].[Type]
        ,[l].[User] AS [User0]
        ,[l].[UserId] AS [UserId0]
    FROM [InvoiceExternalReferences] AS [i2]
    INNER JOIN [Lookups] AS [l] ON [i2].[ReferenceSourceLookupId] = [l].[Id]
) AS [t1] ON [t].[Id] = [t1].[InvoiceId]
ORDER BY
    [t].[Reference]
    ,[t].[Id]
    ,[i0].[Id]
    ,[t0].[InvoiceId]
    ,[t0].[FileId]
    ,[t0].[Id]
    ,[t1].[Id]
    ,[t1].[Id0]

When I run this query directly to the database, I get an instant result but EF core is throwing a timeout exception.

user_371917 · Answer

UPDATE: Entity Framework Core 5 has split queries, and log warnings are generated when the query type is not specified.

Original Answer

The problem with timeouts is that as of Entity Framework Core 3.1, Include statements will no longer split into separate SQL queries (see the breaking changes discussion).

As an alternative to Load/LoadAsync (mentioned in the other answer), the solution that I went for was to use Include Optimised provided in Entity Framework Core Plus (see example and discussion). This will split each include section into its own individual SQL query.

At least for our situation, I think this solution is much less of a rewrite compared to Load/LoadAsync.

        // Code snippet copied and simplified from the example linked above.
        var sample = await dbContext.Projects
            // AsNoTracking() will not work here.
            .IncludeOptimized(z => z.Financial)
            .IncludeOptimized(z => z.SubProject)
            .IncludeOptimized(z => z.SubProject.EnergyAuditData) // if we omit this line it will not load any data unique to "EnergyAuditData", only "EnergyAuditAreas".
            .IncludeOptimized(z => z.SubProject.EnergyAuditData.EnergyAuditAreas)
            .IncludeOptimized(z => z.SubProject.BuildingTypes)
            .IncludeOptimized(z => z.SubProject.Buildings)
            .IncludeOptimized(z => z.SubProject.Buildings.Select(y => y.BuildingType))
            .IncludeOptimized(z => z.SubProject.Buildings.Select(y => y.Site))
            .IncludeOptimized(z => z.SubProject.CommonAreas)
            .IncludeOptimized(z => z.SubProject.CommonAreas.Select(y => y.Building)) // again, if we omit this line it will skip anything unique to "Building" and only load "Units".
            .IncludeOptimized(z => z.SubProject.CommonAreas.Select(y => y.Building).Select(z => z.Units))
            .FirstOrDefaultAsync(x => x.Id == project.Id);

user_5260872 · Answer

One potential improvement could be to execute one Load/LoadAsync per each navigation property. Try splitting up the query into multiple Include statements.

var invoices = await context.Invoices
.Include(i => i.InvoiceLines).LoadAsync();

await invoices.Include(i => i.InvoiceFiles).ThenInclude(_ => _.File).LoadAsync();

await invoices.Include(i => i.InvoiceExternalReferences).ThenInclude(_ => _.ReferenceSourceLookup)
.Skip(0).Take(100).ToListAsync();
return invoices.AsQueryable();

Entity Framework Core 3.1 is throwing a timeout exception for a query that when executed directly is fast

2 Answers