Upgrading Entity Framework Core 2.2

How we debugged and fixed a performance issue related to EF Core 2.2 -> 3.1 upgrade

by Łukasz Wiśniewski, Principal Engineer

Recently at Signal, we updated one of the main dependencies in our front-end API / integration layer project. The package is Entity Framework Core, a popular ORM commonly found in ASP.NET Core projects.

We use a mix of Entity Framework Core and Dapper in this project, with EF Core handling migrations and a part of the DB queries. The decision whether to use Dapper or Entity Framework is based on a number of factors — how easy it is to write a query in one or another, are SQL Server specific features needed, is the DB an “internal” one or an “external”. But performance is rarely a factor for the front-end backing database. Given the small amount of data there we rarely tune the performance of the queries; they usually return within 10s of milliseconds.

Upgrade from version 2.2 directly to version 3.1 went smoothly:

• The breaking changes list did not indicate anything that could seriously affect our code, it seemed
• Only minimal code changes were needed and our integration test suite passed successfully

After successfully passing through our dev and test environments, the “upgrade” release was promoted to production.

Unfortunately, after a while we noticed a slowdown in some API calls — the slowdown was tracked to the EF Core upgrade.

Debugging

We found that one particular DB query was causing most of the slowdown.
The call usually took no more than ~50 ms, but now it was in the order of hundreds of milliseconds up to 1–2 seconds.

In code it looked similar to this:

_dbContext.Users
          .Include(u => u.Group)
          .Include(u => u.Company)
          .Include(u => u.Company.AccessLevels)
          .Include(u => u.Company.CurrentPlan)
          .Include(u => u.Metadata)
          .Include(u => u.Roles)
          .FirstOrDefaultAsync(u => u.Email == userEmail);

and seems to be innocent enough at a first glance.

After setting the Information log level on the Microsoft.EntityFrameworkCore namespace in an appsettings.json file:

{
  "Serilog": {
    "MinimumLevel": {
      "Override": {
        "Microsoft.EntityFrameworkCore": "Information"
      }
    }
  }
}

we were able to quickly find the difference between the queries generated in EF Core 2.2 and EF Core 3.1.

EF Core 2.2 generated SQL:

SELECT TOP(1) /* ... */
FROM [AspNetUsers] AS [u]
LEFT JOIN [Metadata] AS [u.Metadata] ON [u].[MetadataId] = [u.Metadata].[Id]
INNER JOIN [Companies] AS [u.Company] ON [u].[CompanyId] = [u.Company].[Id]
LEFT JOIN [Plans] AS [u.Company.CurrentPlan] ON [u.Company].[CurrentPlanId] = [u.Company.CurrentPlan].[Id]
LEFT JOIN [Groups] AS [u.Group] ON [u].[GroupId] = [u.Group].[Id]
WHERE [u].[Email] = N'user@example.com'
ORDER BY [u.Company].[Id], [u].[Id]
GO
-- Fetch 2nd level relations
SELECT /* ... */
FROM [CompanyAccessLevels] AS [u.Company.CompanyAccessLevels]
INNER JOIN (
    SELECT DISTINCT [t].*
    FROM (
        SELECT TOP(1) [u.Company0].[Id]
        FROM [AspNetUsers] AS [u0]
        LEFT JOIN [Metadata] AS [u.Metadata0] ON [u0].[MetadataId] = [u.Metadata0].[Id]
        INNER JOIN [Companies] AS [u.Company0] ON [u0].[CompanyId] = [u.Company0].[Id]
        LEFT JOIN [Plans] AS [u.Company.CurrentPlan0] ON [u.Company0].[CurrentPlanId] = [u.Company.CurrentPlan0].[Id]
        LEFT JOIN [Groups] AS [u.Group0] ON [u0].[GroupId] = [u.Group0].[Id]
        WHERE [u0].[Email] = N'user@example.com'
        ORDER BY [u.Company0].[Id]
    ) AS [t]
) AS [t0] ON [u.Company.CompanyAccessLevels].[CompanyId] = [t0].[Id]
ORDER BY [t0].[Id]
GO
-- Fetch 2nd level relations
SELECT /* ... */
FROM [AspNetUserRoles] AS [u.UserAspNetUserRoles]
INNER JOIN (
    SELECT DISTINCT [t1].*
    FROM (
        SELECT TOP(1) [u1].[Id], [u.Company1].[Id] AS [Id0]
        FROM [AspNetUsers] AS [u1]
        LEFT JOIN [Metadata] AS [u.Metadata1] ON [u1].[MetadataId] = [u.Metadata1].[Id]
        INNER JOIN [Companies] AS [u.Company1] ON [u1].[CompanyId] = [u.Company1].[Id]
        LEFT JOIN [Plans] AS [u.Company.CurrentPlan1] ON [u.Company1].[CurrentPlanId] = [u.Company.CurrentPlan1].[Id]
        LEFT JOIN [Groups] AS [u.Group1] ON [u1].[GroupId] = [u.Group1].[Id]
        WHERE [u1].[Email] = N'user@example.com'
        ORDER BY [u.Company1].[Id], [u1].[Id]
    ) AS [t1]
) AS [t2] ON [u.UserAspNetUserRoles].[UserId] = [t2].[Id]
ORDER BY [t2].[Id0], [t2].[Id]
GO

EF Core 3.1:

SELECT /* ... a lot of columns ... */
FROM (
    SELECT TOP(1) /* ... */
    FROM [AspNetUsers] AS [a]
    LEFT JOIN [Groups] AS [g] ON [a].[GroupId] = [g].[Id]
    INNER JOIN [Companies] AS [c] ON [a].[CompanyId] = [c].[Id]
    LEFT JOIN [Plans] AS [p] ON [c].[CurrentPlanId] = [p].[Id]
    LEFT JOIN [Metadata] AS [m] ON [a].[MetadataId] = [m].[Id]
    WHERE [a].[Email] = N'user@example.com'
) AS [t]
LEFT JOIN [CompanyAccessLevels] AS [c0] ON [t].[Id1] = [c0].[CompanyId]
LEFT JOIN [AspNetUserRoles] AS [a0] ON [t].[Id] = [a0].[UserId]
ORDER BY [t].[Id], [t].[Id1], [c0].[Id], [a0].[UserId], [a0].[RoleId]

This is the effect of the breaking change described here: https://docs.microsoft.com/en-us/ef/core/what-is-new/ef-core-3.0/breaking-changes#eager-loading-single-query

The difference between the queries is clear, the new one looks cleaner and is more “correct” — it prevents problems with data coherency, where each of the queries could see a different state of the database; in most cases it should be faster because of a fewer DB roundtrips required. Unfortunately there is a caveat:

(…) it could have a considerable effect on application performance when a single query contains a large number of Include operators on collection navigations

Six does not seem to be a large number of Include operators, which, as you can see in the generated SQL, translate to JOIN. It is not obvious why is the EF Core 3.1 significantly slower than 3 queries in this case.

To understand the problem we ran the generated queries directly in SQL Server Management Studio and peeked into the insights provided by SQL Server Profiler.

The investigation was carried out from a local developer machine hitting an Azure SQL database. Results in a real application running in an Azure App Service located in the same region as the Azure SQL database should be better due to significantly smaller roundtrip time.

The results:

EF Core 2.2:

Started executing query at Line 1
(1 row affected)
Started executing query at Line 10
(17 rows affected)
Started executing query at Line 28
(20 rows affected)
Total execution time: 00:00:00.157

SQL Profiler:

|EventClass         |duration|
|-------------------|--------|
|sql_batch_completed|    4870|
|sql_batch_completed|    4796|
|sql_batch_completed|    4952|

EF Core 3.1:

Started executing query at Line 1
(340 rows affected)
Total execution time: 00:00:00.458

SQL Profiler:

|EventClass         |duration|
|-------------------|--------|
|sql_batch_completed|   31309|

Not great, not terrible. v3.1 row count is multiple times larger due to the cartesian product of multiple joins, but still 340 is a low number. Our first guess was that the row count exploded significantly and that we hit the issue mentioned here but it is not exactly the same case.

A second step was to run a .NET Console application calling the exact Entity Framework query, to see what is the EF overhead:

EF Core 2.2

00:00:00.2117382

EF Core 3.1

00:00:01.1239034

The difference is more pronounced. To make sure that EF does not transfer more data than the SSMS client, we checked a Wireshark capture:

EF Core 3.1 generated query through SSMS:

|Address A  |Address B   |Packets B → A|Bytes B → A|Bits/s B → A|
|-----------|------------|-------------|-----------|------------|
|192.168.0.8|40.68.37.158|11208        |15M        |249M        |

That is a lot of packets!

EF Core 3.1 (Console app)

|Address A  |Address B   |Packets B → A|Bytes B → A|Bits/s B → A|
|-----------|------------|-------------|-----------|------------|
|192.168.0.8|40.68.37.158|10321        |15M        |118M        |

Similar situation, but the throughput is ~2x lower
It must be the EF Core processing of the data that causes the additional slowdown versus a raw SQL query.

EF Core 2.2 (Console app)

|Address A  |Address B   |Packets B → A|Bytes B → A|Bits/s B → A|
|-----------|------------|-------------|-----------|------------|
|192.168.0.8|40.68.37.158|52           |68k        |2062k       |

This looks normal, just a couple of packets.

Conclusions

• It is not the amount of rows to be processed that caused the slowdown, but the amount of raw data inside a modest result set — the EF Core 3.1 query results included ~80 columns, many of them nvarchar / text which probably is the reason behind 10k packets / 15 MB of data being sent
• EF in memory processing of the received data contributes significantly to the total time
• The difference between EF Core 2.2 and 3.1 should be more pronounced in an app running in Azure, because the connection latency plays a smaller role

Solution

The discussion in the Github issue mentioned earlier was really helpful — the solution was to manually break the Entity Framework query into a few parts, which simulates the EF Core 2.2 behavior:

var query = _dbContext.Users
    .Include(u => u.Metadata)
    .Include(u => u.Company)
    .Include(u => u.Group)
    .Where(u => u.Email == userEmail);
var result = await query.ToListAsync();
query
    .Include(u => u.Company.AccessLevels)
    .SelectMany(u => u.Company.AccessLevels)
    .Load();
query
    .Include(u => u.Company.CurrentPlan)
    .Select(u => u.Company.CurrentPlan)
    .Load();
var user = result.FirstOrDefault();

Fortunately, in the upcoming EF Core 5.0 there will be a simpler solution available — an .AsSplitQuery() extension method which will split the queries EF Core 2.2 — style.

###

For more tech related articles, click here to follow Signal’s Tech Blog on Medium.