Performance regression in query plan compilation under load on .Net Core

[ArturDorochowicz]

I believe there's a performance regression in query plan compilation under load with EF 6.4.4 on .Net Core 3.1.

Background

We run a somewhat active web application. We have recently upgraded it from net48 and EF 6.2.0 to netcoreapp3.1 and EF 6.4.4.

The application has been long in development so some patterns used there are not necessarily up to date. In particular there's a considerable amount of synchronous IO. This, I think, puts pressure on the thread pool which often runs with elevated number of worker threads (2x - 3x the default, i.e. equal to the number of CPUs). When it happens, we see sustained, increased processor usage making the application slow.

Traces that we took point to EF query plan compilations (which happen in our case because some of the frequent queries in the app don't get cached) and specifically to the use of ConcurrentBag in BitVec.ArrayPool..

Benchmarks

I've tried to show the issue with BenchmarkDotNet benchmarks. Below are the results of it. Note that I'm completely new to BenchmarkDotNet. Still, I think it shows there's an issue.

Benchmarks are completely synthetic, all they do is compile a plan for a non trivial query in a loop on multiple threads in parallel.
Base benchmark class is taken from grpc project (https://github.com/grpc/grpc/blob/master/src/csharp/Grpc.Microbenchmarks/CommonThreadedBase.cs)

Edit: I managed to run all the cases in one benchmark. Results in a comment further below: #1794 (comment)

Benchmarks were run on a 4 core cpu (8 logical cores). There are three comparisons (results and project sources further below):

1. EF 6.4.4 net48 V. EF 6.4.4 netcoreapp3.1 - with growing number number of threads, EF on netcoreapp3.1 is more and more underperforming
2. EF 6.2.0 net48 V. EF 6.4.4 netcoreapp3.1 - similar situation to the above, but EF on netcoreapp3.1 underperforms even more with growing number of threads
3. EF 6.2.0 net48 V. EF 6.4.4 net48 - there's not much of a difference, but seems that 6.2.0 might be just a bit more "scalable" than 6.4.4

EF 6.4.4 net48 V. EF 6.4.4 netcoreapp3.1

BenchmarkDotNet=v0.12.1, OS=Windows 10.0.19042
Intel Core i7-7700HQ CPU 2.80GHz (Kaby Lake), 1 CPU, 8 logical and 4 physical cores
  [Host]     : .NET Framework 4.8 (4.8.4300.0), X64 RyuJIT
  Job-QKEGVM : .NET Framework 4.8 (4.8.4300.0), X64 RyuJIT
  Job-YDYBRC : .NET Core 3.1.10 (CoreCLR 4.700.20.51601, CoreFX 4.700.20.51901), X64 RyuJIT

Server=True  RunStrategy=Monitoring  

Method	Job	Runtime	ThreadCount	Mean	Error	StdDev	Ratio	RatioSD
PlanCompilation	Job-QKEGVM	.NET 4.8	4	2.968 ms	0.0187 ms	0.0124 ms	1.00	0.00
PlanCompilation	Job-YDYBRC	.NET Core 3.1	4	2.862 ms	0.0323 ms	0.0214 ms	0.96	0.01
PlanCompilation	Job-QKEGVM	.NET 4.8	8	4.804 ms	0.0099 ms	0.0065 ms	1.00	0.00
PlanCompilation	Job-YDYBRC	.NET Core 3.1	8	4.653 ms	0.0621 ms	0.0411 ms	0.97	0.01
PlanCompilation	Job-QKEGVM	.NET 4.8	16	9.521 ms	0.0309 ms	0.0204 ms	1.00	0.00
PlanCompilation	Job-YDYBRC	.NET Core 3.1	16	10.247 ms	0.1164 ms	0.0770 ms	1.08	0.01
PlanCompilation	Job-QKEGVM	.NET 4.8	32	20.607 ms	0.0509 ms	0.0337 ms	1.00	0.00
PlanCompilation	Job-YDYBRC	.NET Core 3.1	32	23.783 ms	0.1388 ms	0.0918 ms	1.15	0.01
PlanCompilation	Job-QKEGVM	.NET 4.8	48	33.281 ms	0.3638 ms	0.2406 ms	1.00	0.00
PlanCompilation	Job-YDYBRC	.NET Core 3.1	48	41.700 ms	0.0804 ms	0.0532 ms	1.25	0.01
PlanCompilation	Job-QKEGVM	.NET 4.8	64	46.142 ms	1.2801 ms	0.8467 ms	1.00	0.00
PlanCompilation	Job-YDYBRC	.NET Core 3.1	64	63.083 ms	0.1209 ms	0.0799 ms	1.37	0.02

TestEFRecompilation_644_644.zip

EF 6.2.0 net48 V. EF 6.4.4 netcoreapp3.1

BenchmarkDotNet=v0.12.1, OS=Windows 10.0.19042
Intel Core i7-7700HQ CPU 2.80GHz (Kaby Lake), 1 CPU, 8 logical and 4 physical cores
  [Host]     : .NET Framework 4.8 (4.8.4300.0), X64 RyuJIT
  Job-QKEGVM : .NET Framework 4.8 (4.8.4300.0), X64 RyuJIT
  Job-YDYBRC : .NET Core 3.1.10 (CoreCLR 4.700.20.51601, CoreFX 4.700.20.51901), X64 RyuJIT

Server=True  RunStrategy=Monitoring  

Method	Job	Runtime	ThreadCount	Mean	Error	StdDev	Ratio
PlanCompilation	Job-QKEGVM	.NET 4.8	4	3.120 ms	0.0250 ms	0.0166 ms	1.00
PlanCompilation	Job-YDYBRC	.NET Core 3.1	4	2.752 ms	0.0067 ms	0.0044 ms	0.88
PlanCompilation	Job-QKEGVM	.NET 4.8	8	4.989 ms	0.0574 ms	0.0380 ms	1.00
PlanCompilation	Job-YDYBRC	.NET Core 3.1	8	4.619 ms	0.0372 ms	0.0246 ms	0.93
PlanCompilation	Job-QKEGVM	.NET 4.8	16	9.841 ms	0.0228 ms	0.0151 ms	1.00
PlanCompilation	Job-YDYBRC	.NET Core 3.1	16	10.127 ms	0.1660 ms	0.1098 ms	1.03
PlanCompilation	Job-QKEGVM	.NET 4.8	32	20.541 ms	0.0931 ms	0.0616 ms	1.00
PlanCompilation	Job-YDYBRC	.NET Core 3.1	32	24.051 ms	0.1034 ms	0.0684 ms	1.17
PlanCompilation	Job-QKEGVM	.NET 4.8	48	31.539 ms	0.2406 ms	0.1591 ms	1.00
PlanCompilation	Job-YDYBRC	.NET Core 3.1	48	41.739 ms	0.1223 ms	0.0809 ms	1.32
PlanCompilation	Job-QKEGVM	.NET 4.8	64	43.353 ms	0.5174 ms	0.3422 ms	1.00
PlanCompilation	Job-YDYBRC	.NET Core 3.1	64	62.850 ms	0.3439 ms	0.2275 ms	1.45

TestEFRecompilation_620_644.zip

EF 6.2.0 net48 V. EF 6.4.4 net48

BenchmarkDotNet=v0.12.1, OS=Windows 10.0.19042
Intel Core i7-7700HQ CPU 2.80GHz (Kaby Lake), 1 CPU, 8 logical and 4 physical cores
  [Host]     : .NET Framework 4.8 (4.8.4300.0), X64 RyuJIT
  Job-DQVCDR : .NET Framework 4.8 (4.8.4300.0), X64 RyuJIT
  Job-CMOCQR : .NET Framework 4.8 (4.8.4300.0), X64 RyuJIT

Server=True  Arguments=/p:AutoGenerateBindingRedirects=false,/p:GenerateSupportedRuntime=false  RunStrategy=Monitoring  

Method	Job	NuGetReferences	ThreadCount	Mean	Error	StdDev	Ratio
PlanCompilation	Job-DQVCDR	EntityFramework 6.2.0	4	3.119 ms	0.0258 ms	0.0171 ms	1.00
PlanCompilation	Job-CMOCQR	EntityFramework 6.4.4	4	2.979 ms	0.0424 ms	0.0280 ms	0.96
PlanCompilation	Job-DQVCDR	EntityFramework 6.2.0	8	4.955 ms	0.0215 ms	0.0142 ms	1.00
PlanCompilation	Job-CMOCQR	EntityFramework 6.4.4	8	4.774 ms	0.0996 ms	0.0659 ms	0.96
PlanCompilation	Job-DQVCDR	EntityFramework 6.2.0	16	9.885 ms	0.0468 ms	0.0310 ms	1.00
PlanCompilation	Job-CMOCQR	EntityFramework 6.4.4	16	9.658 ms	0.1366 ms	0.0904 ms	0.98
PlanCompilation	Job-DQVCDR	EntityFramework 6.2.0	24	15.039 ms	0.0459 ms	0.0304 ms	1.00
PlanCompilation	Job-CMOCQR	EntityFramework 6.4.4	24	15.082 ms	0.0397 ms	0.0262 ms	1.00
PlanCompilation	Job-DQVCDR	EntityFramework 6.2.0	32	20.460 ms	0.0529 ms	0.0350 ms	1.00
PlanCompilation	Job-CMOCQR	EntityFramework 6.4.4	32	20.743 ms	0.2705 ms	0.1789 ms	1.01
PlanCompilation	Job-DQVCDR	EntityFramework 6.2.0	40	25.990 ms	0.1027 ms	0.0679 ms	1.00
PlanCompilation	Job-CMOCQR	EntityFramework 6.4.4	40	27.078 ms	0.2125 ms	0.1406 ms	1.04
PlanCompilation	Job-DQVCDR	EntityFramework 6.2.0	48	32.105 ms	0.3490 ms	0.2308 ms	1.00
PlanCompilation	Job-CMOCQR	EntityFramework 6.4.4	48	33.421 ms	0.5360 ms	0.3545 ms	1.04

TestEFRecompilation_620_644_net48.zip

Benchmark code

Benchmark code is basically the following, see zip archives for actual projects.

  public void PlanCompilation()
  {
      RunConcurrent(() => { RunBody(); });
  }

  public static void RunBody()
  {
      using (var ctx = new TestContext("Server=(localdb)\\MSSQLLocalDB; Database=EFBenchmark1;"))
      {
          for (var i = 0; i < 10000; i++)
          {
              var query = GetQuery(ctx);
              var sql = query.ToString();
              _ = sql;
          }
      }
  }

  static IQueryable GetQuery(TestContext context)
  {
      var ids = new[] {1, 2};

      return from employee in context.Employees
          where ids.Contains(employee.Id)
          join other in context.Employees on employee.ManagerId equals other.Id into managers
          from manager in managers.DefaultIfEmpty()
          join other in context.Employees on employee.Id equals other.ManagerId into reports
          select new
          {
              Id = employee.Id,
              Name = employee.Name,
              ManagerId = manager != null ? manager.Id : (int?)null,
              ManagerName = manager != null ? manager.Name : null,
              ReportsCount = reports.Count()
          };
  }

  public class TestContext : DbContext
  {
      public TestContext(string connectionString)
          : base(connectionString)
      {
          Database.SetInitializer<TestContext>(null);
      }

      public DbSet<Employee> Employees { get; set; }
  }

  public class Employee
  {
      public int Id { get; set; }

      public int? ManagerId { get; set; }

      public string Name { get; set; }
  }

[Seabizkit]

Random question, but how do you do 64 threads on say....
"Intel Core i7-7700HQ CPU 2.80GHz (Kaby Lake), 1 CPU, 8 logical and 4 physical cores"
Work? surely the tests beyond the actually limits... are meaningless or will show regression on both.

[ArturDorochowicz]

As I learn more about BenchmarkDotNet, I was able to run all the cases in one benchmark for easier comparison.

TestEFRecompilation.zip

Run with dotnet run -c Release -f net48 -- -f *

BenchmarkDotNet=v0.12.1, OS=Windows 10.0.19042
Intel Core i7-7700HQ CPU 2.80GHz (Kaby Lake), 1 CPU, 8 logical and 4 physical cores
  [Host]     : .NET Framework 4.8 (4.8.4300.0), X64 RyuJIT
  Job-EJNHXU : .NET Framework 4.8 (4.8.4300.0), X64 RyuJIT
  Job-IRUXDQ : .NET Framework 4.8 (4.8.4300.0), X64 RyuJIT
  Job-SHNZVZ : .NET Core 3.1.10 (CoreCLR 4.700.20.51601, CoreFX 4.700.20.51901), X64 RyuJIT

Server=True  Arguments=/p:AutoGenerateBindingRedirects=false,/p:GenerateSupportedRuntime=false  RunStrategy=Monitoring  

Method	Job	Runtime	NuGetReferences	ThreadCount	Mean	Error	StdDev	Ratio
PlanCompilation	Job-EJNHXU	.NET 4.8	EntityFramework 6.2.0	4	3.119 ms	0.0241 ms	0.0159 ms	1.00
PlanCompilation	Job-IRUXDQ	.NET 4.8	EntityFramework 6.4.4	4	2.988 ms	0.0328 ms	0.0217 ms	0.96
PlanCompilation	Job-SHNZVZ	.NET Core 3.1	EntityFramework 6.4.4	4	2.760 ms	0.0223 ms	0.0147 ms	0.88
PlanCompilation	Job-EJNHXU	.NET 4.8	EntityFramework 6.2.0	8	4.952 ms	0.0451 ms	0.0298 ms	1.00
PlanCompilation	Job-IRUXDQ	.NET 4.8	EntityFramework 6.4.4	8	4.720 ms	0.0190 ms	0.0126 ms	0.95
PlanCompilation	Job-SHNZVZ	.NET Core 3.1	EntityFramework 6.4.4	8	4.589 ms	0.0311 ms	0.0205 ms	0.93
PlanCompilation	Job-EJNHXU	.NET 4.8	EntityFramework 6.2.0	16	9.771 ms	0.0496 ms	0.0328 ms	1.00
PlanCompilation	Job-IRUXDQ	.NET 4.8	EntityFramework 6.4.4	16	9.524 ms	0.0369 ms	0.0244 ms	0.97
PlanCompilation	Job-SHNZVZ	.NET Core 3.1	EntityFramework 6.4.4	16	10.140 ms	0.0340 ms	0.0225 ms	1.04
PlanCompilation	Job-EJNHXU	.NET 4.8	EntityFramework 6.2.0	24	15.078 ms	0.0826 ms	0.0546 ms	1.00
PlanCompilation	Job-IRUXDQ	.NET 4.8	EntityFramework 6.4.4	24	15.077 ms	0.0507 ms	0.0335 ms	1.00
PlanCompilation	Job-SHNZVZ	.NET Core 3.1	EntityFramework 6.4.4	24	16.854 ms	0.0886 ms	0.0586 ms	1.12
PlanCompilation	Job-EJNHXU	.NET 4.8	EntityFramework 6.2.0	32	20.554 ms	0.0824 ms	0.0545 ms	1.00
PlanCompilation	Job-IRUXDQ	.NET 4.8	EntityFramework 6.4.4	32	20.790 ms	0.1090 ms	0.0721 ms	1.01
PlanCompilation	Job-SHNZVZ	.NET Core 3.1	EntityFramework 6.4.4	32	24.032 ms	0.0418 ms	0.0276 ms	1.17
PlanCompilation	Job-EJNHXU	.NET 4.8	EntityFramework 6.2.0	40	26.222 ms	0.1503 ms	0.0994 ms	1.00
PlanCompilation	Job-IRUXDQ	.NET 4.8	EntityFramework 6.4.4	40	27.471 ms	0.1849 ms	0.1223 ms	1.05
PlanCompilation	Job-SHNZVZ	.NET Core 3.1	EntityFramework 6.4.4	40	31.987 ms	0.0581 ms	0.0384 ms	1.22
PlanCompilation	Job-EJNHXU	.NET 4.8	EntityFramework 6.2.0	48	31.868 ms	0.3347 ms	0.2214 ms	1.00
PlanCompilation	Job-IRUXDQ	.NET 4.8	EntityFramework 6.4.4	48	33.757 ms	0.5301 ms	0.3507 ms	1.06
PlanCompilation	Job-SHNZVZ	.NET Core 3.1	EntityFramework 6.4.4	48	41.626 ms	0.1623 ms	0.1073 ms	1.31

[ArturDorochowicz]

Random question, but how do you do 64 threads on say....
"Intel Core i7-7700HQ CPU 2.80GHz (Kaby Lake), 1 CPU, 8 logical and 4 physical cores"
Work? surely the tests beyond the actually limits... are meaningless or will show regression on both.

@Seabizkit Sure, I may have gone overboard with this. OTOH, it doesn't show regression on both, but rather it confirms the trend of EF on .net core underperforming under load more and more.

[ajcvickers]

This issue has been closed because EF6 is no longer being actively developed. We are instead focusing on stability of the codebase, which means we will only make changes to address security issues. See the repo README for more information.

[Poltuu]

We just spend 8 month trying to understand why our application freshly migrated from .NET4.8 could not handle the load, never thinking that the time spent compiling plans was abnormal of all things. We now have to migrate to EF Core, which is no little task.

This issue should be clearly advertised in this repo's front page, and serve as a warning for anyone trying to migrate big apps to dotnet core, while still using EF 6.

[FPierrel]

We've seen the same problem this week. In some cases, the loss of time due to the use of ConcurrentBag is greater than 30%.

Have you tested a return to EF6.3? We haven't had time to do so yet. We are also considering the creation of a custom version without the PR that introduces this counter-productive 'optimization' (#430).