Slow build with msbuild and dotnet cli

[NinoFloris]

Ok so we migrated over a few weeks ago but I'm really getting annoyed by the lack of incremental build on rc4. Debug times take 13 seconds from f5 to debugger start because dotnet build lacks any and all smarts to see that only the top level project changed so it just rebuilds all projects again.

I don't have any experience with msbuild and I'd expect at least this to just work out of the box. It's even not working for the simplest case

• dotnet new mvc
• dotnet restore
• dotnet build first time builds nicely
• dotnet build changed nothing, starts all over again wasting 3 seconds of my time.

.NET Command Line Tools (1.0.0-rc4-004849)

Product Information:
 Version:            1.0.0-rc4-004849
 Commit SHA-1 hash:  7dcefb5076

Runtime Environment:
 OS Name:     Mac OS X
 OS Version:  10.12
 OS Platform: Darwin
 RID:         osx.10.12-x64
 Base Path:   /usr/local/share/dotnet/sdk/1.0.0-rc4-004849

[livarcocc]

cc @rainersigwald @dsplaisted this is something that should work out of the box.

[rainersigwald]

Indeed it should--and on my machine with the current build it seems to.

Of course, this is on Windows. And naturally my Mac is out of commission today. @NinoFloris can you run

dotnet build
dotnet build /flp:v=diag

And share the resulting MSBuild.log with us? That will help narrow down why you're seeing this.

My results (on Windows):

S:\work\mvc-incremental>dotnet new mvc
Content generation time: 1174.7873 ms
The template "ASP.NET Core Web App" created successfully.

S:\work\mvc-incremental>dotnet restore
  Restoring packages for S:\work\mvc-incremental\mvc-incremental.csproj...
  Generating MSBuild file S:\work\mvc-incremental\obj\mvc-incremental.csproj.nuget.g.props.
  Generating MSBuild file S:\work\mvc-incremental\obj\mvc-incremental.csproj.nuget.g.targets.
  Writing lock file to disk. Path: S:\work\mvc-incremental\obj\project.assets.json
  Restore completed in 6.43 sec for S:\work\mvc-incremental\mvc-incremental.csproj.

  NuGet Config files used:
      C:\Users\raines\AppData\Roaming\NuGet\NuGet.Config
      C:\Program Files (x86)\NuGet\Config\Microsoft.VisualStudio.Offline.config

  Feeds used:
      https://api.nuget.org/v3/index.json
      C:\Program Files (x86)\Microsoft SDKs\NuGetPackages\

S:\work\mvc-incremental>dotnet build /flp:v=diag;logfile=initial.log
Microsoft (R) Build Engine version 15.1.548.43366
Copyright (C) Microsoft Corporation. All rights reserved.

  mvc-incremental -> S:\work\mvc-incremental\bin\Debug\netcoreapp1.1\mvc-incremental.dll

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

Time Elapsed 00:00:08.99

S:\work\mvc-incremental>dotnet build /flp:v=diag;logfile=incremental.log
Microsoft (R) Build Engine version 15.1.548.43366
Copyright (C) Microsoft Corporation. All rights reserved.

  mvc-incremental -> S:\work\mvc-incremental\bin\Debug\netcoreapp1.1\mvc-incremental.dll

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

Time Elapsed 00:00:02.91

S:\work\mvc-incremental>findstr /c:"Skipping target" incremental.log
                   Skipping target "GenerateTargetFrameworkMonikerAttribute" because all output files are up-to-date with respect to the input files.
                   Skipping target "CoreGenerateAssemblyInfo" because all output files are up-to-date with respect to the input files.
                   Skipping target "CoreCompile" because all output files are up-to-date with respect to the input files.
                   Skipping target "GenerateBuildDependencyFile" because all output files are up-to-date with respect to the input files.

[NinoFloris]

Alright sorry for the delay, here is the log https://gist.github.com/NinoFloris/6599e64cd834b2b5e920bdf42467585a

I do see a lot of "Skipping target" happening but I also see at least 1800ms spent on resolving package dependencies and assembly references.

I guess that is what is happening with my other projects as well, this is unacceptably slow though as a hierarchy of even three dependent packages quickly requires almost 10 seconds in total per build, incremental or not...

[davidfowl]

The up to date check in visual studio isn't working. It's a known issue and is being worked on.

/cc @davkean

[davidfowl]

I do see a lot of "Skipping target" happening but I also see at least 1800ms spent on resolving package dependencies and assembly references.

We should look into this though. /cc @emgarten

[NinoFloris]

@davidfowl (Mind you this is on OSX with vscode) but yes I do hope for a fix soon, project.json was blazing fast in comparison

[davidfowl]

Hmm, if this is VS code then it's likely one of the tasks that's taking a long time 😞.

[davidfowl]

From targets:

139 ms  _ComputeLockFileReferences                 1 calls
381 ms  RunResolvePackageDependencies              1 calls
1456 ms  ResolveAssemblyReferences                  1 calls

From tasks:

83 ms  GenerateRuntimeConfigurationFiles          1 calls
379 ms  ResolvePackageDependencies                 1 calls
1454 ms  ResolveAssemblyReference                   1 calls

[NinoFloris]

So you're saying this is fast on windows with VS?

[davidfowl]

Nope, I'm saying there in VS on windows there is a known feature that is currently missing in the new project system with SDK projects, the "up to date" check. Which effectively avoids even calling back into msbuild if nothing in the project changed.

[NinoFloris]

Will something like the lock file come back to fix that?

Or is there already something like that stored somewhere under the hood?

[dasMulli]

There certainly is room optimising incremental builds. Example: (macOS 10.12, CLI 1.0.1, 2016 MacBook Pro)

• Create 3 library projects from template with references: lib1 > lib2 > lib3
• cd lib3
• dotnet restore
• time dotnet build /clp:PerformanceSummary
• build again

Expected: Much faster builds on subsequent builds.

Actual: Build time is only half of the full build, note that there is next to no code and no large number of files that msbuild needs to scan for glob expansion.

First time:

Project Performance Summary:
1604 ms  /Users/martin/tmp/lib1/lib1.csproj         8 calls
3002 ms  /Users/martin/tmp/lib2/lib2.csproj         4 calls
4385 ms  /Users/martin/tmp/lib3/lib3.csproj         1 calls

Target Performance Summary:
      159 ms  GenerateBuildDependencyFile                3 calls
      464 ms  RunResolvePackageDependencies              3 calls
      507 ms  ResolveAssemblyReferences                  3 calls
     2403 ms  CoreCompile                                3 calls
     4945 ms  ResolveProjectReferences                   3 calls

Task Performance Summary:
      157 ms  GenerateDepsFile                           3 calls
      446 ms  ResolvePackageDependencies                 3 calls
      503 ms  ResolveAssemblyReference                   3 calls
     2391 ms  Csc                                        3 calls
     5063 ms  MSBuild                                   10 calls

Time Elapsed 00:00:04.60

real    0m5.116s
user    0m4.702s
sys 0m0.757s

Incremental:

Project Performance Summary:
      596 ms  /Users/martin/tmp/lib1/lib1.csproj         8 calls
     1286 ms  /Users/martin/tmp/lib2/lib2.csproj         4 calls
     1974 ms  /Users/martin/tmp/lib3/lib3.csproj         1 calls

Target Performance Summary:
      125 ms  _ComputeLockFileReferences                 3 calls
      125 ms  _GetProjectReferenceTargetFrameworkProperties   4 calls
      509 ms  RunResolvePackageDependencies              3 calls
      521 ms  ResolveAssemblyReferences                  3 calls
     2318 ms  ResolveProjectReferences                   3 calls

Task Performance Summary:
      490 ms  ResolvePackageDependencies                 3 calls
      519 ms  ResolveAssemblyReference                   3 calls
     2436 ms  MSBuild                                   10 calls

Time Elapsed 00:00:02.26

real    0m2.973s
user    0m2.605s
sys 0m0.522s

[dasMulli]

Note that the lib scenario is much faster with the latest CI 2.0.0 builds targeting netstandard2.0 with first build taking around 1.88s and incremental builds taking around 0.8s. Seems that a large package graph slows builds down dramatically.

[sepplK]

is there a fix available yet for the missing "up2date" check problem?

[rainersigwald]

@sepplK that's tracked by https://github.com/dotnet/project-system/issues/62.

[sepplK]

thanks for info. debugging a solution with 20 projects is unusable slow and we have to wait again with the vs17 upgrade ... how do you handle this at ms? can we use any workarrounds?

[NinoFloris]

@dasMulli suggested something here https://github.com/Microsoft/msbuild/issues/1990#issuecomment-294975195

But there is still the issue that all the dotnet commands launch a build task before the actual command runs, and as we don't have an up-to-date check...

So you'd have to know what dotnet runs when it starts the debugger to evade that pre build task (it used to be a complicated dotnet exec command but it may have changed)

I currently do this though — which would mesh well with dasmulli's approach — I build the solution then I start the entrypoint assembly via dotnet pathto.dll and then attach a debugger to this process. To wait for the debugger I use this snippet

while(!System.Diagnostics.Debugger.IsAttached) { System.Threading.Thread.Sleep(500); }

@davkean @terrajobst It's getting a bit ridiculous having to evade all the build system pitfalls like it is, are you able to share any priority/timeline info?

[davkean]

A quick read of above, are you talking about inside Visual Studio or command-line? https://github.com/dotnet/project-system/issues/62 is tracking VS only.

We have other bugs tracking incremental build, such as https://github.com/dotnet/sdk/issues/1116 and https://github.com/Microsoft/msbuild/issues/1276.

[NinoFloris]

For me it's about dotnet cli. Vs and cli both call into shared parts of project system plumbing right?

[davkean]

dotnet cli and VS basically share the same build infrastructure. In VS, however, due to our live monitoring of the project, we're in a place where we can quickly see if we're already up-to-date and avoid the MSBuild call. There are no current intentions to make the same change to dotnet cli, but we should still make incremental build faster there.

[NinoFloris]

Yes those issues around package & project reference resolvation you linked are the same for any of us referencing the deep and wide package graphs of (ASP).NET Core

[tmds]

Is someone looking at speeding this up? Having to wait seconds for an application to start that has been built before is poor user experience.

[dasMulli]

While it's a lot faster for 2.0 due to the smaller package graphs 🎉 , it's slow again once you add Microsoft.AspNetCore.All to some projects 😢

[NinoFloris]

:/ @livarcocc will anyone give some TLC to this cross platform story?

We xplat users are not able to enjoy all the VS layers on top that make it fast(er) and bearable.

The project.json system could do it without all that VS duct-tape on top so there should still be a lot of improvements possible in the current lower level msbuild implementation.

[livarcocc]

This is definitely something we want to improve. We develop cross-plat nearly 100% of our time ourselves, so we feel this pain. We have it in the books to go look into performance in general for the CLI.

[alohaninja]

It helped us to use dotnet watch run instead of just dotnet run for faster development cycles. Our project was taking 30s to build each time which was ridiculous. When we used XPROJ it was only 10-15s per build-cyle. Compressing the cycle time is critical for rapid development for our team. Using the watch it's now 2-3s for testing CSPROJ changes.

Check out this link for how to add the CSPROJ dependency tool chain. In the CSPROJ, add the following to an ItemGroup - NOT a PropertyGroup. It's awesome that there is already .NET Core extensibility built in to make this faster. This strategy is similar to TypeScript watcher tsc -w which handles JS compilation when source files change.

  <ItemGroup>
    <!-- dotnet watch run -->
    <DotNetCliToolReference Include="Microsoft.DotNet.Watcher.Tools" Version="1.0.0" />
  </ItemGroup>

Also note if you have a debugger attached to the kestrel process you will need to re-attach it. Check out the ReAttach VS IDE extension to make this painless.

[tetious]

I'm seeing build times over a minute, where previously (project.json) I saw 20ish seconds worst case. A full build of my not-very-large at all project with ZERO changes takes nearly 20 seconds now. So that's all overhead, and poking around it seems to all be due to ResolveAssemblyReferences/ResolveProjectReferences.

I think this is the sort of thing that can permanently hurt .net core's reputation. I don't understand why it was acceptable to replace project.json when important regressions like this are present.

The decision to switch away from the new project format, which had numerous advantages, was already a contentious one. The argument I heard was frequently that it was just XML vs json, and it wasn't a huge deal.

It seems that in reality that much like when DNX went away, cross-platform developers have lost a lot and gained nothing with the shift back to csproj. If cross-platform (i.e. not using Visual Studio) development truly is important to MS, I think they need to consider the impact of these sorts of regressions more carefully, and with more weight.

In my opinion, the compile/run/test cycle is one of the most important to get right for developer happiness and productivity. Microsoft doesn't seem to agree, when you consider deeds vs words.

[NinoFloris]

@tetious Thank you for your well written comment, I could not agree more

[andreujuanc]

Running dotnet run takes 50 seconds average to start in my Ubuntu testing box. Which runs in the cheapest azure price tier. The website I'm running it's just 4 views, 2 controllers, no logic, just some localization and just one contact form.

I had some issues to address (paths are case sensitive in linux, so some resources did not get found) when running in linux and it took me literally one entire day to address.

Have another website running in Node and runs like a lighting.

[shanselman]

@davidfowl This started in RC4 timeframe. Is this handled in 2.0?

[jerometerry]

On the latest bits .net core 2.0 preview 2, mac os x (mac air), dotnet run times against a hello, world! console app take 4+ seconds to run, consistently. Roughly the same times on a Mac Pro i tried at work. I was assuming that since I didn't change anything, the second run should have been blazing fast.

Here's the output of dotnet --version and dotnet --info

As a comparison, I generated a hello, world! app with Rust, and ran run 3 times. First compile time was 2.1 seconds, and run times were consistently ~100ms. Run times for rust console app should be pretty close to the theoretical fastet time, since it's compiled to native code. cargo build is incremental - if no files have changed, cargo build finishes in ~100ms.

I was expecting a similar behaviour from the .net runtime, although I would have expected a little overhead due to Rosyln / .NET CLR.

And as another comparison, I re-ran the dotnet core code, but did a build, publish, followed by 3 invocations of the compiled dll.

Running the dotnet dll's is on par with machine code generated by Rust. But the build time was 6.5 seconds, and the publish time was 4.7 seconds.

Timing the dotnet core console app might not be a primary use case, but if the simplest possible dotnet core app is slow compiling, it might give the wrong impression.

[dmbarbour]

@jerometerry There seems to be a separate issue that delays dotnet exec after dotnet run, cf. dotnet/cli#6241

[tverboon]

I would like to add that this also really hurts the productivity with unit tests. We use VS Code on macOS, so it lacks all Visual Studio caching. Changing a test => run test, results in a compile time of 13 seconds, while only the unit test project should rebuild. Add to the 13 seconds, the Xunit test discovery and running the test, it's a big regression.

I like MSBuild and I am familiar with the reasons why MSBuild is the foundation for building .Net Core now. But really, none of it matters if it's this slow. Performance should have been on top the list in my opinion.

I really hope when 2.0.0 is out, performance will be as important as it is for WebKit:

We have a zero-tolerance policy for performance regressions. If a patch lands that regresses performance according to our benchmarks, then the person responsible must either back the patch out of the tree or drop everything immediately and fix the regression.

The way to make a program faster is to never let it get slower.

Edit: The 13 seconds build time is when I test a class library with only three project references. When I test an Mvc project, the build time is approaching 30 seconds, although nothing changed, except a unit test. These times are for building a 35K lines product on an iMac with Core i7 4Ghz.

[tmds]

@livarcocc is someone working on this issue?

[ctolkien]

Even hello world is brutally slow :/

[koczkatamas]

Is there any workaround for this?

Running a hello world console app on a MacBook Air takes 5-10 seconds. Does switching to VS for Mac or to the old Mono-based toolchain help?

I was used to <1 sec compile time with VS17 on Windows and this performance degradation is blocking me from using C# for my project. (If there is no workaround then I will switch to Typescript + node probably...)

[blaudev]

I love .net/C# (pre-core) but when you've tried the nodejs environment it's complicated to wait to compile in .NET

[tverboon]

The sad thing is that performance was mentioned on the .Net Core 2.0 Roadmap: https://github.com/dotnet/core/blob/master/roadmap.md

Performance. Continue to make the performance of building .NET Core applications faster, especially in the inner loop. This is the cycle of changing the source code and then restarting the application and making that as fast as possible.

Let's have some patience. The team is working very hard to get 2.0 out. Hopefully they can work on performance for the next 2.1 release.

[cwe1ss]

My concern is that 2.0 will be a HUGE adoption release and people will be surprised/disappointed when they see how bad the CLI performance is. I guess this will be a reason for many to step back once again.

For us, the great DNX performance was one reason to do the early switch to ASP.NET Core. I fully understand the reasons for all changes that happened since then but it would also have been great to see more performance-related effort for the 2.0 release.

[cwe1ss]

I'm also concerned that making dotnet restore an implicit command will make this performance situation even worse! While I like the idea in theory, a "noop" restore for any reasonable solution is just way too slow right now to always execute it.

People who use the command line for their dev cycle will now have to remember to use dotnet build --no-restore most of the time to not get even worse performance than before.

I hope that at least VS Code and VS will be smart enough to skip the restore when it's not necessary. 😟

[dasMulli]

@cwe1ss did you try out the noop restore? If you see a substantial performance degradation I'd suggest opening a new issue with measurements. (from what I've played with it, that thing is quite fast but I haven't tested in on super large solutions)

hope that at least VS Code and VS will be smart enough to skip the restore when it's not necessary.

That's actually the goal of the noop-restore - check if a restore is necessary and skip it ("no-op") if not needed.

[cwe1ss]

@dasMulli I just did a quick test on a rather small repo of mine: https://github.com/c3-ls/ServiceFabric-Http

dotnet --version
1.0.4
(Measure-Command { git clean -fxd }).TotalSeconds
0.0301536
(Measure-Command { dotnet restore }).TotalSeconds # First restore
1.7914825
(Measure-Command { dotnet build }).TotalSeconds # First build
7.1661289
(Measure-Command { dotnet build }).TotalSeconds # build without any change
3.9407937
(Measure-Command { dotnet build }).TotalSeconds # build without any change
3.9514562
(Measure-Command { dotnet build }).TotalSeconds # build without any change
3.934135

dotnet --version
2.1.0-preview1-006984
(Measure-Command { git clean -fxd }).TotalSeconds
0.196593
(Measure-Command { dotnet build }).TotalSeconds # First build (includes restore)
10.1680267
(Measure-Command { dotnet build }).TotalSeconds # build without any change
7.5226035
(Measure-Command { dotnet build }).TotalSeconds # build without any change
6.8356463
(Measure-Command { dotnet build }).TotalSeconds # build without any change
6.5224566
(Measure-Command { dotnet build --no-restore }).TotalSeconds # build without any change (skip restore)
5.2879741
(Measure-Command { dotnet build --no-restore }).TotalSeconds # build without any change (skip restore)
5.7895082
(Measure-Command { dotnet build --no-restore }).TotalSeconds # build without any change (skip restore)
4.9253091

As you can see, the current daily CLI is a lot slower - even if you do the build without a restore.

[nguerrera]

@cwe1ss Please share a comparison of dotnet build /clp:PerformanceSummary output.

Does this include retargeting to netcoreapp2.0 or netstandard2.0 or just building identical sources with a newer CLI?

[NinoFloris]

Linking back to tracking issue https://github.com/dotnet/project-system/issues/2789

[rhyek]

I'm giving ASP.NET MVC Core a try and I personally use dotnet watch run. Every time I make the smallest change in code, for example a letter in a string somewhere, I hit save and it's a minimum of 6s for the app to be up again.

It's been a tedious development experience so far.

[roelandmoors]

Is it possible that building is faster on Linux than on MacOS? I have a new laptop and use Linux now. Building seems a lot faster. But I also have more mem/cpu so it is hard to compare. If you have slow builds maybe also mention os/mem/cpu/disk here? Maybe also the number of files in the project ?

[dan-i-am]

Just curious if anyone experiencing the extremely slow build times (i.e. very minimal code, but 30+ seconds) has a node_modules folder inside another folder away from where the .csproj file sits.

In my project, I moved all of my Angular CLI project folder items (including the node_modules folder) to the same level as the .csproj, and the build times became much more reasonable (~3-5 seconds). Apparently there's a structure convention at play here to ignore node_modules ONLY if it's in this location relative to the .csproj?

Seems to be the case anyway. If I have the node_modules folder somewhere deeper, and edit the .csproj to exclude the node_modules (or it's parent if attempting to organize a client SPA in it's own folder), this only affects it's visibility within VS2017. The node_modules folder seems to be always hidden from VS's UI no matter where it goes. But it seems that building doesn't actually ignore it unless it's at the same level as .csproj

This is probably a different issue from the slow build being reported here (I'll take 3-5 seconds over 30 for now). But it may explain the extreme performance problems for those building from very small projects.

[dasMulli]

@dan-i-am yes the node_modules folder is excluded at every level, but at non-root level you are hitting a perf issue in msbuild: https://github.com/Microsoft/msbuild/issues/2000 (TL;DR msbuild scans the whole directory structure and then ignores it, but could do better since it knows it is going to ignore it).

A good workaround is to explicitly specify the full folder name that you are going to exclude by adding this to the csproj file:

  <PropertyGroup>
    <DefaultItemExcludes>ClientApp\node_modules\**;$(DefaultItemExcludes)</DefaultItemExcludes>
  </PropertyGroup>

Note that the path must be before $(DefaultItemExcludes) which is unlike most similar re-definitions seen in msbuild project files. (originating from https://github.com/Microsoft/msbuild/issues/2453#issuecomment-323466096)

[jeffhube]

Is there any info I can provide that would help move this issue along? I don't have a node_modules folder, incremental builds are 10+ seconds, and non-incremental builds are 14+ seconds for a small asp net mvc project on .NET Core 2.0 (targeting netcoreapp2.0). This is especially frustrating when issuing multiple dotnet ef commands which repeatedly build the project.

PS> dotnet --version
2.0.0
PS> (Measure-Command { & dotnet build --no-incremental }).TotalSeconds
14.6963322
PS> (Measure-Command { & dotnet build --no-restore --no-incremental }).TotalSeconds
10.2168533
PS> (Measure-Command { & dotnet build }).TotalSeconds
9.3013874
PS> (Measure-Command { & dotnet build --no-restore }).TotalSeconds
4.6437187
PS> (Measure-Command { & dotnet restore }).TotalSeconds
4.6579352

PS> dotnet build --no-incremental /clp:PerformanceSummary

https://gist.github.com/jeffhube/c500507c0ae01847753cbe6e135a163d

PS> dotnet build /clp:PerformanceSummary

https://gist.github.com/jeffhube/85431eb32e5cbaf4dc2e88e6e15c42e6

Windows 10 Pro [Version 10.0.16291.0]
Processor: Intel Core i5-2500K CPU @ 3.30 GHz
Installed memory (RAM): 24.0 GB (23.9 GB usable)
Hard Drive: Samsung SSD 840 EVO

[davkean]

@jeffhube and folks - performance is very top of mind at the moment, and we're actively working on it, we've got https://github.com/dotnet/project-system/issues/2789 which we're using as the uber issue.

We're first focusing on evaluation/target performance - which affects all builds, then we'll peel off and start digging into individual scenarios such as command-line and VS performance - which will be approached differently due to the way they do builds.