Core: Project build takes long time after upgrading to .Net Core 3.0

[Sally-Xu]

Project build takes a long time after upgrading to .Net Core 3.0 when project contains Migrations folder

I found project build takes a lot longer after upgrading my project to .Net Core 3.0. It feels like a whole rebuild is kicking off after every simple change in the code. This happens when both using Visual Studio 2019 to build or using dotnet build command in the console.

I finally narrowed down the cause is the Migrations folder. If I remove that folder from the project, build takes ~1 sec for a simple change, same as before the upgrade. But with the the Migrations folder (and migration code) in the project, the same code change would take >20 sec to build.

I've tested on both Mac OS and Windows 10, same behavior.

Microsoft.NetCore: 3.0.0
Microsoft.AspNetCore.App 3.0.0
Microsoft.EntityFrameworkCore 3.0.0
Npgsql.EntityFrameworkCore.PostgresSQL 3.0.1

[scalablecory]

@livarcocc @Pilchie

[livarcocc]

@ajcvickers

[ajcvickers]

@livarcocc This isn't something we have seen before. /cc @bricelam

@Sally-Xu We're likely going to need a project/solution or some other way to reproduce what you are seeing and determine if this is an EF issue or something else.

[Pilchie]

@rainersigwald - would a binlog help identify what's going here? Can you share the guidance on uploading them?

[Sally-Xu]

@ajcvickers, thanks for the response.
I have output 2 build log files, one with migrations folder and one without. If you think that might help I can send you the link to the log file. Otherwise, is there a good profiler tool you recommend to use to catch what is going on during the build?

[ajcvickers]

@Sally-Xu Profiling the build is not an area I am very familiar with. @livarcocc @rainersigwald Any ideas?

[rainersigwald]

Let's start with binlogs. They may reveal that we need to apply other tools, like evaluation profiling, but they're usually pretty informative.

@Sally-Xu, can you capture and share a binlog using the instructions at https://aka.ms/msbuild/binlog? Please note the warning about the logs containing potentially-private information before sharing them in public.

[Sally-Xu]

@rainersigwald ,

I have created 4 build binlog files:

• .net2.2-no-migrations.binlog
• .net2.2-with-migrations.binlog
• .net3.0-no-migrations.binlog
• .net3.0-with-migrations.binlog

2 evaluation profile files are also included:

• .net3.0-no-migrations.profile
• .net3.0-with-migrations.profile

file link: https://1drv.ms/u/s!AqUgraw9MWG6gaIZw_wMAwuS1Qcshg?e=mbGYRq

Let me know if this helps.

[rainersigwald]

Thanks! In net3-with-migrations.binlog, it looks like the time is primarily spent in the C# compiler:

    46676 ms  Csc                                        1 calls

Build succeeded.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:48.24

@jaredpar can you help route and advise on next troubleshooting steps?

[jaredpar]

@agocke

Took a quick look at this and confirmed much of what @Sally-Xu laid out in the bug. The only difference between the compilations is the code in the Migrations folder and that takes the compilation time from 2.6 seconds to 46 seconds.

The code in the Migrations folder though does seem to be generally problematic for the compiler. Looking at the net2 binlog I see compilation still takes 15 seconds with the Migrations folder. So the jump is actually from 15 seconds to 46. Even so 15 is a long time for compilation. My suspicion is that there is something in that folder triggering a pathological case in the compiler that is somehow exacerbated in the move to net3.

Is there any way we can get a copy of the code in that folder? That will probably be the fastest way to track down this bug.

[Sally-Xu]

@jaredpar,

I can certainly provide migration code in the Migrations folder which most of them are generated code when we have model changes.

Here is the link: https://1drv.ms/u/s!AqUgraw9MWG6gaIaCCwjfsj27pwirw?e=E7nmW6

The thing I don't understand is that there is no code change in the migrations folder, why the build process needs to recompile them every time.

[jaredpar]

The thing I don't understand is that there is no code change in the migrations folder, why the build process needs to recompile them every time.

@rainersigwald is probably best to answer that. At a glance looking through the build log I don't see an obivous reason why the compiler would be invoked twice.

Thanks for the link. We'll dig into this.

[agocke]

@Sally-Xu Did you by any chance upgrade to EF Core 3.0 at the same time as NET Core 3.0? It looks like there's an EF analyzer, InternalUsageDiagnosticAnalyzer, which is taking a very long time to run.

[Sally-Xu]

@agocke,
Yes, I did upgrade to EF Core 3.0 with Net Core 3.0.

[agocke]

OK, more detail: the migration code here is pretty heavyweight. A very large number of invocations turn out to be to ModelBuilder.Entity which doesn't have a lot of overloads, but we still need to do overload resolution with lambda parameters and that's not cheap. Doing it for thousands of calls has significant overhead.

The analyzer here really isn't that unusual, but due to the architecture it requires redoing overload resolution, which basically doubles the total time.

Disabling the analyzer causes the build to go from about 20s -> 8s on my machine, so it's still pretty slow. Unfortunately, overload resolution with lambda type inference is an inherently expensive operation to compile. I verified that there's no regression in that performance -- it's about as slow in Roslyn 2.9 as it is in 3.3.1.

I think the best approach here would be to try and improve the generated code from EF Core.

@ajcvickers is it expected for Migrations to generate many lambdas and calls to ModelBuilder.Entity? Minimizing this pattern would probably heavily improve compilation performance.

[bricelam]

@ajcvickers I had an oddly related thought recently. If we add a store model, we could just serialize that into the migration code-behind file. This would avoid using modelBuilder

[roji]

@Sally-Xu the OneDrive links you provided above are no longer valid, any chance you can re-post with durable links?

[Sally-Xu]

@roji,
Here you go:
https://1drv.ms/u/s!AqUgraw9MWG6gaIbETKXQEt9pXcrLA?e=5WS3o0

It does seem the ModelBuilder.Entity() code in the designer.cs and snapshot.cs are the problem.

I have tried to remove all the designer.cs files from the Migrations folder, it cuts down the build time significantly. If I also remove the snapshot.cs, the build time is the same as when I remove the whole migrations folder.

Is there a way to exclude this folder from the build process unless when running migration such as when running dotnet ef command?

[roji]

This has already been fixed for 3.1 by @bricelam - the analyzer in 3.0 does not specify GeneratedCodeAnalysisFlags.None and so processes generated code. The 3.1 analyzer specifies it.

See further details and timings in https://github.com/aspnet/EntityFrameworkCore/issues/18618#issuecomment-547465596.