Slow compilation when using many .ThenInclude()'s

[dharmaturtle]

In EFCore3 Preview 7 onwards, there is a significant slow down when I have a query with many .ThenInclude()s, e.g.

new WhyYouSoSlowDb(options)
        .Blog
        .Include(x => x.Posts)
          .ThenInclude(x => x.PostInstances)
          .ThenInclude(x => x.Comments)
          .ThenInclude(x => x.AcquiredComments)
          .ThenInclude(x => x.Tag_AcquiredComments)
          .ThenInclude(x => x.Tag)
        .FirstOrDefault();

The above takes 20 seconds to run on an empty database. On EFCore3 Preview 5, it takes 1.5 seconds to run. (Preview 6 throws an exception.)

Steps to reproduce

Repo available here. Note that some amount of complexity is required to reproduce this issue - if you delete the 5 unreferenced properties from AcquiredCommentEntity, it will take 10 seconds to run.

Further technical details

EF Core version: EFCore3 Preview 7 and 8
Database Provider: Microsoft.EntityFrameworkCore.SqlServer
Operating system: Windows 10
IDE: Visual Studio 2019 Preview

[smitpatel]

Few observations:

• Query compilations takes about 0.5 secs in preview5, 14 secs in preview8 & 20 secs in daily. Above mentioned figures are for cold query and not for cached entry.
• Runtimes are 0s, 4s, 4s respectively.
  Generated SQLs:
  Preview5

SELECT TOP(1) [x].[Id], [x].[Name], [x].[UserId]
FROM [Blog] AS [x]
ORDER BY [x].[Id]

Preview8+

SELECT [t].[Id], [t].[Name], [t].[UserId], [t6].[Id], [t6].[BlogId], [t6].[Description], [t6].[UserId], [t6].[Id0], [t6].[Created], [t6].[Hash], [t6].[IsDeleted], [t6].[Modified], [t6].[PostId], [t6].[Id00], [t6].[Index], [t6].[PostInstanceId], [t6].[TemplateId], [t6].[UserId0], [t6].[CommentId], [t6].[CommentState], [t6].[Created0], [t6].[IsDeleted0], [t6].[Meta], [t6].[Meta2], [t6].[MetaId], [t6].[TagId], [t6].[UserId00], [t6].[CommentId0], [t6].[Id000], [t6].[Name], [t6].[UserId000]
FROM (
    SELECT TOP(1) [b].[Id], [b].[Name], [b].[UserId]
    FROM [Blog] AS [b]
) AS [t]
LEFT JOIN (
    SELECT [p].[Id], [p].[BlogId], [p].[Description], [p].[UserId], [t5].[Id] AS [Id0], [t5].[Created], [t5].[Hash], [t5].[IsDeleted], [t5].[Modified], [t5].[PostId], [t5].[Id0] AS [Id00], [t5].[Index], [t5].[PostInstanceId], [t5].[TemplateId], [t5].[UserId] AS [UserId0], [t5].[CommentId], [t5].[CommentState], [t5].[Created0], [t5].[IsDeleted0], [t5].[Meta], [t5].[Meta2], [t5].[MetaId], [t5].[TagId], [t5].[UserId0] AS [UserId00], [t5].[CommentId0], [t5].[Id00] AS [Id000], [t5].[Name], [t5].[UserId00] AS [UserId000]
    FROM [Post] AS [p]
    LEFT JOIN (
        SELECT [p0].[Id], [p0].[Created], [p0].[Hash], [p0].[IsDeleted], [p0].[Modified], [p0].[PostId], [t4].[Id] AS [Id0], [t4].[Index], [t4].[PostInstanceId], [t4].[TemplateId], [t4].[UserId], [t4].[CommentId], [t4].[CommentState], [t4].[Created] AS [Created0], [t4].[IsDeleted] AS [IsDeleted0], [t4].[Meta], [t4].[Meta2], [t4].[MetaId], [t4].[TagId], [t4].[UserId0], [t4].[CommentId0], [t4].[Id0] AS [Id00], [t4].[Name], [t4].[UserId00]
        FROM [PostInstance] AS [p0]
        LEFT JOIN (
            SELECT [c].[Id], [c].[Index], [c].[PostInstanceId], [c].[TemplateId], [t3].[UserId], [t3].[CommentId], [t3].[CommentState], [t3].[Created], [t3].[IsDeleted], [t3].[Meta], [t3].[Meta2], [t3].[MetaId], [t3].[TagId], [t3].[UserId0], [t3].[CommentId0], [t3].[Id] AS [Id0], [t3].[Name], [t3].[UserId00]
            FROM [Comment] AS [c]
            LEFT JOIN (
                SELECT [a].[UserId], [a].[CommentId], [a].[CommentState], [a].[Created], [a].[IsDeleted], [a].[Meta], [a].[Meta2], [a].[MetaId], [t2].[TagId], [t2].[UserId] AS [UserId0], [t2].[CommentId] AS [CommentId0], [t2].[Id], [t2].[Name], [t2].[UserId0] AS [UserId00]
                FROM [AcquiredComment] AS [a]
                LEFT JOIN (
                    SELECT [t0].[TagId], [t0].[UserId], [t0].[CommentId], [t1].[Id], [t1].[Name], [t1].[UserId] AS [UserId0]
                    FROM [Tag_AcquiredComment] AS [t0]
                    INNER JOIN [Tag] AS [t1] ON [t0].[TagId] = [t1].[Id]
                ) AS [t2] ON ([a].[UserId] = [t2].[UserId]) AND ([a].[CommentId] = [t2].[CommentId])
            ) AS [t3] ON [c].[Id] = [t3].[CommentId]
        ) AS [t4] ON [p0].[Id] = [t4].[PostInstanceId]
    ) AS [t5] ON [p].[Id] = [t5].[PostId]
) AS [t6] ON [t].[Id] = [t6].[BlogId]
ORDER BY [t].[Id], [t6].[Id], [t6].[Id0], [t6].[Id00], [t6].[UserId0], [t6].[CommentId], [t6].[TagId], [t6].[UserId00], [t6].[CommentId0], [t6].[Id000]

The 2nd query is 7x time slower in SqlServer. (according to analyze plan).

• We do not have caching of generated SelectExpression yet. Given size of SQL query, it could easily contribute to time spent. See Query: Add caching of generated RelationalCommand based on nullability of parameters #15892
• The difference in generated SQL comes from single query design.
• Looking at code, if data reader is empty, we return immediately so nothing specific to shaper is affecting it.

My belief is #15892 will get us as close as we can get. Apart from that, there is no extra work we are doing which is not by design.

[dharmaturtle]

I tossed some dummy data into the database (2 rows for every table, and I deleted the hash column), and reran the test using Preview 5. The SQL Server profiler (eventually) seems to return the same SQL you pasted above, but much faster. Here's a video of me running the test. I agree that single query design is worth striving for, but it seems like Preview 5 was able to generate the necessary SQL (and then some) quite fast.

[smitpatel]

I agree that single query design is worth striving for, but it seems like Preview 5 was able to generate the necessary SQL (and then some) quite fast.

Running test for once is not a good metric to measure time due to query compilation.

Single Query design was not just about being fast or slow. It has a lot more issues than that including incorrect results in certain cases. See #12098 for detailed discussion and referenced issues from that which were bugs fixed by the design.

[dharmaturtle]

Lol, I went to the bathroom, and on the way I thought "the last sentence of your post doesn't follow." I come back intending to fix it, and you've already answered :)

It isn't clear to me why generating the Preview8+ SQL takes so much longer than the Preview5 SQL, especially since the Preview5 seems to eventually get there, but I'll dig into that thread. Thanks for the fast response!

[Enngage]

I started seeing this as well when upgrading from preview 5 to preview 8. Queries that took few hundred ms now take up to 2 minutes - that includes repeated tests. I'm not sure if caching helps in this case since I wouldn't really want to wait 2 minutes to get the data (though query has quite a few nested includes - see below).

Based on this discussion, is this something that is going to be addressed in next preview / final release or should we rewrite queries?

Edit:

Query I'm running goes something like this

await someQuery.DynamicInclude(new List<string>() {
    "CategoryA",
    "EntityACollection",
    "EntityACollection.CategoryB",
    "EntityACollection.EntityBCollection",
    "EntityACollection.EntityBCollection.EntityC",
    "EntityACollection.EntityBCollection.EntityC.CategoryB",
    "EntityACollection.EntityBCollection.EntityC.CategoryA",
    "EntityACollection.EntityBCollection.EntityC.EntityDCollection",
    "EntityACollection.EntityBCollection.EntityC.EntityDCollection.EntityC",
    "EntityACollection.EntityBCollection.EntityC.EntityDCollection.EntityC.CategoryA",
    })
    .FirstOrDefaultAsync();

Preview5: Compilation takes about 200 ms and execution time is around 5ms (local sql) - there are 4 distinct SQL Queries run against DB. Subsequent calls take < 10 ms.

Preview8: Compilation takes about 120 seconds and execution time is around 500ms (local sql) - everything is pulled in a single SQL Query. Subsequent calls are only marginally faster.

The DynamicInclude is just a simple wrapper around EntityFrameworkQueryableExtensions.Include.

In both cases I'm getting the same final results.

If I remove the last 2 includes such as:

await someQuery.DynamicInclude(new List<string>() {
    "CategoryA",
    "EntityACollection",
    "EntityACollection.CategoryB",
    "EntityACollection.EntityBCollection",
    "EntityACollection.EntityBCollection.EntityC",
    "EntityACollection.EntityBCollection.EntityC.CategoryB",
    "EntityACollection.EntityBCollection.EntityC.CategoryA",
    "EntityACollection.EntityBCollection.EntityC.EntityDCollection"
    })
    .FirstOrDefaultAsync();

The query now executes in 1 second for the first time and around 200 ms for subsequent calls. Its still far away from < 10 ms in the case of preview 5, but its a lot better.

I also tried using the latest rc-1 daily build, but that took pretty much the same time as preview8

Edit 2:

It seems I can narrow this down even further. Having a query like

await someQuery.DynamicInclude(new List<string>() {
    "EntityACollection.EntityBCollection.EntityC.EntityDCollection"
    })
    .FirstOrDefaultAsync();

performs pretty much the same as the top one (its 20 seconds faster).

[AndriySvyryd]

Related to #12632

[Enngage]

@AndriySvyryd I'm not sure if that is related as in #12632 the issue seems to be slow performing SQL queries and SQL timeouts, whereas in this case it is the query compilation that is slow. Actual SQL is quite fast (0.5s in my case) - though still slower then previous implementation in preview5.

[roji]

I did some further investigation; my SelectExpression optimizations above were OK but didn't address the root of the problem at all.

Profiling this code shows that SelectExpression.VisitChildren (as well as other visit methods) gets called an incredible number of times (upwards of 2 million times). The reason for this, is that all the projections in this query contain ColumnExpressions whose table is a reference to other SelectExpression. This causes repeated visitation of the same SelectExpression over and over, with the number of visitations increasing exponentially as more includes are added.

For example, here's the top-most select:

SELECT [t].[Id], [t].[Name], [t].[UserId], [t6].[Id], [t6].[BlogId], [t6].[Description], [t6].[UserId], [t6].[Id0], [t6].[Created], [t6].[Hash], [t6].[IsDeleted], [t6].[Modified], [t6].[PostId], [t6].[Id00], [t6].[Index], [t6].[PostInstanceId], [t6].[TemplateId], [t6].[UserId0], [t6].[CommentId], [t6].[CommentState], [t6].[Created0], [t6].[IsDeleted0], [t6].[Meta], [t6].[Meta2], [t6].[MetaId], [t6].[TagId], [t6].[UserId00], [t6].[CommentId0], [t6].[Id000], [t6].[Name], [t6].[UserId000]

This SelectExpressions contains 28 projections to columns on [t6], which itself is a SelectExpression with a large number of projections over other SelectExpressions, and so forth recursively.

One immediate question this raises, is if we can simply replace the joins on subqueries with joins on the tables directly:

SELECT ...
FROM (
    SELECT TOP(1) [b].[Id], [b].[Name], [b].[UserId]
    FROM [Blog] AS [b]
) AS [t]
LEFT JOIN [Post] AS [t6] ON [t].[Id] = [t6].[BlogId]
LEFT JOIN [PostInstance] AS [t5] ON [p].[Id] = [t5].[PostId]
LEFT JOIN [Comment] AS [t4] ON [p0].[Id] = [t4].[PostInstanceId]
LEFT JOIN [AcquiredComment] AS [t3] ON [c].[Id] = [t3].[CommentId]
... and so on

This would likely also help runtime (or at least produce better SQL).

But the root problem would still remain for other cases, and to solve it we'd need to avoid re-visiting nodes that have already been visited. I have some thoughts on how we could do that (efficiently), but I wonder if we've already encountered this kind of issue and discussed it.