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.

[roji]

One immediate idea for fixing this... It may simply make sense to avoid visiting SelectExpressions (or even TableExpressions) embedded inside ProjectionExpressions - they are simply "references" to something that will get visited anyway via SelectExpression.Tables. In other words, the expression tree is in fact a DAG, and we can simply not traverse projection edges.

As a quick dirty test, I simply replaced ProjectionExpression.VisitChildren with a version that returns this, and compilation completes instantly. This is an incorrect fix because other parts of the ProjectionExpression still need to be visited, but it may point in the right direction.

[Enngage]

hey @roji, thanks a lot for looking into this! The sample SQL query you posted seems a lot better than what is currently being generated and would indeed perform better (I think).

This might also address the second issue I encounter initially - the call which evaluated in < 10 ms on SQL with preview5 takes 0.5s on preview8. Thanks again for support :-)

[smitpatel]

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.

#17337

[roji]

#17337

@smitpatel I was wondering how that's handled... But just to be sure - even if #17337 is fixed we would still have the issue of visiting the same SelectExpression many times, right? I mean, reconnecting nodes is orthogonal to not re-visiting them?

(but yeah, I can see how we'd probably handle both at the same time...)

[smitpatel]

reconnecting nodes is orthogonal to not re-visiting them?

How could you reconnect nodes when they are supposed to be same node? And if it same node then you have only visited it once.

[roji]

And if it same node then you have only visited it once.

Unless I'm mistaken, what's happening now is that SelectExpression.VisitChildren visits all projections, and then visits all tables/subqueries. Even if both these data structures pointed to the same instance, we'd still visit it more than once, no?

[smitpatel]

When both of them points to same instance, is the case when SelectExpression did not re-generate. Sure, it is not that bug and it would still cause performance issue. But the only way you can keep same instance after re-generation is not visit the same SelectExpression multiple times, (no matter where it appears so it can expand more than projection too). And that solves the perf issue already. #17337 already fixes perf issue and I don't see a reason to track it separately.

[roji]

Makes sense, thanks. I'll a note on the perf aspects in #17337, and we can close this as a dup of that?

[roji]

One more unrelated issue is the possibility I mentioned above of generating joins on tables directly instead of joins on sub-queries - do we have an issue tracking that already?

[smitpatel]

generating joins on tables directly instead of joins on sub-queries

I believe cost vs value does not meet bar to do it.

[roji]

generating joins on tables directly instead of joins on sub-queries

I believe cost vs value does not meet bar to do it.

Shouldn't we do a perf measurement to determine that? I mean execution, not compilation. Opened #17622 to track.

[NetTecture]

Will this be fixed for 3.0 release? Because I run projects that do 20-30 includes and if that is NOT fixed then basically the performance regression makes this update a total no go. I can not move queries from significantly sub 1 second EFCore handling to MINUTES.

Also re SQL: not meeting the bar is run - up to the point people actually have to DEBUG complex expression trees and the SQL looks like a nightmare compared to the clean SQL that was usus earlier.

[dragnilar]

@NetTecture I just checked the 3.0 release that came out yesterday, the problem is still there. Code shows the changes made from the commit are not present. I guess we and anyone else who has queries with multiple includes will have to wait. :(

[roji]

@dragnilar I've just taken the original repro above and changed it to reference EF Core 3.0.0 RTM, and it completed in under a second (with preview8 it took over 18 seconds). Can you please double-check your configuration and make sure you're using the RTM version?

[dragnilar]

@roji The good news is that my environment did have a problem, so after cleaning it up and redownloading the package, I made sure the code changes you made were present in the disassembly.

The bad news is that even with those changes, the query still performs worse than it does with EF Core 2.2.6 (over 30 seconds/timeout versus about 2-3 seconds).

Mine has significantly more Includes than the repro, so that may be one of the reasons why.

[roji]

@dragnilar thanks for the confirmation. This issue was about a extremely slow compilation of the query, which occurs only once at startup - I assume you're saying that your query executes more slowly, which is a different matter.

Note that EF Core 3.0 contains a significant change whereby a single LINQ query is executed via a single SQL query. In particular, this means that we now generate single-query JOINs in cases where we previously generated multiple queries (one per include), and the duplication of data inherent in joins may be slowing down your query.

Can you please open a separate issue with a small code sample, and if possible post the SQL generated from both 2.2.6 and 3.0?

[roji]

To clarify my previous comment, it isn't yet certain whether the problem you're seeing is a compilation or execution problem, so a minimal code sample would help us figure out what's going on.

[dragnilar]

@roji Thanks for the clarification. I noticed the compilation is faster (my integration tests and app looked hung before the query actually fired prior to your fix). I had a feeling in the back of my mind this was related to the significant change you mentioned, but I wasn't entirely sure yet if this issue's resolution would help.

I think you are correct though, I noticed the SQL being emitted by EF with 2.2.6 is being broken up into small queries versus 3.0 where it's one gargantuan query of joins.

[smitpatel]

For no data case, EF Core 2.2.6 is always going to be faster because of multiple SQL.
As for runtime, we still does not have catching of SQL command based on parameter nullability which was present in EF Core 2.2.6 so it would be somewhat slower but we plan to fix that in 3.1

[EliasBobadilla]

Hi!, I had a performance alert in the manager that I'm developing.
I added this warning: RelationalEventId.MultipleCollectionIncludeWarning, in my database context configuration to found where there are performance problems. After several tests I have identified that .ThenInclude is the one that triggers the alert, I am using EF Core 5.0.2

This is my Code:

var applications = await _repo.Application.All()
                .Include(x=> x.Toolkits)
                .ThenInclude(x => x.Tools) //when I remove this line I don't have performance alerts
                .ToListAsync();

Was anyone able to solve this performance issue?

[roji]

@EliasBobadilla take a look at this docs page to understand single vs. split queries. You may want to make that query use split queries, depending on how many Tools there typically are for each Toolkit (and also how many Toolkits for each Application).

[EliasBobadilla]

@EliasBobadilla take a look at this docs page to understand single vs. split queries. You may want to make that query use split queries, depending on how many Tools there typically are for each Toolkit (and also how many Toolkits for each Application).

thanks a lot @roji , I solved my problem and now I know how to better approach queries with multiple join in sql with Ef