Msbuild: long restore time when node_modules in project folder

Created on 18 Aug 2017 · 13Comments · Source: dotnet/msbuild

I asked the question first on StackOverflow but it was suggested that I should make an issue.

I noticed that building in dotnet core 2 seemed a lot slower.
But the timing after the build always showed 'only' 15 seconds.
I couldn't believe that so I timed it with time.

> time dotnet build
Microsoft (R) Build Engine version 15.3.409.57025 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  hrm -> /Users/r/dev/hrm/bin/Debug/netcoreapp2.0/hrm.dll

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

Time Elapsed 00:00:15.45

real    0m52.366s
user    0m36.851s
sys 0m15.458s

That seemed more correct. Almost a minute.
I then tried without restore and it was a lot faster:

> time dotnet build --no-restore
Microsoft (R) Build Engine version 15.3.409.57025 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  hrm -> /Users/r/dev/hrm/bin/Debug/netcoreapp2.0/hrm.dll

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

Time Elapsed 00:00:15.39

real    0m15.795s
user    0m11.397s
sys 0m4.238s

But dotnet also shows 15 seconds.
Could it be that only building is counted in the timings?
Not sure why a restore is always slow when everything is already restored.

(I'm using osx, my environment is set to development)

I prefer to use dotnet watch run but that seems even slower.
Running dotnet watch to view the parameters is taking 12 seconds.

> time dotnet watch
Microsoft DotNet File Watcher 2.0.0-rtm-26452

Usage: dotnet watch [options] [[--] <arg>...]

Options:
  ....


real    0m12.631s
user    0m8.880s
sys 0m3.816s

Is this only on my system?

Here is the result from dotnet restore /clp:PerformanceSummary

> dotnet restore /clp:PerformanceSummary
  Restore completed in 43.95 ms for /Users/roeland/dev/hrm/hrm.csproj.
  Restore completed in 52.73 ms for /Users/roeland/dev/hrm/hrm.csproj.
  Restore completed in 38.48 ms for /Users/roeland/dev/hrm/hrm.csproj.

Project Evaluation Performance Summary:
    36252 ms  /Users/roeland/dev/hrm/hrm.csproj          3 calls

Project Performance Summary:
    36424 ms  /Users/roeland/dev/hrm/hrm.csproj          9 calls
              24359 ms  Restore                                    1 calls
                  1 ms  _IsProjectRestoreSupported                 2 calls
              12011 ms  _GenerateRestoreProjectPathWalk            1 calls
                  1 ms  _GenerateRestoreProjectPathItemsPerFramework   1 calls
                 43 ms  _GenerateRestoreGraphProjectEntry          1 calls
                  0 ms  _GetRestoreSettingsPerFramework            1 calls
                  6 ms  _GenerateProjectRestoreGraph               1 calls
                  3 ms  _GenerateProjectRestoreGraphPerFramework   1 calls

Target Performance Summary:
        0 ms  _GenerateRestoreGraphProjectEntry          1 calls
        0 ms  _GenerateProjectRestoreGraph               1 calls
        0 ms  _GetRestoreTargetFrameworksAsItems         1 calls
        0 ms  _GetRestoreProjectStyle                    2 calls
        0 ms  CheckForImplicitPackageReferenceOverridesBeforeRestore   2 calls
        0 ms  _CheckForUnsupportedNETCoreVersion         1 calls
        0 ms  _IsProjectRestoreSupported                 1 calls
        0 ms  _GetRestoreSettingsPerFramework            1 calls
        0 ms  _GetProjectJsonPath                        2 calls
        0 ms  _GetRestoreSettingsOverrides               1 calls
        1 ms  _GenerateRestoreProjectPathWalk            1 calls
        1 ms  _GenerateRestoreProjectPathItemsPerFramework   1 calls
        1 ms  _GenerateRestoreSpecs                      1 calls
        1 ms  _GenerateRestoreProjectSpec                1 calls
        2 ms  _GenerateProjectRestoreGraphPerFramework   1 calls
        2 ms  _GetRestoreTargetFrameworksOutput          1 calls
        5 ms  _GenerateRestoreDependencies               1 calls
       10 ms  _LoadRestoreGraphEntryPoints               1 calls
       20 ms  _GenerateDotnetCliToolReferenceSpecs       1 calls
       21 ms  _GetRestoreSettings                        1 calls
       54 ms  _GenerateRestoreGraph                      1 calls
      216 ms  Restore                                    1 calls
    12007 ms  _GenerateRestoreProjectPathItems           1 calls
    12014 ms  _GetAllRestoreProjectPathItems             1 calls
    12058 ms  _FilterRestoreGraphProjectInputItems       1 calls

Task Performance Summary:
        1 ms  Message                                    3 calls
        1 ms  ConvertToAbsolutePath                      2 calls
        1 ms  GetRestorePackageReferencesTask            1 calls
        1 ms  GetRestoreProjectReferencesTask            1 calls
        2 ms  GetRestoreProjectFrameworks                1 calls
        3 ms  RemoveDuplicates                           5 calls
        4 ms  WarnForInvalidProjectsTask                 1 calls
       18 ms  GetRestoreSettingsTask                     1 calls
       20 ms  GetRestoreDotnetCliToolsTask               1 calls
      216 ms  RestoreTask                                1 calls
    36121 ms  MsBuild                                    9 calls

Source

r03

Most helpful comment

If that is true, @r03 you could try this instead:

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

dasMulli on 18 Aug 2017

❤3 👍2

All 13 comments

I turned out that node_modules is causing this. If I remove the folder, it is a lot faster. Is this a bug?

r03 on 18 Aug 2017

This may be an instance of https://github.com/Microsoft/msbuild/issues/2392.

@r03 you mentioned on SO that you're including a node_modules folder in your project so it will be included in the build output?

This has caused issues before (https://github.com/dotnet/cli/issues/5656) and has been "fixed" so that excluding node_modules folders in unexpected locations was optimised in the default items.

dasMulli on 18 Aug 2017

Can you share your project and where the node_modules folder is and what your intent is with that?

dasMulli on 18 Aug 2017

Also, which version of the dotnet cli are you using? (dotnet --info output)

dasMulli on 18 Aug 2017

Here is my project file:

<Project Sdk="Microsoft.NET.Sdk.Web">

  <PropertyGroup>
    <TargetFramework>netcoreapp2.0</TargetFramework>
  </PropertyGroup>

  <ItemGroup>
    <Folder Include="wwwroot\" />
  </ItemGroup>

  <ItemGroup>
    <PackageReference Include="Microsoft.AspNetCore.All" Version="2.0.0" />
    <PackageReference Include="Microsoft.EntityFrameworkCore" Version="2.0.0" />
    <PackageReference Include="Microsoft.EntityFrameworkCore.SqlServer" Version="2.0.0" />
    <PackageReference Include="Newtonsoft.Json" Version="10.0.3" />
  </ItemGroup>

  <ItemGroup>
    <DotNetCliToolReference Include="Microsoft.VisualStudio.Web.CodeGeneration.Tools" Version="2.0.0" />
    <DotNetCliToolReference Include="Microsoft.DotNet.Watcher.Tools" Version="2.0.0" />
  </ItemGroup>

</Project>

I only have a single webapi project with these subfolders:

ClientApp (VueJs with Quasar framework, webpack, ... and of course node_modules)
Controllers (web api's)
Data (Entities, Services, Context, ...)
Framework (reusable libraries, will probably move to separate project in the future)
Middleware (error handling, logging)

dotnet version:

.NET Command Line Tools (2.0.0)

Product Information:
 Version:            2.0.0
 Commit SHA-1 hash:  cdcd1928c9

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/2.0.0/

Microsoft .NET Core Shared Framework Host

  Version  : 2.0.0
  Build    : e8b8861ac7faf042c87a5c2f9f2d04c98b69f28d

r03 on 18 Aug 2017

So the node_modules folder is in ClientApp/node_modules?

This is weird, it should be excluded from the build by the glob pattern defined here: https://github.com/aspnet/websdk/blob/1fd3e2add57478aa29f99cbae06c8bf44c095588/src/ProjectSystem/Microsoft.NET.Sdk.Web.ProjectSystem.Targets/netstandard1.0/Microsoft.NET.Sdk.Web.ProjectSystem.props#L15

dasMulli on 18 Aug 2017

This is probably the more-specific #2000, where it's excluded but we still walk the whole directory.

Can you try adding this to the project?

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

rainersigwald on 18 Aug 2017

👍1

I wonder if it is "safe" if NuGet passed sth like EnableDefaultItems=false to nested msbuild calls as a general perf optimisation..

dasMulli on 18 Aug 2017

Without the exclude: (old situation)

Microsoft (R) Build Engine version 15.3.409.57025 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  hrm -> /Users/roeland/dev/hrm/bin/Debug/netcoreapp2.0/hrm.dll

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

Time Elapsed 00:00:15.55

real    0m54.049s
user    0m38.214s
sys 0m15.642s

After the exclude:

time dotnet build
Microsoft (R) Build Engine version 15.3.409.57025 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  hrm -> /Users/roeland/dev/hrm/bin/Debug/netcoreapp2.0/hrm.dll

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

Time Elapsed 00:00:17.46

real    0m55.652s
user    0m40.653s
sys 0m16.243s

The project file:

<Project Sdk="Microsoft.NET.Sdk.Web">

  <PropertyGroup>
    <TargetFramework>netcoreapp2.0</TargetFramework>
  </PropertyGroup>

  <ItemGroup>
    <Folder Include="wwwroot\" />
  </ItemGroup>

  <ItemGroup>
    <PackageReference Include="Microsoft.AspNetCore.All" Version="2.0.0" />
    <PackageReference Include="Microsoft.EntityFrameworkCore" Version="2.0.0" />
    <PackageReference Include="Microsoft.EntityFrameworkCore.SqlServer" Version="2.0.0" />
    <PackageReference Include="Newtonsoft.Json" Version="10.0.3" />
  </ItemGroup>

  <ItemGroup>
    <DotNetCliToolReference Include="Microsoft.VisualStudio.Web.CodeGeneration.Tools" Version="2.0.0" />
    <DotNetCliToolReference Include="Microsoft.DotNet.Watcher.Tools" Version="2.0.0" />
  </ItemGroup>

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

</Project>

After rm -rf ./ClientApp/node_modules/:

Microsoft (R) Build Engine version 15.3.409.57025 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  hrm -> /Users/roeland/dev/hrm/bin/Debug/netcoreapp2.0/hrm.dll

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

Time Elapsed 00:00:04.88

real    0m10.468s
user    0m8.126s
sys 0m2.357s

r03 on 18 Aug 2017

@rainersigwald is the order of the excludes important? since this comes from an SDK props file, the project will only append to the patterns

dasMulli on 18 Aug 2017

If that is true, @r03 you could try this instead:

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

dasMulli on 18 Aug 2017

❤3 👍2

yes, that works.

Microsoft (R) Build Engine version 15.3.409.57025 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  hrm -> /Users/roeland/dev/hrm/bin/Debug/netcoreapp2.0/hrm.dll

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

Time Elapsed 00:00:06.55

real    0m12.061s
user    0m10.693s
sys 0m2.584s

r03 on 18 Aug 2017

I didn't think order was important there. Boo!

Since it worked once it was in a good order, I'm going to close this as a duplicate of #2000.

rainersigwald on 21 Aug 2017

Was this page helpful?

0 / 5 - 0 ratings