Efcore: Analyzer adversely affecting build performance

[roji]

See https://github.com/dotnet/core/issues/3663.

@Pilchie suggested:

I suspect that the advice will be to switch to using Operation analyzers (at least for the memberaccess and objectcreationexpression).
That should let you re-use some already bound info instead of your GetSymbolInfo calls causing the compiler to do a bunch of extra work to re-bind them.

Also look into whether we can/should exclude migration files.

/cc @bricelam

[Pilchie]

@agocke suggested that the overloads taking lambdas are causing a lot of the time. Not sure how much moving to IOperation would help if the underlying binding is already taking a long time. @mavasani - any ideas?

[mavasani]

We have had some internal teams recently move from SyntaxNode/GetSymbolInfo based analyzer implementation to IOperation based implementation and they saw 4x-5x improvement in analyzer performance. I think it would be a good change to make regardless of whether or not it completely addresses the underlying performance concern of the analysis scenario.

[ajcvickers]

Notes from triage:

• Putting this in 3.1 to:
  
  
  
  • Ensure that generated code is being skipped
  
  
  • If the perf is still poor after skipping generated code, then consider also skipping migrations themselves. (It is possible these will be edited to use internal code, but that's not going to be common.)
  
  
• Issue #18620 covers the more general perf issue for big models and/or many migrations

[bricelam]

Confirmed that we generate already generate this in the snapshot and code behind:

// <auto-generated />

Maybe Roslyn doesn't handle self-closing tags? (or attributes for that matter)

[roji]

Will investigate what's going on tomorrow.

[Pilchie]

The roslyn code just looks at the start of the string, but the comment has to be the first thing in the file.

[Pilchie]

It also excludes some files by file name patterns, so it might be working already

[agocke]

So, modifying the analyzer could be useful, but the performance is still not great, even just building the code, because of the pattern of generated code.

The key thing on the analyzer side is that we're somehow avoiding re-using symbols from binding, effectively causing us to bind twice. Obviously this slows things down even more, but the underlying binding is still unfortunate. Overall on the analyzer side I'd say:

1) I agree they probably shouldn't be running on generated code. Something I can debug.
2) An analyzer model that re-uses results from binding would be helpful. I don't know offhand what the best architecture to get this result is

[mavasani]

RE: Generated code analysis

Please ensure that analyzer explicitly configures generated code analysis mode by invoking AnalysisContext.ConfigureGeneratedCodeAnalysis in the Initialize callback.

[bricelam]

the performance is still not great, even just building the code, because of the pattern of generated code

@agocke We've filed https://github.com/aspnet/EntityFrameworkCore/issues/18620 to address this

[bricelam]

@mavasani We do.

https://github.com/aspnet/EntityFrameworkCore/blob/68b864c209f16597c49e6d07e8f0af0edcaa3862/src/EFCore.Analyzers/InternalUsageDiagnosticAnalyzer.cs#L40-L49

[mavasani]

@bricelam Thanks.

I notice that you invoke GetSymbolInfo on every single member access and object creation in the compilation. That is going to be extremely expensive, and certainly not recommended for semantic analysis. @sharwell has done bunch of performance measurements in this space, and can confirm the same. You should certainly move to RegisterOperationAction for these callbacks. You can register for following OperationKinds:

1. OperationKind.ObjectCreation - Gives back an IObjectCreationOperation
2. OperationKind.Invocation - Gives back an IInvocationOperation
3. OperationKind.FieldReference - Gives back an IFieldReferenceOperation
4. OperationKind.MethodReference - Gives back an IMethodReferenceOperation
5. OperationKind.PropertyReference - Gives back an IPropertyReferenceOperation
6. OperationKind.EventReference - Gives back an IEventReferenceOperation

Each of the above operations directly expose the underlying target symbol and would avoid invoking GetSymbolInfo.

I would also avoid registering a syntax node action for ClassDeclarationSyntax and invoking GetDeclaredSymbol. Instead you can invoke RegisterSymbolAction with SymbolKind.NamedType and explicitly check the type kind on the call back to be TypeKind.Class.

[roji]

tl;dr this is fixed in 3.1.

@bricelam added GeneratedCodeAnalysisFlags.None to the analyzer in 68b864c209f16597c49e6d07e8f0af0edcaa3862, which is in 3.1 but not in 3.0 (of course I had totally forgotten). So the 3.0 version of the analyzer indeed processes all code-generated, but 3.1 does not. As @Pilchie wrote above, Roslyn treats all *.Designer.cs as auto-generated (and some other name patterns), as well as any file starting with a comment that contains "see full Roslyn logic here). So we're fine.

Did some tests to confirm that all is good. With latest release/3.1, compiling the provided migration code, we get the following times (in seconds):

| Scenario | Time (seconds) |
| ------------|---------------------|
| Current 3.1 | 11.481 |
| With GeneratedCodeAnalysisFlags.Analyze (as 3.0) | 19.449 |
| With null analyzer (no RegisterSyntaxNodeAction) | 10.971 |
| With no analyzer (no PackageReference) | 7.603 |

We can definitely still optimize the analyzer as per @mavasani's suggestion, opened #18637 to track.

Unless someone objects, will leave this issue as closed-fix in 3.1 for future reference, as we don't have any other visible issue discussing it.

[roji]

@Sally-Xu it can you please try the EF Core 3.1.0 daily builds and confirm the results?

[Sally-Xu]

@roji,

I just downloaded EF Core 3.1.0-preview2.19525.5 and the problem is still there. Does the EF Core 3.1.0-preview2.19525.5 include this fix?

I haven't got time to setup my machine to try the daily build. Would rather wait for NuGet package to try it.

[roji]

@Sally-Xu 3.1.0-preview2.19525.5 indeed contains the fix. I retested and as far as I can see the issue is gone, can you please double-check? If you're still seeing a slow build time, could you please provide detailed instructions (similar to the below)?

To test, I created a minimal project with your migrations (see https://github.com/roji/AnalyzerBuildPerf). I've done three tests, executing the following commandline:

dotnet clean; dotnet build; touch Program.cs; time dotnet build

Results:

| Scenario | Build Time (seconds) |
| ------------|---------------------|
| Depending on EF Core 3.0 | 19.868 |
| Depending on EF Core 3.1.0-preview2.19525.5 | 8.786 |
| Analyzer disabled | 6.022 |

The analyzer was disabled via a special fragment in the csproj, which allows passing /p:UseRoslynAnalyzers=false on the commandline.

[Sally-Xu]

@roji, I just tested it again. Yes, the build time with 3.1.0-preview2.19525.5 is better than v3.0.0, but it is still not ideal.

For our project the build time is 53s (EF3.0) vs 32s (EF 3.1.0-preview2.19525.5 ) vs. 2.7s (without Migrations folder)

For your EFGames testing project, the build time on my machine is 34s( EF3.0) vs 9s (EF 3.1.0-preview2.19525.5) vs. 1s (Without Migrations folder)

The migrations code compile still takes the biggest chunk of build time.

Here are the binlog files: https://1drv.ms/u/s!AqUgraw9MWG6gaIdG0dcrq2wa0eAzA?e=L3qmDN

[roji]

@Sally-Xu thanks for providing the info. To make sure I understand: the numbers I posted above are for the migrations you provided earlier (see full project in https://github.com/roji/AnalyzerBuildPerf), are you using a different project with many more migrations? Just trying to understand the considerable difference between the times you and I are seeing. If so, could you please provide the migration folder that triggers a 32s build time?

Since the 3.1 analyzer is ignoring code-generated files, only the non-code-generation portions of the migrations could be responsible for this. I'd want to see if there's any special pattern used in the migrations which triggers this (or just a massive amount of them).

[Sally-Xu]

@roji,

The migrations folder in your testing project is exactly the same as in my full project. But my project is much bigger with all the other code.

When looking at the build time without the Migrations folder, the build time on your testing project is < 1s vs 2. s on my full project which I think is reasonable.

With Migrations folder, the build time increases dramatically (and seems the bigger the project, the bigger the increase).

By the way, I also re-tested my project using dotnet core 2.2. The build time is still better than ef3.1 preview.

Build time on my project:

  | EF 2.2X | EF 3.0 | EF 3.1 Preview
-- | -- | -- | --
With Migrations | 18 s | 53 s | 32 s
No Migrations | 2.2 s | 4.3 s | 2.7 s

Since Migrations code is only needed when actually adding and running Migrations, Is there a flag to exclude this folder from the build?

[roji]

That's odd... Since there's no slowdown with only the migrations folder, it would seem that to repro this you need to have both:

1. The migration folder, and
2. The entire (non-migration) project

I'm not sure how that could be - any chance you could share the entire project for me to repro this on my side? This would allow me to dig deeper and possibly to experiment whether #18637 is a solution.

---

As a workaround, you should be able to disable the analyzer in you csproj:

<PackageReference Include="Microsoft.EntityFrameworkCore.SqlServer" Version="3.0.0" ExcludeAssets="analyzers" />

However, there seems to be a long-standing bug preventing this from working (https://github.com/dotnet/sdk/issues/1212). Another way is to do the following:

<Target Name="DisableAnalyzers" BeforeTargets="CoreCompile">
  <ItemGroup>
    <Analyzer Remove="@(Analyzer)" />
  </ItemGroup>
</Target>

Note that this will disable all analyzers, always (it can be tweaked to be selective, though).

[Pilchie]

I haven't looked at the code generated for migrations, but if as @agocke said, there a ton of overload resolutions that involve lambdas and the non-migration code includes additional overloads, it could increase the complexity of each resolution.

[roji]

It's weird though... When @Sally-Xu deletes the migration directory, the build is super fast (~3s), implying that the non-migration code isn't problematic. At the same time, when I run a project containing only the migrations, I get an ~8s build (~6s with the analyzer totally disabled).

[Pilchie]

My point is that if the compiler has to consider overloads declared outside the migrations folder to resolve the calls inside the migrations folder, it could lead to this sort of complexity where both pieces are required to see the full effect of the perf problem

[roji]

Right, understood - although migrations typically aren't supposed to interact in complex with the rest of the project code.

Anyway, it would be good to be able to look at the actual project producing this. Regardless I'll definitely also give #18637 a try as previously suggested.

[Sally-Xu]

@roji ,

I created a new mini Web API project (https://github.com/Sally-Xu/net3buildissue) only contains the Migrations Folder and DBContext.

The build time on my machine is ~40 s (with Migrations) vs. 2 s (without Migrations).

You can un-comment the following setting in the .csproj file to test both situations:

<ItemGroup> <!--<Compile Remove="Migrations\**" /> --> </ItemGroup>

[roji]

Thanks @Sally-Xu, I'll investigate this.

[roji]

I've dug some more and indeed saw a big build perf difference between the repo @Sally-Xu provided and my own. I managed to narrow it down to a quite surprising factor: specifying <Project Sdk="Microsoft.NET.Sdk.Web"> in the csproj makes the build time shoot up from around 6s to around 16s. Here are some measurements:

Scenario | Build time
-- | --
Microsoft.NET.Sdk.Web | 16s
Microsoft.NET.Sdk | 6s
Microsoft.NET.Sdk.Web, without auto-generated migration files | 4.5s
Microsoft.NET.Sdk, without auto-generated migration files | 2s
Microsoft.NET.Sdk.Web with migration files but analyzer disabled | 6.3s
Microsoft.NET.Sdk with migration files but analyzer disabled | 5s

This was with EF Core 3.1.0-preview3.19554.8, on SDK 3.1.100-preview2-014569. I've updated the repo used (https://github.com/roji/AnalyzerBuildPerf) to be very similar to what @Sally-Xu provided (but changed from Npgsql to SQL Server to exclude any unknown issues, and some other minor changes).

Note that running with EF Core 3.0.0, where the analyzer didn't yet specify GeneratedCodeAnalysisFlags.None, makes the build time go up to 30s. Also, while with 3.0.0 I can see a warning by placing an offending internal snippet in auto-generated migration files, in 3.1.0 I can't. In other words, GeneratedCodeAnalysisFlags.None does seem to be doing its job - diagnostics aren't generated and build time is cut from 30s to 15s, suggesting the auto-generated files aren't processed.

Does anyone have any idea where to go from here? @Pilchie @mavasani @agocke @jaredpar @rainersigwald

[Pilchie]

The Web Sdk pulls in a bunch of other analyzers for MVC and stuff, so it's possible that they have similar problems. @mkArtakMSFT ?

[rainersigwald]

@roji Is that all end-to-end build time? Where is the time going? The task time summary in MSBuild is probably a nice place to start.

[roji]

@Pilchie that sounds like a promising direction.

@rainersigwald yeah, sorry, this is end-to-end time (am not a big build perf expert). Here's the msbuild detailed summary from an even slower machine, although it doesn't seem very helpful:

  Detailed Build Summary
  ======================


  ============================== Build Hierarchy (IDs represent configurations) =======================================
  ==============
  Id                  : Exclusive Time   Total Time   Path (Targets)
  ---------------------------------------------------------------------------------------------------------------------
  --------------
  0                   : 25.129s           25.129s       C:\projects\AnalyzerBuildPerf\web-api.csproj ()

  ============================== Node Utilization (IDs represent configurations) ======================================
  ==============
  Timestamp:            1        Duration   Cumulative
  ---------------------------------------------------------------------------------------------------------------------
  --------------
  637087586518145680:   0        25.129s     25.129s +++++ (scale 1:100)
  ---------------------------------------------------------------------------------------------------------------------
  --------------
  Utilization:          100.0    Average Utilization: 100.0

[rainersigwald]

@roji I think the more interesting sections will be Project Evaluation Performance Summary, Project Performance Summary, Target Performance Summary, and Task Performance Summary.

Specifically:

• If the Csc task is taking the bulk of the time, it's likely code complexity or analzyers.
• If evaluation is slow we have more data we can get.

I suspect the former but it's cheap to confirm.

[roji]

@rainersigwald I can dig into this more tomorrow if nobody else does before that (am in Berlin)

[roji]

I investigated this further and all seems clear. Using Microsoft.NET.Sdk.Web brings in three additional analyzer packages: Microsoft.AspNetCore.Analyzers, Microsoft.AspNetCore.Mvc.Analyzers AND Microsoft.AspNetCore.Components.Analyzers. Lots of the contained analyzers do perform generated code analysis, explaining the situation. Did an analyzer-by-analyzer analysis (ha), and opened https://github.com/aspnet/AspNetCore/issues/16922 to discuss possibly opting out for some/all of the analyzers.

@Sally-Xu thanks for your patience and for providing the repro project!