Building an ASP.NET project 2-10x slower with .NET 9 vs .NET 8

nwoolls commented 2 months ago

Describe the bug

Building ASP.NET MVC applications with .NET 9 is 2x slower than .NET 8 for basic applications and 10x slower for applications that utilize several client-side libraries (e.g. with LibMan).

To Reproduce

See the following GitHub repository to reproduce: https://github.com/nwoolls/spl-dotnet-9-slow-build

The applications in this project were created with dotnet new mvc. The projects in the simple folder stop at that. The projects in the advanced folder have a handful of client-side libraries that are installed using the LibMan CLI.

Running benchmark.js from the repository yields:

Benchmark results: Simple MVC .NET 8 (avg. seconds): 1.05 Simple MVC .NET 9 (avg. seconds): 2.08 Advanced MVC .NET 8 (avg. seconds): 3.48 Advanced MVC .NET 9 (avg. seconds): 30.96

Exceptions (if any)

Running dotnet clean before dotnet build results in dramatically faster build times, even though the client-side libraries are restored by LibMan prior to the BeforeBuild MSBuild target.

Benchmark results: Simple MVC .NET 8 (avg. seconds): 1.15 Simple MVC .NET 9 (avg. seconds): 2.06 Advanced MVC .NET 8 (avg. seconds): 2.21 Advanced MVC .NET 9 (avg. seconds): 2.42

Further technical details

Include the output of dotnet —info

dotnet --info
.NET SDK:
 Version:           8.0.400
 Commit:            36fe6dda56
 Workload version:  8.0.400-manifests.27c4fe60
 MSBuild version:   17.11.3+0c8610977

Runtime Environment:
 OS Name:     Mac OS X
 OS Version:  14.6
 OS Platform: Darwin
 RID:         osx-arm64
 Base Path:   /usr/local/share/dotnet/sdk/8.0.400/

.NET workloads installed:
Configured to use loose manifests when installing new manifests.
There are no installed workloads to display.

Host:
  Version:      9.0.0-rc.1.24431.7
  Architecture: arm64
  Commit:       static

.NET SDKs installed:
  6.0.425 [/usr/local/share/dotnet/sdk]
  8.0.400 [/usr/local/share/dotnet/sdk]
  9.0.100-preview.7.24407.12 [/usr/local/share/dotnet/sdk]
  9.0.100-rc.1.24452.12 [/usr/local/share/dotnet/sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.App 6.0.33 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 8.0.8 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 9.0.0-preview.7.24406.2 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 9.0.0-rc.1.24452.1 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 6.0.33 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 8.0.8 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 9.0.0-preview.7.24405.7 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 9.0.0-rc.1.24431.7 [/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/nwoolls/src/dotnet/global.json

Learn more:
  https://aka.ms/dotnet/info

Download .NET:
  https://aka.ms/dotnet/download

The IDE (VS / VS Code/ VS4Mac) you're running on, and its version

None

baronfel commented 2 months ago

I don't repro the slowdowns - can you do this again and get binlogs for each run? The in every case, the step that took the longest was the BeforeBuildTasks call of the libman restore tool - this takes several seconds on every build and is not at all designed in the way a good MSBuild integration should be (i.e. tracking incrementality, inputs and outputs, doing some detection to see if the command needs to be run).

It's my strong suspicion that libman is the cause of your delays, and any fixes should be referred to the owners of that tool.

nwoolls commented 2 months ago

@baronfel will do now and post my findings. FWIW that target is not what takes appreciable time for me. Here it's ResolveProjectStaticWebAssets and ResolveBuildCompressedStaticWebAssets - each taking seemingly 10s of seconds.

baronfel commented 2 months ago

in that case cc @javiercn for static web assets delays

nwoolls commented 2 months ago

@baronfel also - not disagreeing per se, but if this were a libman issue I don't see why it wouldn't exist in .NET 8, or why a dotnet clean first would seem to dramatically decrease build times.

baronfel commented 2 months ago

I can only report my findings, I don't know what to tell you otherwise. I am on Windows though which may have different performance characteristics from your macOS host! In any case, binlogs from your repo will be the most accurate thing for us to work from.

nwoolls commented 2 months ago

@baronfel MSBuild binary log files generated and included w/ the repo - e.g.:

https://github.com/nwoolls/spl-dotnet-9-slow-build/blob/main/advanced/mvc-dotnet-9/msbuild.binlog

baronfel commented 2 months ago

Thanks, those really helped! They did confirm that the new static web assets content type handling can be really quite slow:

This is a pretty big slowdown for several hundred assets, I expect this will have very large penalties in real-world applications.

nwoolls commented 2 months ago

I expect this will have very large penalties in real-world applications.

It does 😆.

I apologize for not reporting sooner — this is what kept me away from earlier preview releases. And why I came back for the RC to see if it was fixed.

MackinnonBuck commented 2 months ago

We did have a perf fix for DefineStaticWebAssetEndpoints in https://github.com/dotnet/sdk/pull/43099, which didn't make the cut for RC1. However, I just tried the repro on the latest nightly build and still see the perf issues described in this issue. I collected a trace, and it seems most of the time spent in the static web assets pipeline is on JSON serialization and file system globbing, but @javiercn would know better what the best way to optimize this is.

javiercn commented 1 month ago

@nwoolls thanks for reporting this issue.

It seems that the way Libman is installing packages drops a lot of unnecessary files. In .NET 8.0 those files received minimal processing, hence it wasn't a problem, but with the features we added in .NET 9.0 (Compression, Fingerprinting) those files need to be processed by the build even if they are not used by the app.

The large number of files (around 3K in the advanced repro) is causing many tasks that didn't take a significant amount of time to take much more time to run given the number of files.

We have started working on clawing a bunch of the performance back, some of the changes which we plan to port back to 9.0 https://github.com/dotnet/sdk/pull/43708 https://github.com/dotnet/sdk/pull/43709 https://github.com/dotnet/sdk/pull/43711 https://github.com/dotnet/sdk/pull/43722 https://github.com/dotnet/sdk/pull/43724 https://github.com/dotnet/sdk/pull/43745 as well as some other changes that we have in-flight that we will also consider.

With our current set of changes, the build is down to around 4s for the advanced scenario:

Build succeeded.
Time Elapsed 00:00:05.38

Build succeeded.
Time Elapsed 00:00:04.53

Build succeeded.
Time Elapsed 00:00:04.59

Build succeeded.
Time Elapsed 00:00:05.02

Build succeeded.
Time Elapsed 00:00:04.50

Build succeeded.
Time Elapsed 00:00:04.98

Build succeeded.
Time Elapsed 00:00:04.60

Build succeeded.
Time Elapsed 00:00:04.96

Build succeeded.
Time Elapsed 00:00:04.52

Build succeeded.
Time Elapsed 00:00:04.54

and is faster than 8.0 for the simple scenario:

Build succeeded.
Time Elapsed 00:00:01.29

Build succeeded.
Time Elapsed 00:00:01.25

Build succeeded.
Time Elapsed 00:00:01.26

Build succeeded.
Time Elapsed 00:00:01.25

Build succeeded.
Time Elapsed 00:00:01.27

Build succeeded.
Time Elapsed 00:00:01.26

Build succeeded.
Time Elapsed 00:00:01.26

Build succeeded.
Time Elapsed 00:00:01.26

Build succeeded.
Time Elapsed 00:00:01.26

Build succeeded.
Time Elapsed 00:00:01.25

With that said, there are a few things you can do today to avoid or limit the performance problems you are running into:

Disable compression during the build by setting <CompressionEnabled>false</CompressionEnabled> in your project file and using dotnet publish /p:CompressionEnabled=true to turn it on.
Limit the files in the wwwroot to those that your project will use. You can do this in a couple of ways:
- Telling libman to install a select number of files.
- Using <Content Remove="<<glob-to-remove>" /> to remove unnecessary files from selected packages.
If you have a large folder that you want to exclude during development but want to optimize during publish, conditionally remove it during development and enable StaticFiles for those assets during development using
```
if(Environment.IsDevelopment())
{
  app.UseStaticFiles();
}
```

nwoolls commented 1 month ago

@javiercn while disabling compression does help a bit, we're still seeing 10+ seconds spent on ResolveProjectStaticWebAssets. Is there any way to disable that step, and re-enable for publish?

nwoolls commented 1 month ago

FWIW I've updated to RC.2 and see some marked improvements over RC.1:

Benchmark results: Simple MVC .NET 8 (avg. seconds): 1.15 Simple MVC .NET 9 (avg. seconds): 2.20 Advanced MVC .NET 8 (avg. seconds): 3.63 Advanced MVC .NET 9 (avg. seconds): 22.05

javiercn commented 1 month ago

@javiercn while disabling compression does help a bit, we're still seeing 10+ seconds spent on ResolveProjectStaticWebAssets. Is there any way to disable that step, and re-enable for publish?

There's no way to disable ResolveProjectStaticWebAssets unless you disable static web assets completely, which will prevent you from using content from RCLs and packages.

If all your content is in a single web project and you aren't bringing other content via class libraries or packages you can try disabling static web assets through <StaticWebAssetsEnabled>false</StaticWebAssetsEnabled> and use if(Environment.isDevelopment()) { app.UseStaticFiles(); } on your app.

That said, we are working on porting some of the fixes we've been doing for 9.0. We have more substantial fixes, but we might delay those until we've gotten more validation.

It would help make our case to backport these if you can give it a try with a 10.0 build (The SDK for 10 builds 9.0 just fine) that can be downloaded from https://github.com/dotnet/sdk/blob/main/documentation/package-table.md and report back your build times. The main fixes we are porting back to 9.0 are already available on the nightly build.

On our testing we've brought back parity with 8.0 on the template-like scenarios and we take around 8s for the advanced scenario that you provided with compression enabled and around 4s I believe with it disabled. (Sample runs below) but we want to make sure that this is also helping your scenario.

@nwoolls The way I would suggest you approach this to speed up build times, is to identify folders in your wwwroot with a large amount of assets and remove those from the content item group during development). I believe they will still be served as static files using the fallback path we have in MapStaticAssetEndpoints() and they'll get the standard processing treatment at publish time.

With compression

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

Time Elapsed 00:00:08.12

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

Time Elapsed 00:00:08.20

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

Time Elapsed 00:00:08.11

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

Time Elapsed 00:00:08.29

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

Time Elapsed 00:00:08.13

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

Time Elapsed 00:00:08.21

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

Time Elapsed 00:00:08.15

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

Time Elapsed 00:00:08.16

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

Time Elapsed 00:00:08.15

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

Time Elapsed 00:00:08.19

No compression

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

Time Elapsed 00:00:04.43

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

Time Elapsed 00:00:04.46

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

Time Elapsed 00:00:04.84

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

Time Elapsed 00:00:04.85

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

Time Elapsed 00:00:04.43

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

Time Elapsed 00:00:04.45

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

Time Elapsed 00:00:04.87

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

Time Elapsed 00:00:04.85

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

Time Elapsed 00:00:04.49

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

Time Elapsed 00:00:04.81

nwoolls commented 1 month ago

@javiercn

It would help make our case to backport these if you can give it a try with a 10.0 build (The SDK for 10 builds 9.0 just fine) that can be downloaded from https://github.com/dotnet/sdk/blob/main/documentation/package-table.md and report back your build times. The main fixes we are porting back to 9.0 are already available on the nightly build.

I've done this, and committed the updates (including the MSBuild binary log files from .NET 10) to the repo. My findings are:

Benchmark results: Simple MVC .NET 8.0.403 (avg. seconds): 1.13 Simple MVC .NET 9.0.100-rc.2.24474.11 (avg. seconds): 1.83 Simple MVC .NET 10.0.100-alpha.1.24509.5 (avg. seconds): 1.75 Advanced MVC .NET 8.0.403 (avg. seconds): 3.65 Advanced MVC .NET 9.0.100-rc.2.24474.11 (avg. seconds): 22.14 Advanced MVC .NET 10.0.100-alpha.1.24509.5 (avg. seconds): 20.18

The way I would suggest you approach this to speed up build times, is to identify folders in your wwwroot with a large amount of assets and remove those from the content item group during development).

Thanks - I've done this for our various projects after you mentioned it a couple of weeks ago with great results.

javiercn commented 1 month ago

@nwoolls thanks for the additional details.

Looking at the binlogs there seems to be a huge delta between the time that task takes to run on your environment and what it takes on our machines, which accounts for the majority of the time spent running. In our benchmarking it takes around 1s to 2s, not 11, so there's something going on that it is causing it to take way longer on your environment.

To help us set a common baseline, let's make sure that we are benchmarking things the same way.

The way we are running things is as follows:

git clean -xdff; dotnet build; dotnet build --no-restore; 1..10 | % { dotnet build --no-restore -clp:ErrorsOnly -terminalLogger:off }; 1..3 | % { dotnet build --no-restore /bl:../logs/run-$_.binlog }

There is an ordering problem on the CSPROJ and the assets installed by Libman don't get picked up on the initial build, so we do a build first with restore that makes sure all files get in place, then we do a cold build without restore, and then we loop 10 times running build without restore to get some metrics we can use for what is fair to consider a warm build.

Another question is, what hardware are you running this on and what OS (Windows/Linux/OSX)? Is it a docker container with limited resources or is this your main dev box.

Finally, we've pushed an additional perf improvement to the particular task that is taking longer to run on your hardware. There should be a nightly build available soon, and it would help us a lot if you could try it. We'll post the version here once it's available.

nwoolls commented 1 month ago

@javiercn there is a benchmark.sh in the repo here - that is what I am running. I am doing the same (ish) you are - a clean and build first to make sure the assets are picked up, then looping 5 times with a build. You should be able to grab the benchmark.sh and run on a macOS machine (which is what I am using).

Output of sysinfo.sh is:

sysctl: unknown oid 'machdep.cpu.extfeatures'
sysctl: unknown oid 'machdep.cpu.leaf7_features'
------------------------------------------------------------------------
Current Date:        Mon Oct 14 10:43:34 EDT 2024
Hostname:            Nathanials-MacBook-Pro-M2.local
OS:                  macOS 15.0.1 (24A348)
Kernel:              Darwin 24.0.0
HW Version:          <?xml version="1.0" encoding="utf-8" ?><root><error>0009</error><locale>en_US</locale></root>
HW Serial:           <Redacted>
HW UUID:             <Redacted>
Uptime:              10 days hours
Load Average:        3.27 4.23 6.35
Processor:           Apple M2 Max
Core Count:          12
Virtual Cores:       12
Total Memory:        64.00 gigabytes
Memory Used:         63G used (3587M wired, 7084M compressor), 69M unused.
Internal IP:         192.168.86.218 (Tx/Rx: 10265 MB/34140 MB)
Docker Version:      27.2.0
------------------------------------------------------------------------

nwoolls commented 1 month ago

@javiercn note that I am running AV (Avast) but I tried disabling the file watches and the improvements, while measurable, are not the order of magnitude you are seeing on your system(s).

Benchmark results: Simple MVC .NET 8.0.403 (avg. seconds): .97 Simple MVC .NET 9.0.100-rc.2.24474.11 (avg. seconds): 1.73 Simple MVC .NET 10.0.100-alpha.1.24509.5 (avg. seconds): 1.62 Advanced MVC .NET 8.0.403 (avg. seconds): 3.37 Advanced MVC .NET 9.0.100-rc.2.24474.11 (avg. seconds): 19.77 Advanced MVC .NET 10.0.100-alpha.1.24509.5 (avg. seconds): 18.49

javiercn commented 1 month ago

@nwoolls thanks for the additional details.

Running on Mac and the AV are differences in our environments (we are running windows). With that knowledge, I can try Mac OS.

10.0.100-alpha.1.24509.5

Doesn't contain the latest fix that we checked-in, so it's expected the numbers haven't improved significantly in that regard. The fix we included runs DefineStaticWebAssetEndpoints in parallel, which should (hopefully) significantly speed up that task on your machine.

I'm going to try and see if we can repro this on a Mac on our side, to understand what's taking so long in that scenario.

That task does a lot of JSON serialization internally, so I suspect it might be something at a lower level (S.T.J or the runtime) that runs some code-path slower on Mac.

nwoolls commented 1 month ago

@javiercn here's with the latest 10.0 build. Not sure if this one includes the fix you are referring to. If not I'll try again tomorrow.

Benchmark results: Simple MVC .NET 8.0.403 (avg. seconds): 1.03 Simple MVC .NET 9.0.100-rc.2.24474.11 (avg. seconds): 1.79 Simple MVC .NET 10.0.100-alpha.1.24510.13 (avg. seconds): 1.69 Advanced MVC .NET 8.0.403 (avg. seconds): 3.47 Advanced MVC .NET 9.0.100-rc.2.24474.11 (avg. seconds): 21.41 Advanced MVC .NET 10.0.100-alpha.1.24510.13 (avg. seconds): 19.87

dotnet / sdk