Restore speed is slow in 4.0

[iskiselev]

Details about Problem

NuGet product used: msbuild /restore
VS version: VS 2017 RC4

I have solution with 123 project, ~10 of them are new csproj, most of others are old csproj with project.json.
Currently msbuild /t:restore takes 15 minutes.

Before conversion with xproj and Nuget 3.5 command nuget restore for same solution on same environment took only 2 minutes.

[emgarten]

@iskiselev are you able to share this solution? Does this include downloading packages or is this for a noop restore?

I have seen some slow downs with csproj PackageReference also, but not to that extent. With xproj there was no evaluation needed, all references including projects were in a static json file. With csproj now all of this has to be evaluated through msbuild which unfortunately takes longer than project.json.

Also it is important to point out that to find out if a project has PackageReferences restore has to evaluate it fully. Previously with project.json a simple file scan could determine this.

Still 15 minutes seems way too long, so I'm very interested in getting a repro of this.

From my own testing on projects such as Roslyn which has 155 projects the restore time is around 25 seconds.

[iskiselev]

@emgarten, we probably may share it if NDA will be signed. Would you like me to check it with my managers?

[emgarten]

@iskiselev we can try a few other things first.

• How long does it take you to run msbuild /t:Clean on the solution?
• If you run with verbosity set to detailed which targets does msbuild show as taking the most time in the performance summary when running a restore?

[rrelyea]

@iskiselev - are you able to help answer @iskiselev's questions.

[iskiselev]

I'll try to provide answers to @emgarten questions today.

[iskiselev]

I've done bunch of tests. I've done it on my local machine, so time results a little bit different (it was slower on our build server). I'll provide step-by step description.

1. Restored project from source control (there is no package folder and project.json.lock files on this step). I've restored same packages before, so they likely preserved in NuGet cache
2. Exectute .nuget\NuGet.exe restore MySolution.sln -MsBuildPath "C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\MSBuild\15.0\Bin". NuGet.exe is one of the latest 4.0 RC (4.0.0.2275). I used it, as calling msbuild will not resotore dependecies from project.config. Work time: 6:32.
3. Execute same command again (now all packages are actually restored). Work time: 6:02
4. Execute "C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\MSBuild\15.0\Bin\MSBuild" /t:Clean MySolution.sln. Work time: 22 seconds
5. Execute same command again. Work time: 21 seconds
6. Execute "C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\MSBuild\15.0\Bin\MSBuild" /t:Restore MySolution.sln /flp:Verbosity=detailed;logfile=log.txt. Work time: 6:30. Unfortunately, msbuild doesn't write time stats with detailed log.
7. Execute "C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\MSBuild\15.0\Bin\MSBuild" /t:Restore MySolution.sln /flp:Verbosity=diag;logfile=logDiag.txt. Work time: 11:30. Here is collected statics:

Target Performance Summary:
        0 ms  ValidateToolsVersions                      1 calls
        2 ms  CheckForImplicitPackageReferenceOverridesBeforeRestore  36 calls
       10 ms  _LoadRestoreGraphEntryPoints               1 calls
       13 ms  _FilterRestoreGraphProjectInputItems       1 calls
       25 ms  ValidateSolutionConfiguration              1 calls
      107 ms  _GetRestoreTargetFrameworksOutput         19 calls
      125 ms  _SplitProjectReferencesByFileExistence   176 calls
      176 ms  _GetRestoreProjectStyle                  334 calls
      287 ms  _GenerateRestoreProjectSpec              158 calls
      590 ms  ValidateProjects                           1 calls
      789 ms  _GenerateRestoreProjectReferencePaths    176 calls
      799 ms  _GetProjectJsonPath                      334 calls
     1273 ms  _GenerateRestoreGraphWalkPerFramework    176 calls
    24329 ms  _GetAllRestoreProjectReferences          158 calls
    28485 ms  _GenerateRestoreSpecs                    157 calls
    28619 ms  _GenerateDotnetCliToolReferenceSpecs     157 calls
    30988 ms  _GenerateRestoreDependencies             158 calls
    46836 ms  Restore                                    1 calls
    89187 ms  _GenerateRestoreGraphWalk                158 calls
    89360 ms  _GenerateRestoreGraphProjectEntry        157 calls
    561227 ms  _GetChildRestoreProjects                 158 calls
    643760 ms  _GenerateRestoreGraph                      1 calls

Task Performance Summary:
       70 ms  GetRestoreProjectFrameworks               19 calls
       96 ms  GetRestorePackageReferencesTask           35 calls
      255 ms  GetRestoreDotnetCliToolsTask             157 calls
      381 ms  ConvertToAbsolutePath                    193 calls
      415 ms  Message                                  318 calls
      473 ms  GetRestoreProjectJsonPathTask            282 calls
      940 ms  GetRestoreProjectReferencesTask          176 calls
    22944 ms  RestoreTask                                1 calls
    23887 ms  RemoveDuplicates                           1 calls
    1169222 ms  MsBuild                                  511 calls

For comparison, I checked out same project before conversion to VS 2017, and run twice .nuget\NuGet.exe restore MySolution.sln command. Here I used nuget 3.5.0.1737. First run took 1:15, second ended in just 30 seconds.

[emgarten]

@iskiselev thanks for the detailed feedback!

The number of calls made looks roughly correct here. It seems to be spending a lot of time getting the project references. Is there anything unique about your solution with regards to that? Do the projects contain a large number of project references?

[iskiselev]

@emgarten, probably you are correct. We started converted our core 12 projects to xproj some time ago, and as there was no support for transitive references before VS 2017 for xproj, most of other (~100) projects has reference to that 12 projects, in addition to normal 3-10 references that they actually need. So, I'd say that most of old csproj with prohect.json contains around 15-25 project references.

I'll try to remove that was added only for transitive, and check if it will improve speed, but I won't be able to do it fast - probably in one or two weeks.

[emgarten]

I'll try generating some test solutions with a lot of project to project references to try this out. Keep me posted on what you once you update this also.

[rrelyea]

#4640 may be related...@emgarten is investigating a fix for that.

[iskiselev]

I have cleaned-up most unnecessary transitive p2p references. It works fasted now.
First run nuget restore on clean check-out: 2:45 (my computer), 5:58 (build server)
Second run: 2:13 (my computer).

It still works 2-3 times slower than NuGet 3.5 on our solution, but probably it is acceptable time.

[emgarten]

@iskiselev thanks for the times, I'm glad to hear that helped!

I have some ideas on how perf can be improved for solutions with a lot of p2p references. I'll keep this issue to track that work.

[emgarten]

I was able to repro this using a solution of 127 projects that have 2 target frameworks each and project references to every possible child project.

The current targets file takes 15 minutes (similar to the original issue) to collect all restore inputs from the solution. It looks like this can be improve by finding the full set of projects first and then reading each directly instead of relying on MSBuild caching.

[davkean]

nuget restore used to be 3% of our total build, after this change, msbuild /t:restore is now 27% of our up-to-date build run time.

[emgarten]

The fix for this will be in 4.1.0 (Visual Studio 15.1)

My results for this with 127 interlinked projects:
Before: 900s
After: 21s

[dmitriyse]

I still have this problem. 62 projects are restored in 90 seconds. Machine is fast enough (Core I7-6800k@4.2, SSD).
Tested on NuGet 4.1, 4.2, 4.3 beta. Result the same.
It will be nice to have 20 second for the restore operation.

[dmitriyse]

This is very annoying to wait packages restore 2+ minutes every time after solution opening.

I was forced to perform hack to break VS restore functionality:
In the file: c:\Program Files (x86)\Microsoft Visual Studio\2017\Community\MSBuild\Microsoft\VisualStudio\Managed\Microsoft.Managed.DesignTime.targets

<!-- NuGet Restore Properties -->
<!--    COMMEND THIS
    <PropertyPageSchema Include="$(ManagedXamlResourcesDirectory)NuGetRestore.xaml">
      <Context>ProjectSubscriptionService</Context>
    </PropertyPageSchema>-->

And do packages restore manually by command.

[emgarten]

@dmitriyse you mentioned opening a solution, this issue was fixed for command line restore. It sounds like you seeing slow perf with visual studio automatic package restore which hasn't been fixed yet. Take a look at these issues for more details:

#4307
dotnet/project-system#1600

Also, you can disable auto restore under the NuGet options in Visual Studio. Disable both the automatic package restore options. Then to restore you can right click on the solution node and select restore.

[dmitriyse]

@emgarten Thank you for tip with disabling two checkboxes.

I solved my problem by removing <RuntimeIdentifiers> from all projects.
Now I have 62 projects ~ 35 seconds.

I found that when I put in the project section:

<RuntimeIdentifiers>win7-xxx;ubunty.yyy-yy</RuntimeIdentifiers>

packages are restored 3x times longer.

I think this is real performance BUG. Probably it should be posted in another issue.

Also I think 62 projects ~ 35 seconds is still too much.

[dmitriyse]

Read solution file, then read 62 csproj files, then read brief info from nuget.spec files from the packages cache (.nuget/) + CPU thinking. 1000 Files read +some calculations, then write 62x500kb files should take ~ not more than 10 seconds on modern hardware.

[dmitriyse]

For example in my case 62 projects finally references 506 different packages (according to project.assets.file).