dotnet / roslyn-analyzers

MIT License
1.6k stars 468 forks source link

dotnet cli commands perform very slow compared to .NET 7 #7020

Open ShreyasJejurkar opened 1 year ago

ShreyasJejurkar commented 1 year ago

I was just trying to compiler and run a simple console hello world project, and noticed that the dotnet build and dotnet run commands are performing very slowly. So I tried with .NET 7 as well with version 7.0.203 and those are pretty fast as 2x compared to .NET 8.

Please see the command output for more detail. I tried many times but every time .NET 7 builds times faster than .NET 8. Even the dotnet new console command is slow compared to .NET 7.

So looks like something is wrong there or the code has regressed.

.NET 7

  Shreyas2023-06-04 18:02:05  E:/net7  ﲍ 
➜ cat .\global.json
{
  "sdk": {
    "version": "7.0.203"
  }
}
  Shreyas2023-06-04 18:02:10  E:/net7  ﲍ 
➜ dotnet new console
The template "Console App" was created successfully.

Processing post-creation actions...
Restoring E:\net7\net7.csproj:
  Determining projects to restore...
  Restored E:\net7\net7.csproj (in 197 ms).
Restore succeeded.

  Shreyas2023-06-04 18:02:16  E:/net7  ﲍ 
➜ Measure-Command -Expression { dotnet run }

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 2
Milliseconds      : 776
Ticks             : 27766157
TotalDays         : 3.2136755787037E-05
TotalHours        : 0.000771282138888889
TotalMinutes      : 0.0462769283333333
TotalSeconds      : 2.7766157
TotalMilliseconds : 2776.6157

.NET 8

  Shreyas2023-06-04 18:03:51  E:/net8  ﲍ 
➜ cat .\global.json
{
  "sdk": {
    "version": "8.0.100-preview.4.23260.5"
  }
}
  Shreyas2023-06-04 18:04:09  E:/net8  ﲍ 
➜ dotnet new console
The template "Console App" was created successfully.

Processing post-creation actions...
Restoring E:\net8\net8.csproj:
  Determining projects to restore...
  Restored E:\net8\net8.csproj (in 290 ms).
Restore succeeded.

  Shreyas2023-06-04 18:04:18  E:/net8  ﲍ 
➜ Measure-Command -Expression { dotnet run }

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 4
Milliseconds      : 353
Ticks             : 43536428
TotalDays         : 5.03893842592593E-05
TotalHours        : 0.00120934522222222
TotalMinutes      : 0.0725607133333333
TotalSeconds      : 4.3536428
TotalMilliseconds : 4353.6428
Forgind commented 1 year ago

I took a first pass at this just now. I used a different 8.0 preview, and I got a slightly smaller difference between 8.0 and 7.0, but it was still very measurable—over 40% slower.

I compared binlogs from the build part, and build was about 50% slower. Drilling down, the csc task was driving the difference: net8:

image

net7:

image

Glancing through the parameters, the parameter that jumped out at me is that net8 has a new analyzer: Microsoft.Interop.ComInterfaceGenerator.dll

@jaredpar, is there some way I can measure the performance of that analyzer? Happy sharing binlogs or whatever other information you think might be useful in looking into this.

jaredpar commented 1 year ago

@Forgind

Yes pass -p:ReportAnalyzer=true to dotnet build and then there will be a summary of analyzer / generator time included in the binlog. It will make it very evident how much time is spent in every assembly and individual analyzer / generator.

Forgind commented 1 year ago

Well, the good news is that the analyzer is indeed part of the problem; the analyzers for net8 took about 2.5x as long as for net7. The bad news is that that only accounts for about a third of the discrepancy, so there's likely something else going on here. net7.txt net8.txt

I attached a binlog (just change the extension) with analyzer times included for each of net7 and net8. This is the first build experience without the compiler server (or dotnet, etc.) running. You can see that there's about a one-second difference in Csc execution time, which mostly accounts for the total difference in build time (and the rest is likely noise), and about 0.3 seconds of that is from analyzers.

jcouv commented 1 year ago

Assigned to @cston to investigate.

Youssef1313 commented 1 year ago

This might be just because there are new analyzers in .NET 8

ShreyasJejurkar commented 1 year ago

This might be just because there are new analyzers in .NET 8

Agreed. But my question is why those new analyzers are running for a simple "Hello World" program. Newcomers are usually ones who will run this program as their first one, when they see slowness in the compilation itself (if they compared it to what others offer), they will lose motivation for learning .NET there itself.

Glancing through the parameters, the parameter that jumped out at me is that net8 has a new analyzer: Microsoft.Interop.ComInterfaceGenerator.dll

One more thing what this analyzer is getting invoked for a simple hello world program? Is it like code under hood is having com interop? i mean Console.WriteLine ?

jaredpar commented 1 year ago

Moving to roslyn-analyzers

mvarblow commented 10 months ago

I'm seeing something similar. Our builds on some developer machines are very slow. The build log shows that almost all the time is spent in the Csc tasks. A large portion of the time is spent in the ComInterfaceGenerator. For one project, the time in Csc was 5+ minutes(!) and the time in ComInterfaceGenerator was 2 minutes even though the project does no COM interop(!). I tried removing that analyzer using a custom target:

<Target Name="DisableSlowAnalyzers" BeforeTargets="CoreCompile">
    <!-- Building using .NET 8 seems to sometimes be very slow with a lot of time spent in the COM interop generator, which we don't use. Disable it. -->
    <ItemGroup>
        <Analyzer Remove="@(Analyzer)" Condition="'%(Analyzer.Filename)' == 'Microsoft.Interop.ComInterfaceGenerator'"/>
    </ItemGroup>
</Target>

Even with that analyzer removed, the build was still MUCH slower than before we moved to .NET 8. The behavior is not consistent. Some developers experience the build slowness and others don't. So far, none of our (10) CI servers has shown this problem.

Forgind commented 10 months ago

The behavior is not consistent. Some developers experience the build slowness and others don't. So far, none of our (10) CI servers has shown this problem.

This part is very interesting to me. Perhaps there's some extra feature turned off in CI that makes builds unimaginably slower? The only feature I'm aware of is MSBuild's new terminal logger, but I'd be very, very surprised if that was the problem, especially since most of the problem is driven by csc. Is anyone aware of other features turned on by default but turned off in CI?

cston commented 9 months ago

I tried the following with SDK versions 7.0.313 and 8.0.200:

> dotnet new console
> Measure-Command -Expression { dotnet build /t:rebuild }
> Measure-Command -Expression { dotnet build /t:rebuild }
> Measure-Command -Expression { dotnet build /t:rebuild }
> ...

Ignoring the first Measure-Command run in each case, the times varied between runs with either SDK but the times seemed to be in a similar range across the two SDKs: 50ms - 150ms.