long restore time when node_modules in project folder #2453

roelandxyz · 2017-08-18T20:54:03Z

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

The text was updated successfully, but these errors were encountered:

roelandxyz · 2017-08-18T21:00:57Z

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

dasMulli · 2017-08-18T21:01:06Z

This may be an instance of #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 · 2017-08-18T21:01:48Z

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

dasMulli · 2017-08-18T21:07:07Z

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

roelandxyz · 2017-08-18T21:08:43Z

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

dasMulli · 2017-08-18T21:17:20Z

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

rainersigwald · 2017-08-18T21:18:37Z

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>

dasMulli · 2017-08-18T21:26:38Z

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

roelandxyz · 2017-08-18T21:27:07Z

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

dasMulli · 2017-08-18T21:29:24Z

@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 · 2017-08-18T21:34:27Z

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

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

roelandxyz · 2017-08-18T21:36:10Z

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

rainersigwald · 2017-08-21T14:43:32Z

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.

roelandxyz changed the title ~~dotnet core 2 build time incorrect -> long restore time~~ long restore time when node_modules in project folder Aug 18, 2017

rainersigwald closed this as completed Aug 21, 2017

dasMulli mentioned this issue Aug 31, 2017

dotnet restore hangs indefinitely, spinning CPU NuGet/Home#5828

Closed

AR-May added the triaged label Feb 21, 2024

This issue was closed.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

long restore time when node_modules in project folder #2453

long restore time when node_modules in project folder #2453

roelandxyz commented Aug 18, 2017

roelandxyz commented Aug 18, 2017

dasMulli commented Aug 18, 2017

dasMulli commented Aug 18, 2017

dasMulli commented Aug 18, 2017

roelandxyz commented Aug 18, 2017

dasMulli commented Aug 18, 2017

rainersigwald commented Aug 18, 2017

dasMulli commented Aug 18, 2017

roelandxyz commented Aug 18, 2017

dasMulli commented Aug 18, 2017

dasMulli commented Aug 18, 2017

roelandxyz commented Aug 18, 2017 •

edited

Loading

rainersigwald commented Aug 21, 2017

long restore time when node_modules in project folder #2453

long restore time when node_modules in project folder #2453

Comments

roelandxyz commented Aug 18, 2017

roelandxyz commented Aug 18, 2017

dasMulli commented Aug 18, 2017

dasMulli commented Aug 18, 2017

dasMulli commented Aug 18, 2017

roelandxyz commented Aug 18, 2017

dasMulli commented Aug 18, 2017

rainersigwald commented Aug 18, 2017

dasMulli commented Aug 18, 2017

roelandxyz commented Aug 18, 2017

dasMulli commented Aug 18, 2017

dasMulli commented Aug 18, 2017

roelandxyz commented Aug 18, 2017 • edited Loading

rainersigwald commented Aug 21, 2017

roelandxyz commented Aug 18, 2017 •

edited

Loading