50x slower build with .net 6.0.403 compared to 6.0.402

[jfheins]

Describe the bug

With the new path release of .net 6, our build times increased significantly.
A dotnet publish that takes under one minute with .net 6.0.402 now takes about 50 minutes with .net 6.0.403

We see this behaviour in our self-hosted agents (running Ubuntu) but I can also reproduce this locally on Mac M1.

with the pipeline step:

      - script: dotnet publish --force -o bin
        workingDirectory: EndToEndTests
        displayName: Copy artifacts

To Reproduce

Unfortunately this does not seem to reproduce on small example projects. But I am happy to run the CLI or the Azure pipeline with added diagnostic if that helps.

Further technical details

Pipeline log with timestamp:

2022-11-15T09:33:58.3747979Z   project1 -> /agent/_work/2/s/Backend/p1/project1/bin/Debug/net6.0/project1.dll
2022-11-15T09:33:58.6882283Z   project2 -> /agent/_work/2/s/Backend/p2/project2/bin/Debug/net6.0/project2.dll
2022-11-15T10:23:29.7324711Z   project3 -> /agent/_work/2/s/Backend/p3/project3/bin/Debug/net6.0/project3.dll
2022-11-15T10:23:29.7734805Z   project4 -> /agent/_work/2/s/Backend/p4/project4/bin/Debug/net6.0/project4.dll

So it seems to be one project that takes long (out of 90 or so) but it is not always the same project.

Locally, I ran dotnet build and this is what I got:

➜  ATS2 git:(dev) ✗ time (dotnet build) > /dev/null
( dotnet build; ) > /dev/null  6.99s user 3.15s system 102% cpu 9.854 total
➜  ATS2 git:(dev) ✗ dotnet --info
.NET SDK (reflecting any global.json):
 Version:   6.0.402
 Commit:    6862418796

Runtime Environment:
 OS Name:     Mac OS X
 OS Version:  12.6
 OS Platform: Darwin
 RID:         osx.12-arm64
 Base Path:   /usr/local/share/dotnet/sdk/6.0.402/

Host:
  Version:      7.0.0
  Architecture: arm64
  Commit:       d099f075e4

.NET SDKs installed:
  6.0.402 [/usr/local/share/dotnet/sdk]
  6.0.403 [/usr/local/share/dotnet/sdk]
  7.0.100 [/usr/local/share/dotnet/sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.App 6.0.10 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 6.0.11 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 7.0.0 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 6.0.10 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.11 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 7.0.0 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]

Other architectures found:
  x64   [/usr/local/share/dotnet/x64]
    registered at [/etc/dotnet/install_location_x64]

Environment variables:
  Not set

global.json file:
  /Users/Q447843/01_Repos/ATS2/global.json

And with 6.0.403:

➜  ATS2 git:(dev) ✗ time (dotnet build) > /dev/null
( dotnet build; ) > /dev/null  19.56s user 6.65s system 1% cpu 41:05.88 total
➜  ATS2 git:(dev) ✗ dotnet --info
.NET SDK (reflecting any global.json):
 Version:   6.0.403
 Commit:    2bc18bf292

Runtime Environment:
 OS Name:     Mac OS X
 OS Version:  12.6
 OS Platform: Darwin
 RID:         osx.12-arm64
 Base Path:   /usr/local/share/dotnet/sdk/6.0.403/

Host:
  Version:      7.0.0
  Architecture: arm64
  Commit:       d099f075e4

.NET SDKs installed:
  6.0.402 [/usr/local/share/dotnet/sdk]
  6.0.403 [/usr/local/share/dotnet/sdk]
  7.0.100 [/usr/local/share/dotnet/sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.App 6.0.10 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 6.0.11 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 7.0.0 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 6.0.10 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.11 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 7.0.0 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]

Other architectures found:
  x64   [/usr/local/share/dotnet/x64]
    registered at [/etc/dotnet/install_location_x64]

Environment variables:
  Not set

global.json file:
  /Users/Q447843/01_Repos/ATS2/global.json

[baronfel]

Hi @jfheins - can you take a binlog and share it (pending checking it for secrets)? Investigating that in the structured log viewer would show which tasks are at fault here, directing the investigation.

[jfheins]

I had some troubles reproducing the issue (as of today, it does not happen reliably any more), but finally I got a log
removed

[jfheins]

I managed to boil it down to a reproducible example project.
The issue is only present if there are big byte arrays in the source code. In our case, these were auto-generated by Ef core migrations.

The below project should build quickly (with errors) on 6.0.402 but it takes a long time (did not measure) with high CPU load if you run dotnet build with 6.0.403

Adjust the global.json as needed.

ReproExample.zip

[jfheins]

The example project is also very slow to build with Windows 11 x64 and .net SDK 7.0.101 so it seems to reproduce quite well.
(On my laptop it errors after 11 minutes)

[baronfel]

Thanks for the binlog, and sorry for the long delay here. The binlog shows that all of the time (more than 55 minutes) is spent in Csc - the C# compiler itself. I'm going to move to dotnet/roslyn for further analysis.

[cston]

It looks like most of the time is spent within the call to Microsoft.CodeAnalysis.DotnetRuntime.Extensions.ForAttributeWithSimpleName() for a source generator.

The perf issue repros with .NET 6.0.405 but does not repro with .NET 7.0.102. [Correction: The does repro with .NET 7.0.102.]

[CyrusNajmabadi]

Can you make this byte[] into a resource instead?

[cston]

The perf issue results from SyntaxNode.GetChildPosition(int index) which walks previous child nodes when the previous nodes are not cached. (Thanks @CyrusNajmabadi for identifying the underlying cause.) This can occur when the first iteration through the child nodes is in reverse.

The following hits the perf issue:

int n = 100000;
var builder = new StringBuilder();
builder.Append("int[] values = new[] { ");
for (int i = 0; i < n; i++) builder.Append("0, ");
builder.AppendLine("};");

var tree = CSharpSyntaxTree.ParseText(builder.ToString());
var node = tree.GetRoot().DescendantNodes().OfType<InitializerExpressionSyntax>().First();

foreach (var child in node.ChildNodesAndTokens().Reverse())
{
    _ = child.ToString();
}

[jfheins]

The perf issue repros with .NET 6.0.405 but does not repro with .NET 7.0.102.

I just tried this on my work laptop:

➜ ReproExample dotnet --info
.NET SDK:
Version: 7.0.102
Commit: 4bbdd14480

Runtime Environment:
OS Name: Mac OS X
OS Version: 13.2
OS Platform: Darwin
RID: osx.13-arm64
Base Path: /usr/local/share/dotnet/sdk/7.0.102/
...

➜ ReproExample time dotnet build
0 Warning(s)
12 Error(s)

Time Elapsed 00:05:30.61
dotnet build 2.34s user 1.59s system 1% cpu 5:30.79 total

Were you running a preview version?

Can you make this byte[] into a resource instead?

We "solved" this issue by pinning .net 6 to version 6.0.402 and (in addition) just removing the byte arrays. Nevertheless I think that other people may encounter this slowdown as well and it would be nice to fix it.

[cston]

Thanks @jfheins, you're correct, this does repro with .NET 7.0.102. I've updated my comment above.