search

koenbeuk / EntityFrameworkCore.Projectables

Project over properties and functions in your linq queries
MIT License
312 stars 23 forks source link

Visual Studio performance issue in a large project #102

Closed ZvonimirMatic closed 5 months ago

ZvonimirMatic commented 8 months ago

I'm working on a large project with more than 1000 entities. When I add a reference to EntityFrameworkCore.Projectables nuget package, it drastically deteriorates Visual Studio - Peek definition and Go to definition take about 30 second to complete. It was so bad that for the moment being we had to switch to ClaveExpressionify which does not have this problem. It slows everything down even when there are no [Projectable] attributes anywhere in the code. I tried to recreate this problem on a dummy project, but no luck.

Do you have any idea what could be the problem? I don't mind helping with the problem, but some guidance could probably save a lot of time. If more information is needed, let me know.

koenbeuk commented 8 months ago

Thanks for bringing this up, there are a few simple optimizations that should have a big performance impact, should be a quick win,

ZvonimirMatic commented 8 months ago

Great, thank you! Do you think you will be able to implement those implementations in the next preview version?

ZvonimirMatic commented 7 months ago

Hi, I have tried out with the new version (v4.0.0-preview.2), but it still slows down the project to the point where it is not usable.

ZvonimirMatic commented 5 months ago

Could you give me any quick notes on where to start exploring the issue? Which files, I haven't worked with source generators yet.

I can't figure out how does it slow down the project so much. When I make a syntax error in the code (not event related to this library), Visual Studio takes about 30 seconds to underline the error and the CPU goes to 100% if I have the library added. It seems like this library analyzes the files a little too often which might cause the IDE to slow down in case when there is large number of files in the project.

PhenX commented 5 months ago

@ZvonimirMatic I suggest you try to measure performance like described in this article https://www.meziantou.net/measuring-performance-of-roslyn-source-generators.htm

This might help confirm which source generator takes so much time.

ZvonimirMatic commented 5 months ago

Thank you! I followed the article, and here are the results.

First, I built the project that has the reference to this library with the /binaryLogger flag. The ProjectionExpressionGenerator takes by far the most time from all other generators. image

Then I wrote the same program as in the article with the small modification to add the [WARNING] label if the generator takes more than 10 second. Here is the complete code of that program.

using Microsoft.Diagnostics.Tracing.Session;

using var session = new TraceEventSession("roslyn-sg");
Console.CancelKeyPress += (_, _) => session.Dispose();

session.Source.Dynamic.AddCallbackForProviderEvent("Microsoft-CodeAnalysis-General", "SingleGeneratorRunTime/Stop", traceEvent => {
    var generatorName = (string)traceEvent.PayloadByName("generatorName");
    var ticks = (long)traceEvent.PayloadByName("elapsedTicks");
    //var id = (string)data.PayloadByName("id");
    //var assemblyPath = (string)data.PayloadByName("assemblyPath");

    var isLongerThanTenSeconds = TimeSpan.FromTicks(ticks).TotalMilliseconds > 10000;
    Console.WriteLine($"{(isLongerThanTenSeconds ? "[WARNING] " : string.Empty)}{generatorName}: {TimeSpan.FromTicks(ticks).TotalMilliseconds:N0}ms");

    // As suggested by Lucas Trzesniewski (https://twitter.com/Lucas_Trz/status/1631739866915434497)
    // you can use Console.Beep() to get a sound when a source generator is executed.
    // If this is too noisy, you know one of the source generators doesn't use the cache correctly.
});

session.EnableProvider("Microsoft-CodeAnalysis-General");
session.Source.Process();

I ran the program as administrator and opened Visual Studio with the project that had the reference to the library. First thing I tried was to go to definition of a random class in the model. That is the first log with the [WARNING] label, it took 27 seconds. Then I tried to make a syntax error on purpose so I wrote var a = dsdad (or some similar gibberish). Initially it ran ProjectionExpressionGenerator in under a second 7 times, but Visual Studio still didn't underline the syntax error. Then after about 28 seconds, a bunch of logs appeared including 5 logs that ProjectionExpressionGenerator ran for about 28 seconds. After that the syntax error was underlined in Visual Studio.

I'm sending the log with my comments added (starting with ###) for easier reading.

Microsoft.Interop.ComInterfaceGenerator: 67ms
Microsoft.Interop.ComInterfaceGenerator: 631ms
Microsoft.Interop.JavaScript.JSExportGenerator: 32ms
Microsoft.Interop.JavaScript.JSExportGenerator: 32ms
Microsoft.Interop.LibraryImportGenerator: 8ms
Microsoft.Interop.LibraryImportGenerator: 8ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 3ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 3ms
Microsoft.Interop.ComClassGenerator: 12ms
Microsoft.Interop.ComClassGenerator: 12ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 12ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 12ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 3ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 4ms
Microsoft.Interop.VtableIndexStubGenerator: 5ms
Microsoft.Interop.VtableIndexStubGenerator: 11ms
System.Text.RegularExpressions.Generator.RegexGenerator: 33ms
System.Text.RegularExpressions.Generator.RegexGenerator: 28ms
Microsoft.Interop.JavaScript.JSImportGenerator: 3ms
Microsoft.Interop.JavaScript.JSImportGenerator: 3ms
Microsoft.Interop.ComInterfaceGenerator: 3ms
Microsoft.Interop.JavaScript.JSExportGenerator: 1ms
Microsoft.Interop.LibraryImportGenerator: 1ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 0ms
Microsoft.Interop.ComClassGenerator: 0ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 0ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 0ms
Microsoft.Interop.VtableIndexStubGenerator: 0ms
System.Text.RegularExpressions.Generator.RegexGenerator: 0ms
Microsoft.Interop.JavaScript.JSImportGenerator: 0ms
Microsoft.Interop.ComInterfaceGenerator: 6ms
Microsoft.Interop.JavaScript.JSExportGenerator: 2ms
Microsoft.Interop.LibraryImportGenerator: 1ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 0ms
Microsoft.Interop.ComClassGenerator: 1ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 0ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 0ms
Microsoft.Interop.VtableIndexStubGenerator: 1ms
System.Text.RegularExpressions.Generator.RegexGenerator: 0ms
Microsoft.Interop.JavaScript.JSImportGenerator: 1ms
Microsoft.Interop.ComInterfaceGenerator: 32ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 4ms
Microsoft.Interop.JavaScript.JSExportGenerator: 7ms
Microsoft.Interop.LibraryImportGenerator: 6ms
Microsoft.Interop.ComClassGenerator: 3ms
Microsoft.NET.Sdk.Razor.SourceGenerators.RazorSourceGenerator: 67ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 3ms
Microsoft.Interop.VtableIndexStubGenerator: 4ms
System.Text.RegularExpressions.Generator.RegexGenerator: 202ms
Microsoft.Interop.JavaScript.JSImportGenerator: 4ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 2ms
Microsoft.Interop.ComInterfaceGenerator: 48ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 3ms
Microsoft.Interop.JavaScript.JSExportGenerator: 8ms
Microsoft.Interop.LibraryImportGenerator: 5ms
Microsoft.Interop.ComClassGenerator: 2ms
Microsoft.NET.Sdk.Razor.SourceGenerators.RazorSourceGenerator: 2ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 2ms
Microsoft.Interop.VtableIndexStubGenerator: 4ms
System.Text.RegularExpressions.Generator.RegexGenerator: 18ms
Microsoft.Interop.JavaScript.JSImportGenerator: 22ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 2ms

### Tried to Go to deifnition
[WARNING] EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 27.426ms
Microsoft.Interop.ComInterfaceGenerator: 290ms
Clave.Expressionify.Generator.ExpressionifySourceGenerator: 372ms
VocaDb.ResXFileCodeGenerator.SourceGenerator: 1.098ms
Microsoft.Interop.JavaScript.JSExportGenerator: 242ms
Microsoft.Interop.LibraryImportGenerator: 258ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 126ms
Microsoft.Interop.ComClassGenerator: 126ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 123ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 139ms
Microsoft.Interop.VtableIndexStubGenerator: 239ms
System.Text.RegularExpressions.Generator.RegexGenerator: 119ms
Microsoft.Interop.JavaScript.JSImportGenerator: 243ms
Microsoft.Interop.ComInterfaceGenerator: 29ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 2ms
Microsoft.Interop.JavaScript.JSExportGenerator: 3ms
Microsoft.Interop.LibraryImportGenerator: 3ms
Microsoft.Interop.ComClassGenerator: 28ms
Microsoft.NET.Sdk.Razor.SourceGenerators.RazorSourceGenerator: 1ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 2ms
Microsoft.Interop.VtableIndexStubGenerator: 3ms
System.Text.RegularExpressions.Generator.RegexGenerator: 23ms
Microsoft.Interop.JavaScript.JSImportGenerator: 4ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 1ms
Microsoft.Interop.ComInterfaceGenerator: 20ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 1ms
Microsoft.Interop.JavaScript.JSExportGenerator: 12ms
Microsoft.Interop.LibraryImportGenerator: 10ms
Microsoft.Interop.ComClassGenerator: 3ms
Microsoft.NET.Sdk.Razor.SourceGenerators.RazorSourceGenerator: 2ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 3ms
Microsoft.Interop.VtableIndexStubGenerator: 17ms
System.Text.RegularExpressions.Generator.RegexGenerator: 17ms
Microsoft.Interop.JavaScript.JSImportGenerator: 4ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 1ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 5.669ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 5.130ms
Microsoft.Interop.ComInterfaceGenerator: 1.955ms
Microsoft.Interop.ComInterfaceGenerator: 155ms
Microsoft.Interop.JavaScript.JSExportGenerator: 1ms
Microsoft.Interop.JavaScript.JSExportGenerator: 1ms
Microsoft.Interop.LibraryImportGenerator: 1ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 0ms
Microsoft.Interop.ComClassGenerator: 0ms
Microsoft.Interop.LibraryImportGenerator: 1ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 0ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 0ms
Microsoft.Interop.ComClassGenerator: 0ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 0ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 0ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 0ms
Microsoft.Interop.VtableIndexStubGenerator: 5ms
Microsoft.Interop.VtableIndexStubGenerator: 6ms
System.Text.RegularExpressions.Generator.RegexGenerator: 0ms
System.Text.RegularExpressions.Generator.RegexGenerator: 0ms
Microsoft.Interop.JavaScript.JSImportGenerator: 1ms
Microsoft.Interop.JavaScript.JSImportGenerator: 1ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 51ms
Microsoft.Interop.ComInterfaceGenerator: 7ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 2ms
Microsoft.Interop.JavaScript.JSExportGenerator: 4ms
Microsoft.Interop.LibraryImportGenerator: 2ms
Microsoft.Interop.ComClassGenerator: 1ms
Microsoft.NET.Sdk.Razor.SourceGenerators.RazorSourceGenerator: 1ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 2ms
Microsoft.Interop.VtableIndexStubGenerator: 3ms
System.Text.RegularExpressions.Generator.RegexGenerator: 1ms
Microsoft.Interop.JavaScript.JSImportGenerator: 3ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 2ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 34ms
Microsoft.Interop.ComInterfaceGenerator: 4ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 1ms
Microsoft.Interop.JavaScript.JSExportGenerator: 2ms
Microsoft.Interop.LibraryImportGenerator: 2ms
Microsoft.Interop.ComClassGenerator: 1ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 1ms
Microsoft.Interop.VtableIndexStubGenerator: 2ms
System.Text.RegularExpressions.Generator.RegexGenerator: 1ms
Microsoft.Interop.JavaScript.JSImportGenerator: 19ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 2ms
Microsoft.Interop.ComInterfaceGenerator: 3ms
Microsoft.Interop.JavaScript.JSExportGenerator: 1ms
Microsoft.Interop.LibraryImportGenerator: 0ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 0ms
Microsoft.Interop.ComClassGenerator: 0ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 0ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 0ms
Microsoft.Interop.VtableIndexStubGenerator: 0ms
System.Text.RegularExpressions.Generator.RegexGenerator: 0ms
Microsoft.Interop.JavaScript.JSImportGenerator: 0ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 1ms
Microsoft.Interop.ComInterfaceGenerator: 2ms
Microsoft.Interop.JavaScript.JSExportGenerator: 1ms
Microsoft.Interop.LibraryImportGenerator: 0ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 0ms
Microsoft.Interop.ComClassGenerator: 0ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 0ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 0ms
Microsoft.Interop.VtableIndexStubGenerator: 0ms
System.Text.RegularExpressions.Generator.RegexGenerator: 0ms
Microsoft.Interop.JavaScript.JSImportGenerator: 0ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 65ms
Microsoft.Interop.ComInterfaceGenerator: 8ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 2ms
Microsoft.Interop.JavaScript.JSExportGenerator: 3ms
Microsoft.Interop.LibraryImportGenerator: 3ms
Microsoft.Interop.ComClassGenerator: 1ms
Microsoft.NET.Sdk.Razor.SourceGenerators.RazorSourceGenerator: 1ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 1ms
Microsoft.Interop.VtableIndexStubGenerator: 3ms
System.Text.RegularExpressions.Generator.RegexGenerator: 1ms
Microsoft.Interop.JavaScript.JSImportGenerator: 23ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 1ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 3.645ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 19ms
Microsoft.Interop.ComInterfaceGenerator: 29ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 2ms
Microsoft.Interop.JavaScript.JSExportGenerator: 14ms
Microsoft.Interop.LibraryImportGenerator: 2ms
Microsoft.Interop.ComClassGenerator: 3ms
Microsoft.NET.Sdk.Razor.SourceGenerators.RazorSourceGenerator: 6ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 0ms
Microsoft.Interop.VtableIndexStubGenerator: 1ms
System.Text.RegularExpressions.Generator.RegexGenerator: 8ms
Microsoft.Interop.JavaScript.JSImportGenerator: 0ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 0ms
Microsoft.Interop.ComInterfaceGenerator: 1.135ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 27ms
Microsoft.Interop.JavaScript.JSExportGenerator: 51ms
Microsoft.Interop.LibraryImportGenerator: 50ms
Microsoft.Interop.ComClassGenerator: 27ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 22ms
Microsoft.Interop.VtableIndexStubGenerator: 48ms
System.Text.RegularExpressions.Generator.RegexGenerator: 26ms
Microsoft.Interop.JavaScript.JSImportGenerator: 56ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 28ms

### Added syntax error to the code on purpose
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 680ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 227ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 86ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 205ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 337ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 821ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 331ms
[WARNING] EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 27.999ms
Microsoft.Interop.ComInterfaceGenerator: 24ms
Clave.Expressionify.Generator.ExpressionifySourceGenerator: 464ms
VocaDb.ResXFileCodeGenerator.SourceGenerator: 35ms
Microsoft.Interop.JavaScript.JSExportGenerator: 6ms
Microsoft.Interop.LibraryImportGenerator: 15ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 4ms
Microsoft.Interop.ComClassGenerator: 4ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 16ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 10ms
Microsoft.Interop.VtableIndexStubGenerator: 8ms
System.Text.RegularExpressions.Generator.RegexGenerator: 10ms
Microsoft.Interop.JavaScript.JSImportGenerator: 4ms
[WARNING] EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 28.974ms
Microsoft.Interop.ComInterfaceGenerator: 5ms
Clave.Expressionify.Generator.ExpressionifySourceGenerator: 522ms
VocaDb.ResXFileCodeGenerator.SourceGenerator: 13ms
Microsoft.Interop.JavaScript.JSExportGenerator: 14ms
Microsoft.Interop.LibraryImportGenerator: 5ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 3ms
Microsoft.Interop.ComClassGenerator: 4ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 14ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 2ms
Microsoft.Interop.VtableIndexStubGenerator: 4ms
System.Text.RegularExpressions.Generator.RegexGenerator: 2ms
Microsoft.Interop.JavaScript.JSImportGenerator: 4ms
[WARNING] EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 29.655ms
Microsoft.Interop.ComInterfaceGenerator: 5ms
Clave.Expressionify.Generator.ExpressionifySourceGenerator: 444ms
VocaDb.ResXFileCodeGenerator.SourceGenerator: 15ms
Microsoft.Interop.JavaScript.JSExportGenerator: 6ms
Microsoft.Interop.LibraryImportGenerator: 15ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 3ms
Microsoft.Interop.ComClassGenerator: 3ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 3ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 3ms
Microsoft.Interop.VtableIndexStubGenerator: 11ms
System.Text.RegularExpressions.Generator.RegexGenerator: 2ms
Microsoft.Interop.JavaScript.JSImportGenerator: 4ms
[WARNING] EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 27.896ms
Microsoft.Interop.ComInterfaceGenerator: 10ms
Clave.Expressionify.Generator.ExpressionifySourceGenerator: 435ms
VocaDb.ResXFileCodeGenerator.SourceGenerator: 5ms
Microsoft.Interop.JavaScript.JSExportGenerator: 4ms
Microsoft.Interop.LibraryImportGenerator: 10ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 2ms
Microsoft.Interop.ComClassGenerator: 2ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 2ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 2ms
Microsoft.Interop.VtableIndexStubGenerator: 11ms
System.Text.RegularExpressions.Generator.RegexGenerator: 2ms
Microsoft.Interop.JavaScript.JSImportGenerator: 4ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 75ms
Microsoft.Interop.ComInterfaceGenerator: 17ms
Microsoft.Interop.JavaScript.JSExportGenerator: 1ms
Microsoft.Interop.LibraryImportGenerator: 1ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 0ms
Microsoft.Interop.ComClassGenerator: 1ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 0ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 0ms
Microsoft.Interop.VtableIndexStubGenerator: 1ms
System.Text.RegularExpressions.Generator.RegexGenerator: 0ms
Microsoft.Interop.JavaScript.JSImportGenerator: 1ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 27ms
Microsoft.Interop.ComInterfaceGenerator: 2ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 0ms
Microsoft.Interop.JavaScript.JSExportGenerator: 1ms
Microsoft.Interop.LibraryImportGenerator: 0ms
Microsoft.Interop.ComClassGenerator: 0ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 0ms
Microsoft.Interop.VtableIndexStubGenerator: 0ms
System.Text.RegularExpressions.Generator.RegexGenerator: 0ms
Microsoft.Interop.JavaScript.JSImportGenerator: 0ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 0ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 0ms
Microsoft.Interop.ComInterfaceGenerator: 1ms
Microsoft.Interop.JavaScript.JSExportGenerator: 0ms
Microsoft.Interop.LibraryImportGenerator: 0ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 0ms
Microsoft.Interop.ComClassGenerator: 0ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 0ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 0ms
Microsoft.Interop.VtableIndexStubGenerator: 0ms
System.Text.RegularExpressions.Generator.RegexGenerator: 0ms
Microsoft.Interop.JavaScript.JSImportGenerator: 0ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 63ms
Microsoft.Interop.ComInterfaceGenerator: 1ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 13ms
Microsoft.Interop.JavaScript.JSExportGenerator: 1ms
Microsoft.Interop.LibraryImportGenerator: 1ms
Microsoft.Interop.ComClassGenerator: 1ms
Microsoft.NET.Sdk.Razor.SourceGenerators.RazorSourceGenerator: 4ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 0ms
Microsoft.Interop.VtableIndexStubGenerator: 0ms
System.Text.RegularExpressions.Generator.RegexGenerator: 0ms
Microsoft.Interop.JavaScript.JSImportGenerator: 0ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 0ms
EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 116ms
Microsoft.Interop.ComInterfaceGenerator: 2ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 0ms
Microsoft.Interop.JavaScript.JSExportGenerator: 1ms
Microsoft.Interop.LibraryImportGenerator: 1ms
Microsoft.Interop.ComClassGenerator: 0ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 0ms
Microsoft.Interop.VtableIndexStubGenerator: 0ms
System.Text.RegularExpressions.Generator.RegexGenerator: 0ms
Microsoft.Interop.JavaScript.JSImportGenerator: 0ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 0ms
[WARNING] EntityFrameworkCore.Projectables.Generator.ProjectionExpressionGenerator: 29.846ms
Microsoft.Interop.ComInterfaceGenerator: 5ms
Clave.Expressionify.Generator.ExpressionifySourceGenerator: 474ms
VocaDb.ResXFileCodeGenerator.SourceGenerator: 12ms
Microsoft.Interop.JavaScript.JSExportGenerator: 4ms
Microsoft.Interop.LibraryImportGenerator: 4ms
Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator: 2ms
Microsoft.Interop.ComClassGenerator: 9ms
Microsoft.Extensions.Options.Generators.OptionsValidatorGenerator: 2ms
System.Text.Json.SourceGeneration.JsonSourceGenerator: 2ms
Microsoft.Interop.VtableIndexStubGenerator: 4ms
System.Text.RegularExpressions.Generator.RegexGenerator: 11ms
Microsoft.Interop.JavaScript.JSImportGenerator: 4ms
ZvonimirMatic commented 5 months ago

I tried adding a reference to the source, as shown in the sample in this repository. Firstly, I confirmed that the reference is added correctly by making sure that the generator still takes a long time.

I tried adding some primitive logging to the file to try to figure out which part of the code might be the problem. Here is the modified code of ProjectionExpressionGenerator.

using EntityFrameworkCore.Projectables.Services;
using Microsoft.CodeAnalysis;
using Microsoft.CodeAnalysis.CSharp;
using Microsoft.CodeAnalysis.CSharp.Syntax;
using Microsoft.CodeAnalysis.Text;
using System;
using System.Collections.Generic;
using System.Collections.Immutable;
using System.Diagnostics;
using System.Linq;
using System.Security.Cryptography.X509Certificates;
using System.Text;
using System.Threading;
using System.Threading.Tasks;
using static Microsoft.CodeAnalysis.CSharp.SyntaxFactory;

namespace EntityFrameworkCore.Projectables.Generator
{
    [Generator]
    public class ProjectionExpressionGenerator : IIncrementalGenerator
    {
        private const string ProjectablesAttributeName = "EntityFrameworkCore.Projectables.ProjectableAttribute";

        static readonly AttributeSyntax _editorBrowsableAttribute = 
            Attribute(
                ParseName("global::System.ComponentModel.EditorBrowsable"),
                AttributeArgumentList(
                    SingletonSeparatedList(
                        AttributeArgument(
                            MemberAccessExpression(
                                SyntaxKind.SimpleMemberAccessExpression,
                                IdentifierName("global::System.ComponentModel.EditorBrowsableState"),
                                IdentifierName("Never")
                            )
                        )
                    )
                )
            );

        public void Initialize(IncrementalGeneratorInitializationContext context)
        {
            var logFilePath = @"C:\current\ProjectablesLog.txt";
            var sw = new Stopwatch();

            // STEP 1
            sw.Start();

            // Do a simple filter for members
            IncrementalValuesProvider<MemberDeclarationSyntax> memberDeclarations = context.SyntaxProvider
                .CreateSyntaxProvider(
                    predicate: static (s, _) => s is MemberDeclarationSyntax m && m.AttributeLists.Count > 0,
                    transform: static (c, _) => GetSemanticTargetForGeneration(c)) 
                .Where(static m => m is not null)!; // filter out attributed enums that we don't care about
            sw.Stop();

#pragma warning disable RS1035 // Do not use APIs banned for analyzers
            File.AppendAllLines(logFilePath, new[]
            {
                $"[STEP 1]: {sw.ElapsedMilliseconds}ms",
            });
#pragma warning restore RS1035 // Do not use APIs banned for analyzers
            sw.Reset();

            // STEP 2
            sw.Start();

            // Combine the selected enums with the `Compilation`
            IncrementalValueProvider<(Compilation, ImmutableArray<MemberDeclarationSyntax>)> compilationAndEnums
                = context.CompilationProvider.Combine(memberDeclarations.Collect());

            sw.Stop();
#pragma warning disable RS1035 // Do not use APIs banned for analyzers
            File.AppendAllLines(logFilePath, new[]
            {
                $"[STEP 2]: {sw.ElapsedMilliseconds}ms",
            });
#pragma warning restore RS1035 // Do not use APIs banned for analyzers
            sw.Reset();

            // STEP 3
            sw.Start();

            // Generate the source using the compilation and enums
            context.RegisterImplementationSourceOutput(compilationAndEnums,
                static (spc, source) => Execute(source.Item1, source.Item2, spc));

            sw.Stop();
#pragma warning disable RS1035 // Do not use APIs banned for analyzers
            File.AppendAllLines(logFilePath, new[]
            {
                $"[STEP 3]: {sw.ElapsedMilliseconds}ms",
            });
#pragma warning restore RS1035 // Do not use APIs banned for analyzers
            sw.Reset();
        }

        static MemberDeclarationSyntax? GetSemanticTargetForGeneration(GeneratorSyntaxContext context)
        {
            var logFilePath = @"C:\current\ProjectablesLog.txt";
            var sw = new Stopwatch();

            sw.Start();

            // we know the node is a MemberDeclarationSyntax
            var memberDeclarationSyntax = (MemberDeclarationSyntax)context.Node;

            // loop through all the attributes on the method
            foreach (var attributeListSyntax in memberDeclarationSyntax.AttributeLists)
            {
                foreach (var attributeSyntax in attributeListSyntax.Attributes)
                {
                    if (context.SemanticModel.GetSymbolInfo(attributeSyntax).Symbol is not IMethodSymbol attributeSymbol)
                    {
                        // weird, we couldn't get the symbol, ignore it
                        continue;
                    }

                    var attributeContainingTypeSymbol = attributeSymbol.ContainingType;
                    var fullName = attributeContainingTypeSymbol.ToDisplayString();

                    // Is the attribute the [Projcetable] attribute?
                    if (fullName == ProjectablesAttributeName)
                    {

                        sw.Stop();
#pragma warning disable RS1035 // Do not use APIs banned for analyzers
                        File.AppendAllLines(logFilePath, new[]
                        {
                $"[GetSemanticTargetForGeneration FOUND]: {sw.ElapsedMilliseconds}ms",
            });
#pragma warning restore RS1035 // Do not use APIs banned for analyzers
                        sw.Reset();

                        // return the enum
                        return memberDeclarationSyntax;
                    }
                }
            }

            sw.Stop();
#pragma warning disable RS1035 // Do not use APIs banned for analyzers
            File.AppendAllLines(logFilePath, new[]
            {
                $"[GetSemanticTargetForGeneration NOT FOUND]: {sw.ElapsedMilliseconds}ms",
            });
#pragma warning restore RS1035 // Do not use APIs banned for analyzers
            sw.Reset();

            // we didn't find the attribute we were looking for
            return null;
        }

        static void Execute(Compilation compilation, ImmutableArray<MemberDeclarationSyntax> members, SourceProductionContext context)
        {
            if (members.IsDefaultOrEmpty)
            {
                // nothing to do yet
                return;
            }

            var logFilePath = @"C:\current\ProjectablesLog.txt";
            var sw = new Stopwatch();

            sw.Start();

            var projectables = members
                .Select(x => ProjectableInterpreter.GetDescriptor(compilation, x, context))
                .Where(x => x is not null)
                .Select(x => x!);

            var resultBuilder = new StringBuilder();

            foreach (var projectable in projectables)
            {
                if (projectable.MemberName is null)
                {
                    throw new InvalidOperationException("Expected a memberName here");
                }

                var generatedClassName = ProjectionExpressionClassNameGenerator.GenerateName(projectable.ClassNamespace, projectable.NestedInClassNames, projectable.MemberName);
                var generatedFileName = projectable.ClassTypeParameterList is not null ? $"{generatedClassName}-{projectable.ClassTypeParameterList.ChildNodes().Count()}.g.cs" : $"{generatedClassName}.g.cs";

                var classSyntax = ClassDeclaration(generatedClassName)
                    .WithModifiers(TokenList(Token(SyntaxKind.StaticKeyword)))
                    .WithTypeParameterList(projectable.ClassTypeParameterList)
                    .WithConstraintClauses(projectable.ClassConstraintClauses ?? List<TypeParameterConstraintClauseSyntax>())
                    .AddAttributeLists(
                        AttributeList()
                            .AddAttributes(_editorBrowsableAttribute)
                    )
                    .AddMembers(
                        MethodDeclaration(
                            GenericName(
                               Identifier("global::System.Linq.Expressions.Expression"),
                               TypeArgumentList(
                                    SingletonSeparatedList(
                                        (TypeSyntax)GenericName(
                                            Identifier("global::System.Func"),
                                            GetLambdaTypeArgumentListSyntax(projectable)
                                        )
                                    )
                                )
                            ),
                            "Expression"
                        )
                        .WithModifiers(TokenList(Token(SyntaxKind.StaticKeyword)))
                        .WithTypeParameterList(projectable.TypeParameterList)
                        .WithConstraintClauses(projectable.ConstraintClauses ?? List<TypeParameterConstraintClauseSyntax>())
                        .WithBody(
                            Block(
                                ReturnStatement(
                                    ParenthesizedLambdaExpression(
                                        projectable.ParametersList ?? ParameterList(),
                                        null,
                                        projectable.ExpressionBody
                                    )
                                )
                            )
                         )
                    );

#nullable disable

                var compilationUnit = CompilationUnit();

                foreach (var usingDirective in projectable.UsingDirectives)
                {
                    compilationUnit = compilationUnit.AddUsings(usingDirective);
                }

                if (projectable.ClassNamespace is not null)
                {
                    compilationUnit = compilationUnit.AddUsings(
                        UsingDirective(
                            ParseName(projectable.ClassNamespace)
                        )
                    );
                }

                compilationUnit = compilationUnit
                    .AddMembers(
                        NamespaceDeclaration(
                            ParseName("EntityFrameworkCore.Projectables.Generated")
                        ).AddMembers(classSyntax)
                    )
                    .WithLeadingTrivia(
                        TriviaList(
                            Comment("// <auto-generated/>"),
                            Trivia(NullableDirectiveTrivia(Token(SyntaxKind.DisableKeyword), true))
                        )
                    );

                context.AddSource(generatedFileName, SourceText.From(compilationUnit.NormalizeWhitespace().ToFullString(), Encoding.UTF8));

                static TypeArgumentListSyntax GetLambdaTypeArgumentListSyntax(ProjectableDescriptor projectable)
                {
                    var lambdaTypeArguments = TypeArgumentList(
                        SeparatedList(
                            // TODO: Document where clause
                            projectable.ParametersList?.Parameters.Where(p => p.Type is not null).Select(p => p.Type!)
                        )
                    );

                    if (projectable.ReturnTypeName is not null)
                    {
                        lambdaTypeArguments = lambdaTypeArguments.AddArguments(ParseTypeName(projectable.ReturnTypeName));
                    }

                    return lambdaTypeArguments;
                }
            }

            sw.Stop();
#pragma warning disable RS1035 // Do not use APIs banned for analyzers
            File.AppendAllLines(logFilePath, new[]
            {
                $"[EXECUTE]: {sw.ElapsedMilliseconds}ms",
            });
#pragma warning restore RS1035 // Do not use APIs banned for analyzers
            sw.Reset();
        }
    }
}

In the log file, [STEP 1], [STEP 2] and [STEP 3] take 0ms, so the problem is definitely not in them. There is no [EXECUTE] label in the log file, so that method is not invoked I suppose (which makes sense since the is no [Projectable] attribute anywhere in the code).

The is 47124 lines with [GetSemanticTargetForGeneration] label. None of those logs reported any extreme durations (all together summed up are equal to around 8000ms). Perhaps the problem is the amount of invocations of the GetSemanticTargetForGeneration method. I do have A LOT of classes in the project which is probably the reason for a large number of invocations.

ZvonimirMatic commented 5 months ago

I found an article with common pitfalls while implementing IIncrementalGenerator: https://andrewlock.net/creating-a-source-generator-part-9-avoiding-performance-pitfalls-in-incremental-generators/

It seems like points 1, 2, 3 and 5 could be useful for quite a bit of optimization. I will try to do this myself and let you know how it goes.

ZvonimirMatic commented 5 months ago

I found the fix, everything is described in the PR: https://github.com/koenbeuk/EntityFrameworkCore.Projectables/pull/107

Thanks for pointing me in the right direction.

@koenbeuk @PhenX

koenbeuk commented 5 months ago

Thanks @ZvonimirMatic and @PhenX for staying on top of this! I'll publish a new preview build soon.