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 dotnet/project-system#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 dotnet/msbuild#1990 (comment)

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? dotnet/project-system#62 is tracking VS only.

We have other bugs tracking incremental build, such as #1116 and dotnet/msbuild#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.

[dasMulli]

Just to make sure the feature is known:

When using my "testbed" linked above with "lib1, referenced by lib2, which is in turn referenced by lib3, which is in turn" ... up to lib20, changing an implementation detail of lib1 causes the build time to be the same as the initial build.

However when adding this to the Directory.Build.props file (or added to every csproj file):

  <PropertyGroup>
    <ProduceReferenceAssembly>true</ProduceReferenceAssembly>
  </PropertyGroup>

The build time is only 1-2 seconds higher during incremental builds (using 2.2.0 CI build, but the feature should already be available in 2.0.0+). Only when the public interface of any assembly is changed (e.g. signature of public methods, types) the build time is as long as the initial build again.

[nguerrera]

@AndyGerlicher @jaredpar How would you feel about turning that on by default for sdk projects?

Failing that, @Pilchie, could we get some nice UI and maybe an info bar to turn it on?

[Pilchie]

Also tagging @jcouv and @rainersigwald . I thought we had turned it on for SDK projects. If not, what are the drawbacks? That it takes longer to produce binaries that are not referenced? Could we turn it on by default for libraries, but not programs or tests?

[AndyGerlicher]

I think the fast-up-to-date check was the last thing holding back from general usage. I don't remember the details, but I think it couldn't statically be known whether or not to rebuild. So it was either always rebuilding or not in certain cases when it should. If we feel comfortable with the state of that with the SDK projects it should definitely be turned on.

[NinoFloris]

@Pilchie Beware though, if I turn this on for all projects in a mixed solution (C# + F#) I get errors where it can't find the ref assembly for the F# projects.

[jeromelaban]

Should this issue be fixed beforehand ? dotnet/msbuild#2431. With VS15.5, incrementally updated assemblies are not picked up the head projects, where the up to date check indeed seems to be too agressive.

[davkean]

Folks, we're still making some pretty good progress - this change NuGet/NuGet.Client#1866 significantly reduces the overhead of implicit restore. We saw up-to-date dotnet build for https://github.com/OrchardCMS/OrchardCore reduce by about 25%.

[FransBouma]

Is there any info about whether 'dotnet build' performs poorly inside a VM (e.g. a VMWare VM with 6 virtual CPUs) ? I have a large .sln with 47 multitargeting csproj files (targeting .net 4.5.2 and .netstandard2.0) (the projects used by our unit tests, they're all generated).

I do in a cmd file:

@Echo off

set destinationRoot="\SomeFolder\"

pushd.
dotnet build -f netstandard2.0 --no-restore -o %destinationRoot%\netstandard2.0 AllUnitTestsSupportProjects.sln 
dotnet build -f net452 --no-restore -o  %destinationRoot%\net452 AllUnitTestsSupportProjects.sln
popd

this needs sometimes 1m22 or 2m23 or thereabout (I don't know why this fluctuates, nothing else is going on on the machine nor VM). Quite slow. When I do on the commandline: msbuild AllUnitTestsSupportProjects.sln /v:m /t:rebuild after a clean, it takes msbuild 22 seconds to build everything.
When I do: dotnet build --no-incremental --no-restore AllUnitTestsSupportProjects.sln it takes 2m12 seconds.

This is inside the VM, VMWare, windows 8.1 x64, visual studio 15.5.5, dotnet 2.1.4. msbuild version: Microsoft (R) Build Engine version 15.5.180.51428 for .NET Framework.

So I copied literally all files in this solution from the VM to the host running the VM. On it vs 2017 15.5.6 (the VM's vs installer apparently can't see an update, the one on the host os did, that aside), dotnet 2.1.4, msbuild version Microsoft (R) Build Engine version 15.5.180.51428 for .NET Core, and the exact same .cmd file takes 41 seconds. Now, VMWare might be slow at times, but not this slow. Also the massive discrepancy between MSBuild on the guest vs. dotnet build isn't normal IMHO.

So my question to you is: what can I do to dig up some information to track down the root cause of this? dotnet build is way slower than msbuild it seems, but even then, it shouldn't be that much of a difference between host and guest on the same hw.

TIA

[mikeharder]

@FransBouma: We haven't seen significant perf differences between a Hyper-V VM and the host. My first guess would be a difference in disk perf. If you can share your solution, I can measure the perf on a physical machine and a Hyper-V VM to see how they compare.

You can also try a daily build of 2.1.300-preview1 which has many performance improvements to .NET Core build. I would expect the relative performance to be the same between the VM and host, but both should be significantly faster.

[FransBouma]

@mikeharder I can't share this code sadly (it's not open source), however I've tried the 2.1.300 preview1 and it solved things :) The total build time is now ~22 seconds (retested) on the guest (VM), so I see the problem I had solved, as the upcoming release contains the fix. No further action required :) (On the host, the 2.1.300 preview1 takes 15 seconds, with 8 core parallel build). Nice progress! :)

[andycmaj]

have a question about build times that might be related to this...

I am working with a large solution with a UI app that delegates Areas (controllers/commands/models/etc.) to a bunch of smaller projects.

I was trying to consolidate all the Area projects (an arbitrary partition, dependency/design-wise) into the main UI project.

example:

root
  - UI.csproj (68 .cs files)
  - Area.Foo.csproj
  - Area.Bar.csproj

|
v

root
  - UI.csproj (537 .cs files)
    - Area.Foo code
    - Area.Bar code

When i built the Before state, after making a change to UI.csproj, i hit about 43 second builds (with 68 files).

After consolidating, builds now take about 3-4 minutes (with 537 .cs files).

I understand why performance would be worse here. Seems like incremental build heuristic can make easier decisions about which src files it doesn't have to re-build if changes are localized to a smaller project that has clearly defined downstream consumer projects.

This make sense, but my original expectation is that i'd save time building/walking/comprehending the dependency tree and transitive package/project dependencies.

In any event... would it be considered a "best practice" or a "recommendation" to split out slow-building projects into lots of smaller partitions for the sake of taking advantage of incremental builds?

[davkean]

It's hard to know without seeing where the time is spent. Do a diagnostic builds of both states and share out the performance sections at the bottom of the log. I suspect csc (compile) is probably the bottle neck.

[NinoFloris]

@davkean any news on reference assembly support for local projects?

So we only rebuild full chain on api changes, or too many issues?

[Pilchie]

@rainersigwald for this one.

[rainersigwald]

@NinoFloris You can opt in to reference assembly support today. There are some docs here but the easiest way to enable it is to set

<PropertyGroup>
  <ProduceReferenceAssembly>true</ProduceReferenceAssembly>
</PropertyGroup>

in a Directory.Build.props file that applies to your projects.

reads upward

Oh, I see you've already tried that and were seeing problems with F#? Is that the problem you're having?

[NullVoxPopuli]

I'm having problems with this and F# as well. it's like it lost track of all my nuget packages

[nguerrera]

@NullVoxPopuli That sounds like a different, more specific issue. Please file it as a new issue and include the steps you take to reproduce the problem. Thanks.

[livarcocc]

Closing this issue as we have done a series of perf improvements for SDK 2.1.300 and while we will continue improving on it, we are not planning any other changes in this area for this release.

[davkean]

As a heads up, more improvements have been made in Preview 2 - https://blogs.msdn.microsoft.com/dotnet/2018/04/11/announcing-net-core-2-1-preview-2/.

[forki]

That sounds good.

[p3rb3r]

Dramatic improvement here. Excellent work 👍

[ghost]

Unfortunately it is still slow on some projects. For example on OrchardCore CMS. The main project has internal dependencies which are every time recompiled and it takes like 6 minutes every build.

You can check it out here: https://github.com/OrchardCMS/OrchardCore

Tested with 2.1.300 on Linux.

[sebastienros]

@adamos101 I can't see this behavior locally with Orchard Core. Even on our CI which uses lower end machine it's faster than that. Also I assume the numbers the team is showing is using Orchard Core for the large project test.

Do you know which dependencies are triggering the issue you are seeing?

[mikeharder]

@adamos101: OrchardCore is actually part of our build perf test suite, though we use a fixed commit SHA (currently https://github.com/OrchardCMS/OrchardCore/tree/21ab3a56d0b93bb5c89285d18faa7b788354c4c0 from Feb 8 2018) rather than the tip of dev.

Here are the warm build times we measure on an Azure DS4_v2 (8-core, SSD) VM running Ubuntu 16.04:

Build Type	Time (s)
Full	55.650
Incremental	22.510

If you are seeing significantly different results (like 6 minutes for an incremental build), please let us know how to reproduce it. I will also update the commit SHA we test to the tip of dev, to see if a recent change in the OrchardCore repo might be causing this.

[ghost]

@mikeharder sorry for the hassle, forget it. It doesn't rebuild the DLLs, they have the same timestamp. It just takes long time to go thru all the project and it is slow on my machine. I think I will need some faster quad core for that. That's why I was thinking it is rebuilding it because on my machine it took 6 minutes but it wasnt rebuilding at all. False alarm :-)

[mikeharder]

@adamos101: We are concerned about slow builds regardless of the root cause. Would you mind sharing the specs of your machine (CPU and disk), the exact command you are running, and how long it takes? I can try to repro on an Azure VM similar to your machine.

[mikeharder]

I am seeing a significant increase in OrchardCore incremental build time between Feb 8 and today:

Commit	Incremental Build Time (s)
5b306d0 (2/8/18)	22.510
e75d7c3 (6/13/18)	37.160

We will investigate this difference, but it might be expected based on the changes to OrchardCore between these dates.