Same projects targeting .NET Core restore slower than .NET Framework (.NET Core App dependencies have more packages)

[rainersigwald]

---

Issue moved from dotnet/sdk#13538

• Please respond to @saul.

---

From @saul on Friday, September 11, 2020 4:36:23 PM

Hi

We're currently in the middle of migrating a large .NET Framework codebase (~350 projects) to .NET Core. Unfortunately we've hit a bit of a roadblock - the NuGet restore times have shot up from ~1:30m -> ~16:00m (an increase of 10x!)

Unfortunately I can't share the full solution as it is sensitive. However I have been able to create a representative solution outside of the office. This representative solution has the same number of projects, the same ProjectReferences and the same third-party PackageReferences. With this representative solution, here are my results:

• .NET Framework restore time: 14s average
• .NET Core restore time: 51s average

Note that the only thing that has changed between .NET Framework and .NET Core is moving from net471 -> netcoreapp3.1. All project/package references remain the same.

Benchmark #1: dotnet restore --force C:\Code\SharedSolutions\SanitisedNetCoreApp3.1\Solution.sln
  Time (mean ± σ):     53.221 s ±  1.505 s    [User: 4.4 ms, System: 4.5 ms]
  Range (min … max):   50.993 s … 55.307 s    10 runs

Benchmark #2: dotnet restore --force C:\Code\SharedSolutions\SanitisedNet471\Solution.sln
  Time (mean ± σ):     14.121 s ±  0.272 s    [User: 1.5 ms, System: 4.5 ms]
  Range (min … max):   13.750 s … 14.481 s    10 runs

You can find the solutions here to test/profile for yourself here:

• SanitisedNet471.zip
• SanitisedNetCoreApp3.1.zip

Any info would be greatly appreciated as we're unable to complete the .NET Core migration without a solution.

Thanks Saul

[rainersigwald]

---

Issue moved from dotnet/sdk#13538

• Please respond to @rainersigwald.

---

From @rainersigwald on Friday, September 11, 2020 8:49:47 PM

On my machine it's not so dramatic, but still noticeable

$ hyperfine -w 1 --parameter-list solution "SanitisedNetCoreApp3.1\Solution.sln,SanitisedNet471\Solution.sln" "dotnet restore --force -nr:false {solution}"
Benchmark #1: dotnet restore --force -nr:false SanitisedNetCoreApp3.1\Solution.sln
Time (mean ± σ):     55.174 s ±  0.987 s    [User: 2.9 ms, System: 6.1 ms]
Range (min … max):   53.103 s … 56.704 s    10 runs

Benchmark #2: dotnet restore --force -nr:false SanitisedNet471\Solution.sln
  Time (mean ± σ):     17.821 s ±  0.306 s    [User: 2.9 ms, System: 4.1 ms]
Range (min … max):   17.313 s … 18.212 s    10 runs

Summary
  'dotnet restore --force -nr:false SanitisedNet471\Solution.sln' ran
    3.10 ± 0.08 times faster than 'dotnet restore --force -nr:false SanitisedNetCoreApp3.1\Solution.sln'

Can you share the tail end of an MSBuild log that has PerformanceSummary turned on? You can add -flp:PerformanceSummary to your command line to get that. The log itself will have possibly-sensitive information in it; the Task Performance Summary should generally not.

net472:

Task Performance Summary:
        1 ms  NuGetMessageTask                           1 calls
        1 ms  WarnForInvalidProjectsTask                 1 calls
        7 ms  GetRestoreSolutionProjectsTask             1 calls
       17 ms  Message                                  676 calls
       28 ms  GetRestorePackageDownloadsTask           337 calls
       31 ms  GetReferenceAssemblyPaths                336 calls
       32 ms  GetRestoreFrameworkReferencesTask        337 calls
       52 ms  GetRestoreDotnetCliToolsTask             337 calls
       53 ms  ApplyImplicitVersions                    220 calls
       66 ms  GetProjectTargetFrameworksTask           337 calls
       69 ms  GetRestorePackageReferencesTask          337 calls
       74 ms  ConvertToAbsolutePath                    674 calls
      112 ms  CheckForImplicitPackageReferenceOverrides 337 calls
      114 ms  GetRestoreProjectStyleTask               337 calls
      152 ms  GetRestoreProjectReferencesTask          337 calls
      217 ms  RemoveDuplicates                         677 calls
     9323 ms  RestoreTask                                1 calls
    11727 ms  GetRestoreSettingsTask                   337 calls
    215032 ms  MsBuild                                  342 calls

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

Time Elapsed 00:00:19.22

netcoreapp3.1:

Task Performance Summary:
        1 ms  NuGetMessageTask                           1 calls
        1 ms  WarnForInvalidProjectsTask                 1 calls
        7 ms  GetRestoreSolutionProjectsTask             1 calls
       21 ms  Message                                  676 calls
       47 ms  GetRestoreFrameworkReferencesTask        337 calls
       48 ms  GetRestorePackageDownloadsTask           337 calls
       52 ms  ApplyImplicitVersions                    220 calls
       53 ms  GetRestorePackageReferencesTask          337 calls
       53 ms  GetRestoreDotnetCliToolsTask             337 calls
       59 ms  CheckIfPackageReferenceShouldBeFrameworkReference 438 calls
       70 ms  CheckForDuplicateFrameworkReferences     336 calls
       70 ms  GetProjectTargetFrameworksTask           337 calls
       76 ms  ConvertToAbsolutePath                    674 calls
       84 ms  CheckForImplicitPackageReferenceOverrides 337 calls
       97 ms  ResolveAppHosts                          336 calls
      141 ms  GetRestoreProjectReferencesTask          337 calls
      181 ms  GetRestoreProjectStyleTask               337 calls
      269 ms  RemoveDuplicates                         677 calls
     1251 ms  ProcessFrameworkReferences               336 calls
     7967 ms  GetRestoreSettingsTask                   337 calls
    46556 ms  RestoreTask                                1 calls
    203468 ms  MsBuild                                  342 calls

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

Time Elapsed 00:00:56.18

If yours looks like that, it'll suggest that the problem is in NuGet rather than the SDK or MSBuild. Narrowing that down will help route.

(also, hyperfine high-five!)

[rainersigwald]

---

Issue moved from dotnet/sdk#13538

• Please respond to @saul.

---

From @saul on Friday, September 11, 2020 9:20:33 PM

@rainersigwald thanks for looking at this so quickly - it's much appreciated. Out of interest, are you able to try restore with --force? The incremental (i.e. no-op) restore is fast for us too - we're seeing this extreme slowness on the build servers, which do clean builds each time.

I'll try to get performance summaries for you soon - I did look at these before, and the vast, vast majority of the time was spent in RestoreTask.

Edit: When I say clean builds, I mean clean code checkouts (i.e. no obj or bin folders) - the local NuGet caches on the build servers are still primed.

[rainersigwald]

---

Issue moved from dotnet/sdk#13538

• Please respond to @rainersigwald.

---

From @rainersigwald on Friday, September 11, 2020 9:38:39 PM

Sorry, I did do that I just pasted the wrong results! edited above to reduce future confusion.

Time spent in RestoreTask is the clue we're looking for to make sure it's a NuGet problem.

[rainersigwald]

---

Issue moved from dotnet/sdk#13538

• Please respond to @saul.

---

From @saul on Friday, September 11, 2020 11:19:22 PM

Here is the performance summary with the real solution:

net471

Target Performance Summary:
        0 ms  ValidateProjects                           1 calls
        0 ms  _CheckForUnsupportedNETStandardVersion     1 calls
        0 ms  ValidateToolsVersions                      1 calls
        3 ms  CollectFrameworkReferences               336 calls
        4 ms  CollectPackageDownloads                  336 calls
        5 ms  _GetRestoreSettingsCurrentProject        336 calls
        7 ms  _GenerateRestoreGraphProjectEntry        336 calls
        7 ms  _GenerateProjectRestoreGraph             336 calls
        7 ms  _GenerateRestoreDependencies             336 calls
        8 ms  _GenerateProjectRestoreGraphCurrentProject 336 calls
        9 ms  _CheckForUnsupportedTargetFrameworkAndFeatureCombination 335 calls
       10 ms  CollectPackageReferences                 336 calls
       11 ms  _GenerateRestoreProjectPathItemsCurrentProject 336 calls
       15 ms  _CheckForObsoleteDotNetCliToolReferences 336 calls
       19 ms  _CheckForUnsupportedCppNETCoreVersion    336 calls
       19 ms  RemoveCoreOnlyPackageReferences          335 calls
       21 ms  _CheckForLanguageAndFeatureCombinationSupport 336 calls
       24 ms  _GetRestoreSettingsOverrides             336 calls
       26 ms  _LoadRestoreGraphEntryPoints               1 calls
       28 ms  _GetRestoreSettingsPerFramework          336 calls
       31 ms  _GetRestoreProjectStyle                  336 calls
       43 ms  _GetProjectJsonPath                      336 calls
       52 ms  ValidateSolutionConfiguration              1 calls
       87 ms  _GenerateRestoreProjectPathItems         336 calls
      101 ms  _GenerateRestoreProjectSpec              336 calls
      141 ms  _GenerateRestoreSpecs                    336 calls
      186 ms  ApplyImplicitVersions                    336 calls
      205 ms  CheckForMissingPackageReferenceVersions  336 calls
      224 ms  _IsProjectRestoreSupported               336 calls
      279 ms  _GenerateDotnetCliToolReferenceSpecs     336 calls
      445 ms  _GetRestoreTargetFrameworksOutput        336 calls
      498 ms  _GenerateProjectRestoreGraphPerFramework 336 calls
      996 ms  _GenerateRestoreProjectPathItemsPerFramework 336 calls
     1220 ms  CheckForImplicitPackageReferenceOverrides 336 calls
     2134 ms  _GetAllRestoreProjectPathItems             1 calls
     2407 ms  CheckForCentralPackageVersionConflicts   336 calls
     3373 ms  _GenerateRestoreGraph                      1 calls
    11259 ms  _FilterRestoreGraphProjectInputItems       1 calls
    13213 ms  _GetRestoreSettings                      336 calls
    23855 ms  UpdatePackageReferences                  90384 calls
    76957 ms  Restore                                    1 calls
    273812 ms  _GenerateRestoreProjectPathWalk          336 calls

Task Performance Summary:
        2 ms  WarnForInvalidProjectsTask                 1 calls
       15 ms  GetRestoreSolutionProjectsTask             1 calls
       32 ms  GetRestoreFrameworkReferencesTask        336 calls
       38 ms  GetRestorePackageDownloadsTask           336 calls
       70 ms  Message                                  674 calls
       94 ms  GetRestorePackageReferencesTask          336 calls
       97 ms  ApplyImplicitVersions                    336 calls
      150 ms  GetRestoreProjectReferencesTask          336 calls
      197 ms  CheckForImplicitPackageReferenceOverrides 336 calls
      206 ms  GetRestoreDotnetCliToolsTask             336 calls
      208 ms  ConvertToAbsolutePath                    672 calls
      345 ms  RemoveDuplicates                         675 calls
      352 ms  GetProjectTargetFrameworksTask           336 calls
    12932 ms  GetRestoreSettingsTask                   336 calls
    76942 ms  RestoreTask                                1 calls
    289928 ms  MsBuild                                  341 calls

netcoreapp3.1

Target Performance Summary:
        0 ms  ValidateProjects                           1 calls
        0 ms  _CheckForUnsupportedTargetFrameworkAndFeatureCombination   2 calls
        0 ms  RemoveCoreOnlyPackageReferences            2 calls
        0 ms  ValidateToolsVersions                      1 calls
        1 ms  _GetRestoreTargetFrameworksAsItems         2 calls
        2 ms  _CheckForUnsupportedNETStandardVersion    39 calls
        4 ms  CollectFrameworkReferences               339 calls
        5 ms  CollectPackageDownloads                  339 calls
        5 ms  _GetRestoreSettingsCurrentProject        335 calls
        7 ms  _GenerateRestoreGraphProjectEntry        337 calls
        7 ms  _GenerateProjectRestoreGraph             337 calls
        7 ms  _GenerateRestoreDependencies             337 calls
        8 ms  _GenerateProjectRestoreGraphCurrentProject 335 calls
       10 ms  _GenerateRestoreProjectPathItemsCurrentProject 335 calls
       15 ms  CollectPackageReferences                 341 calls
       18 ms  _CheckForUnsupportedCppNETCoreVersion    339 calls
       22 ms  _CheckForUnsupportedNETCoreVersion       298 calls
       22 ms  _GetRestoreProjectStyle                  341 calls
       23 ms  _CheckForLanguageAndFeatureCombinationSupport 339 calls
       24 ms  _LoadRestoreGraphEntryPoints               1 calls
       28 ms  _GetRestoreSettingsPerFramework          339 calls
       28 ms  _CheckForObsoleteDotNetCliToolReferences 339 calls
       29 ms  _GetRestoreSettingsOverrides             337 calls
       42 ms  _GetProjectJsonPath                      341 calls
       50 ms  ValidateSolutionConfiguration              1 calls
      103 ms  _GenerateRestoreProjectPathItems         337 calls
      103 ms  GetAllRuntimeIdentifiers                   6 calls
      104 ms  _GenerateRestoreProjectSpec              337 calls
      130 ms  _GenerateRestoreSpecs                    337 calls
      169 ms  ApplyImplicitVersions                    339 calls
      223 ms  _IsProjectRestoreSupported               337 calls
      235 ms  CheckForMissingPackageReferenceVersions  341 calls
      246 ms  _GetRestoreTargetFrameworksOutput        337 calls
      268 ms  _GenerateDotnetCliToolReferenceSpecs     337 calls
      283 ms  _GenerateProjectRestoreGraphAllFrameworks   2 calls
      451 ms  _GenerateProjectRestoreGraphPerFramework 339 calls
      696 ms  _GetRestoreSettingsAllFrameworks           2 calls
      724 ms  UpdateAspNetToFrameworkReference         298 calls
      901 ms  CheckForImplicitPackageReferenceOverrides 339 calls
      969 ms  _GenerateRestoreProjectPathItemsPerFramework 339 calls
     1004 ms  _GenerateRestoreProjectPathItemsAllFrameworks   2 calls
     2260 ms  CheckForCentralPackageVersionConflicts   341 calls
     2289 ms  _GetAllRestoreProjectPathItems             1 calls
     2842 ms  ProcessFrameworkReferences               298 calls
     3377 ms  _GenerateRestoreGraph                      1 calls
    10310 ms  _FilterRestoreGraphProjectInputItems       1 calls
    13780 ms  _GetRestoreSettings                      337 calls
    24352 ms  UpdatePackageReferences                  91729 calls
    295627 ms  _GenerateRestoreProjectPathWalk          337 calls
    1109948 ms  Restore                                    1 calls

Task Performance Summary:
        2 ms  WarnForInvalidProjectsTask                 1 calls
       14 ms  GetRestoreSolutionProjectsTask             1 calls
       39 ms  GetRestoreFrameworkReferencesTask        339 calls
       42 ms  GetRestorePackageDownloadsTask           339 calls
       58 ms  CheckForDuplicateFrameworkReferences     298 calls
       59 ms  Message                                  676 calls
       70 ms  GetRestorePackageReferencesTask          339 calls
       88 ms  ApplyImplicitVersions                    339 calls
      111 ms  GetProjectTargetFrameworksTask           337 calls
      156 ms  GetRestoreProjectReferencesTask          339 calls
      156 ms  CheckForImplicitPackageReferenceOverrides 339 calls
      168 ms  CheckIfPackageReferenceShouldBeFrameworkReference 596 calls
      172 ms  ResolveAppHosts                          298 calls
      186 ms  ConvertToAbsolutePath                    676 calls
      198 ms  GetRestoreDotnetCliToolsTask             337 calls
      307 ms  RemoveDuplicates                         677 calls
     2457 ms  ProcessFrameworkReferences               298 calls
    13445 ms  GetRestoreSettingsTask                   337 calls
    313131 ms  MsBuild                                  358 calls
    1109915 ms  RestoreTask                                1 calls

[rainersigwald]

---

Issue moved from dotnet/sdk#13538

• Please respond to @rainersigwald.

---

From @rainersigwald on Monday, September 14, 2020 3:02:51 PM

Great, thanks! I'm going to move this to the NuGet repo since that's where RestoreTask lives.

[chrise9]

I can add some further statistics gathered from debugging/profiling a local build of Nuget 5.6 against our internal project. The only difference between the restores discussed below are the target frameworks being either net472 or netcoreapp3.1.

Restoring just one of the 350ish projects:

• Net472 takes about 3.6 seconds, of which that is broken down into about 850ms creating the dependency graph inside RemoteDependencyWalker.WalkAsync(), and a similar 800ms traversing the graph inside GraphOperations.Analyze(). In total these steps take less than 50% of the total time.
• Netcoreapp3.1 takes about 32 seconds, and the same breakdown above is 13 seconds to create the graph and 17 second to traverse it (> 90% of the total time)

This shows the appproximate 10x slow down we're seeing on the whole set of projects.

There's nothing particularly remarkable about this project, it has about 15 project references and 10 package references, which are mainly to internal Nuget packages, with one reference to System.Collections.Immutable.

On the restore operation of the whole 350 projects, some stats:

• Net472: about 10m graph nodes are created, split into 4m System., 500k Microsoft. and 5m 'other'. There are about 250m node visits in total.
• Netcoreapp3.1: about 180m graph nodes are created, split into 88m System., 74m Microsoft. and 16m 'other'. There are about 5b node visits in total!

It seems clear that a big part of the change is being caused by the expansion of the dependency graph with additional System. and Microsoft. packages, presumably due to the way .net Core is structured internally.

[nkolev92]

@chrise9

Thanks for doing this investigation. You've done a lot of heavy lifting here already!

I ran the tests on results.txt and the results with the latest nuget client in preview were 90s NC to 60s when everything is completely empty.

In the .NET Core version, there are more packages than the .NET Framework one, but that doesn't explain the complete impact.

You are correct in that the framework is structured in packages in .NET Core. Well, actually was.

While netcoreapp1.x and netcoreapp2.x represented the framework as packages, netcoreapp3.x significantly reduced that. See relevant: https://github.com/dotnet/designs/blob/main/accepted/2019/targeting-packs-and-runtime-packs.md.

I do see quite a few ASP.NET.Core packages that can be replaced with the shared framework concept see: https://docs.microsoft.com/en-us/aspnet/core/fundamentals/target-aspnetcore?view=aspnetcore-3.1&tabs=visual-studio#use-the-aspnet-core-shared-framework.

To truly get the benefits of the 3x changes, you need to remove all packages that do depend on the 1.x and 2.x packages.

Can you try some of those changes and see how your restore time changes?

For reference, I used this script to gather the results I linked above: https://github.com/NuGet/NuGet.Client/blob/343184861e337a695fffb0cf05be4aee23ae6823/scripts/perftests/RunPerformanceTests.ps1#L54.

If you are willing, you can run the script on your actual project and share the results here.

[kastel]

Hi @nkolev92, I'm in the same team as @saul and @chrise9.

Here are the results of the performance test on the real solution (both net472 and netcoreapp3.1 versions): perf-test-results.txt. You can see there's basically a 10x slowdown, much more evident than in the test solution.

As to your suggestion to remove all netcoreapp2.x dependencies, that may not be entirely possible at the moment, as many dependencies are shared with other projects that are still running under net472 and aren't going to be migrated soon.

[nkolev92]

Thanks for those numbers @kastel

Looking at those a little closer, in both net472 & netcoreapp3.1 scenarios, the numbers suggest a slow restore even in the situation where things are not getting download (compare cold vs force).

As to your suggestion to remove all netcoreapp2.x dependencies, that may not be entirely possible at the moment, as many dependencies are shared with other projects that are still running under net472 and aren't going to be migrated soon.

I understand, digging a bit deeper, I might have a few other suggestions.

• Static graph restore. When you have a lot of projects, NuGet spends a lot of time in MSBuild evaluation. For example on my local machine, about ~25s/65s are spent in evaluation for the test netcoreapp31 solution. StaticGraphRestore is an experimental feature that NuGet added recently in 3.1.400 (if you are able to move to that). You can opt in, by setting /p:RestoreUseStaticGraphEvaluation=true.

• ProjectReference - initially I focused on netfx vs netcoreapp sln and the differences there. The differences are primarily the package count, but digging deeper, I can see that the netfx version suffers from well the same problems, just at a smaller scale. In your perf results for example, the ones with the actual projects, I see a cold restore is comparable to the force one (whether almost everything is on disk. In the local version of the sln (which I interpret as having the same project references as the actual sln), the ProjectReference count is 8092! My guess is the slightly larger graph combined with the many project references is a potential factor.

The one thing about the SDK based projects is that they are ProjectReference transitive. That means that P1 -> P2 -> P3, P1 can code against P3.

For example take Projec177 from the repro provided to me. Project177 references Project125, Project134, Project136, Project138. However Project125 already depends on Project134, Project136, Project138.

I know it's not an ideal solution, but it's likely that reducing the number of project references helps here. Unfortunately this work would be very manual.

Another suggestion that didn't show too much improvement on my end, but could be good in general is if you keep the related ASP.NET packages on the same version. For example, consider aligning them all to 2.2.0.

We do have a good repro with the netcore version of the zip, but I am not sure if/when we'd be able to start working on a fix here, so I'm trying to figure out ways where we can help you immediately.

cc @JonDouglas @zivkan @aortiz-msft @srdjanjovcic An interesting case of restore performance :)

[marcin-krystianc]

I've spent some time looking at this issue trying to understand what is the root cause for the observed slowdown. My analysis shows that with a certain topology of the solution the computational complexity of the restore algorithm grows exponentially with the number of projects. It turns out that only a few dozen projects with the right topology of references is enough to make the restore operation to struggle.

To present the problem I've prepared two synthetic solutions (RestoreBomb-net472.zip) and (RestoreBomb-netcoreapp3.1.zip) containing 31 projects with 60 project references and 2 package references :

      -> Lib01 -> Lib03 -> Lib05 ... -> Lib29 -> log4net 2.0.9
  App          X        X            X                
      -> Lib02 -> Lib04 -> Lib06 ... -> Lib30 -> log4net 2.0.9

This topology is the worst case for the graph traversal algorithm (RemoteDependencyWalker.WalkAsync()) as number of nodes needed to represent the graph in memory is doubled for each nesting level of the graph:

                                          ...
                                             
                              -> Lib05       
                             /               
                     -> Lib03                
                    /        \               
                   /          -> Lib06       
                  /                          
          -> Lib01                        ...
         /        \                          
        /          \          -> Lib05       
       /            \        /               
      /              -> Lib04                
     /                       \               
    /                         -> Lib06       
   /                                         
App                                       ...
   \                                         
    \                         -> Lib05       
     \                       /               
      \              -> Lib03                
       \            /        \               
        \          /          -> Lib06       
         \        /                          
          -> Lib02                        ...
                  \                          
                   \          -> Lib05       
                    \        /               
                     -> Lib04                
                             \               
                              -> Lib06       
                                          ...

As a result the graph traversal algorithm creates 32k (2^15) nodes for log4net itself! The log4net package doesn't have any other references for the net472 target, so the graph is not further expanded. However for the necoreapp3.1 target it has references to System.* packages therefore the graph needs to be further expanded. Due to the exponential growth, the total number of nodes in the graph for the necoreapp3.1 case goes from thousands into millions!

Similarly to the original report, there is huge difference in the restore time between the net472 and the netcoreapp3.1 targets:

• RestoreBomb-net472: 2 seconds
• RestoreBomb-netcoreapp3.1: 160 seconds

[nkolev92]

cc @JonDouglas

[JonDouglas]

@marcin-krystianc I was looking into this as well and it seems to really come down to 1.x packages instead of using 2.x packages like netstandard2.0+.

For example, using your scenarios, you will witness this terrible performance straight from loading VS:

https://gist.github.com/JonDouglas/ca808e03fc6a40ca1b7a17d5886c4c57

net472
Time Elapsed: 00:00:06.5711154
========== Finished ==========

vs.

netcoreapp3.1
Time Elapsed: 00:02:31.6097910
========== Finished ==========

However, if you then try the latest version of log4net referenced in your sample based on probably this PR:

https://github.com/apache/logging-log4net/commit/831a8d248ef8ea8b2ffcaaf830a40c42ad3a0e4f edit by nkolev92 + https://github.com/apache/logging-log4net/commit/c728a7065036c641adba471c2a3d79b5a5786c0e

You'll see that performance dramatically improves, purely because of netstandard2.0+ concepts being used and the reference graph being only a single reference.

https://www.nuget.org/packages/log4net/2.0.12

This then turns your sample to be:

net472
Time Elapsed: 00:00:03.5640151
========== Finished ==========

vs.

netcoreapp3.1
Time Elapsed: 00:00:05.4510461
========== Finished ==========

In other words:

was changed to:

And performance should be much faster!

[marcin-krystianc]

Thanks for looking at this. I wasn't even aware that there are newer versions of log4net which don't have this problem with a large dependency graph anymore. I would like to emphasize though that I don't think that this is a problem with log4net or any other particular NuGet package. As it has been shown in my previous comment, the main problem is that the restore algorithm suffers from exponential complexity which was just accidently exposed by switching from net472 to netcoreapp3.1. So to take out log4net and the target framework out of the equation, I prepared another synthetic solution called RestoreNuke. It consists of 51 projects with the graph depth of 25. It is barely restorable as it takes about 17 minutes and requires almost 16GB of RAM to complete the operation. My point is that the restore algorithm doesn't scale too well and given the fact that codebases tend to grow over time, it is very likely that many more developers are going to be affected by this issue in the future.

Tested solution:

      -> Lib01 -> Lib03 -> Lib05 ... -> Lib49
  App          X        X            X                
      -> Lib02 -> Lib04 -> Lib06 ... -> Lib50

Performance result:

dotnet restore -clp:PerformanceSummary -clp:summary --force --disable-parallel

  Determining projects to restore...
  Restored ...\RestoreNuke\Lib50\Lib50.csproj (in 0.9 ms).
  Restored ...\RestoreNuke\Lib49\Lib49.csproj (in 0.7 ms).
  Restored ...\RestoreNuke\Lib48\Lib48.csproj (in 1 ms).
  Restored ...\RestoreNuke\Lib47\Lib47.csproj (in 1 ms).
  Restored ...\RestoreNuke\Lib46\Lib46.csproj (in 1 ms).
  Restored ...\RestoreNuke\Lib45\Lib45.csproj (in 2 ms).
  Restored ...\RestoreNuke\Lib44\Lib44.csproj (in 2 ms).
  Restored ...\RestoreNuke\Lib43\Lib43.csproj (in 2 ms).
  Restored ...\RestoreNuke\Lib42\Lib42.csproj (in 3 ms).
  Restored ...\RestoreNuke\Lib41\Lib41.csproj (in 2 ms).
  Restored ...\RestoreNuke\Lib40\Lib40.csproj (in 3 ms).
  Restored ...\RestoreNuke\Lib39\Lib39.csproj (in 3 ms).
  Restored ...\RestoreNuke\Lib38\Lib38.csproj (in 3 ms).
  Restored ...\RestoreNuke\Lib37\Lib37.csproj (in 3 ms).
  Restored ...\RestoreNuke\Lib36\Lib36.csproj (in 3 ms).
  Restored ...\RestoreNuke\Lib35\Lib35.csproj (in 4 ms).
  Restored ...\RestoreNuke\Lib34\Lib34.csproj (in 5 ms).
  Restored ...\RestoreNuke\Lib33\Lib33.csproj (in 6 ms).
  Restored ...\RestoreNuke\Lib32\Lib32.csproj (in 6 ms).
  Restored ...\RestoreNuke\Lib31\Lib31.csproj (in 8 ms).
  Restored ...\RestoreNuke\Lib30\Lib30.csproj (in 11 ms).
  Restored ...\RestoreNuke\Lib29\Lib29.csproj (in 14 ms).
  Restored ...\RestoreNuke\Lib28\Lib28.csproj (in 16 ms).
  Restored ...\RestoreNuke\Lib27\Lib27.csproj (in 18 ms).
  Restored ...\RestoreNuke\Lib26\Lib26.csproj (in 33 ms).
  Restored ...\RestoreNuke\Lib25\Lib25.csproj (in 31 ms).
  Restored ...\RestoreNuke\Lib24\Lib24.csproj (in 58 ms).
  Restored ...\RestoreNuke\Lib23\Lib23.csproj (in 49 ms).
  Restored ...\RestoreNuke\Lib22\Lib22.csproj (in 106 ms).
  Restored ...\RestoreNuke\Lib21\Lib21.csproj (in 100 ms).
  Restored ...\RestoreNuke\Lib20\Lib20.csproj (in 219 ms).
  Restored ...\RestoreNuke\Lib19\Lib19.csproj (in 208 ms).
  Restored ...\RestoreNuke\Lib18\Lib18.csproj (in 434 ms).
  Restored ...\RestoreNuke\Lib17\Lib17.csproj (in 429 ms).
  Restored ...\RestoreNuke\Lib16\Lib16.csproj (in 867 ms).
  Restored ...\RestoreNuke\Lib15\Lib15.csproj (in 883 ms).
  Restored ...\RestoreNuke\Lib14\Lib14.csproj (in 1.78 sec).
  Restored ...\RestoreNuke\Lib13\Lib13.csproj (in 1.77 sec).
  Restored ...\RestoreNuke\Lib12\Lib12.csproj (in 3.68 sec).
  Restored ...\RestoreNuke\Lib11\Lib11.csproj (in 3.88 sec).
  Restored ...\RestoreNuke\Lib10\Lib10.csproj (in 9.06 sec).
  Restored ...\RestoreNuke\Lib09\Lib09.csproj (in 8.34 sec).
  Restored ...\RestoreNuke\Lib08\Lib08.csproj (in 19.15 sec).
  Restored ...\RestoreNuke\Lib07\Lib07.csproj (in 18.8 sec).
  Restored ...\RestoreNuke\Lib06\Lib06.csproj (in 37.39 sec).
  Restored ...\RestoreNuke\Lib05\Lib05.csproj (in 34.52 sec).
  Restored ...\RestoreNuke\Lib04\Lib04.csproj (in 1.2 min).
  Restored ...\RestoreNuke\Lib03\Lib03.csproj (in 1.19 min).
  Restored ...\RestoreNuke\Lib02\Lib02.csproj (in 2.62 min).
  Restored ...\RestoreNuke\Lib01\Lib01.csproj (in 2.63 min).
  Restored ...\RestoreNuke\App\App.csproj (in 6.92 min).
...

Target Performance Summary:
        0 ms  ValidateProjects                           1 calls
        0 ms  ValidateToolsVersions                      1 calls
        1 ms  CollectFrameworkReferences                51 calls
        1 ms  CollectCentralPackageVersions             51 calls
        1 ms  _GenerateProjectRestoreGraph              51 calls
        1 ms  CollectPackageReferences                  51 calls
        1 ms  _GenerateRestoreGraphProjectEntry         51 calls
        1 ms  CollectPackageDownloads                   51 calls
        1 ms  _GenerateRestoreDependencies              51 calls
        1 ms  _GetRestoreSettingsCurrentProject         51 calls
        1 ms  _GenerateRestoreProjectPathItemsCurrentProject  51 calls
        1 ms  _GenerateProjectRestoreGraphCurrentProject  51 calls
        2 ms  _CheckForUnsupportedTargetFrameworkAndFeatureCombination  51 calls
        3 ms  _CheckForUnsupportedCppNETCoreVersion     51 calls
        3 ms  _CheckForObsoleteDotNetCliToolReferences  51 calls
        6 ms  _GetProjectJsonPath                       51 calls
        6 ms  _CheckForLanguageAndFeatureCombinationSupport  51 calls
        7 ms  _GetRestoreSettingsPerFramework           51 calls
        7 ms  _GetRestoreSettingsOverrides              51 calls
        9 ms  ValidateSolutionConfiguration              1 calls
       10 ms  _LoadRestoreGraphEntryPoints               1 calls
       14 ms  _GenerateRestoreProjectPathItems          51 calls
       27 ms  _GenerateDotnetCliToolReferenceSpecs      51 calls
       30 ms  _GenerateRestoreSpecs                     51 calls
       30 ms  _GenerateRestoreProjectSpec               51 calls
       44 ms  _GetRestoreTargetFrameworksOutput         51 calls
       45 ms  _IsProjectRestoreSupported                51 calls
       46 ms  IncludeTargetingPackReference             51 calls
       93 ms  _GenerateProjectRestoreGraphPerFramework  51 calls
      103 ms  CheckForImplicitPackageReferenceOverrides  51 calls
      145 ms  _GenerateRestoreProjectPathItemsPerFramework  51 calls
      151 ms  _GetRestoreProjectStyle                   51 calls
      196 ms  _GetAllRestoreProjectPathItems             1 calls
      339 ms  _GenerateRestoreGraph                      1 calls
      920 ms  _GetRestoreSettings                       51 calls
     2046 ms  _FilterRestoreGraphProjectInputItems       1 calls
     4288 ms  _GenerateRestoreProjectPathWalk           51 calls
    1016053 ms  Restore                                    1 calls

Task Performance Summary:
        1 ms  WarnForInvalidProjectsTask                 1 calls
        1 ms  NuGetMessageTask                           1 calls
        5 ms  GetRestoreSolutionProjectsTask             1 calls
        8 ms  GetRestoreFrameworkReferencesTask         51 calls
        9 ms  GetRestorePackageReferencesTask           51 calls
       12 ms  GetRestorePackageDownloadsTask            51 calls
       14 ms  GetReferenceAssemblyPaths                 51 calls
       17 ms  GetRestoreDotnetCliToolsTask              51 calls
       18 ms  Message                                  104 calls
       20 ms  RemoveDuplicates                         105 calls
       28 ms  ConvertToAbsolutePath                    102 calls
       29 ms  GetRestoreProjectReferencesTask           51 calls
       29 ms  GetProjectTargetFrameworksTask            51 calls
       48 ms  CheckForImplicitPackageReferenceOverrides  51 calls
       79 ms  GetRestoreProjectStyleTask                51 calls
      909 ms  GetRestoreSettingsTask                    51 calls
     6805 ms  MSBuild                                   56 calls
    1016053 ms  RestoreTask                                1 calls

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

Time Elapsed 00:16:58.82

[nkolev92]

I would like to emphasize though that I don't think that this is a problem with log4net or any other particular NuGet package.

We don't mean to suggest that it's only 1 package that has this problem. The bad perf is a function of the project refs + the depth of the log4net graph. We know of the problems our complex package graphs caused in the 1.x, 2.x .NET Core days, which is why we've gone away from that.

We're aware of the worst time complexity, we're merely trying to understand the scenarios where this happens so we can correctly prioritize our actions.

[lmorvan]

Can we have a status on the resolution of this issue?

We're currently migrating our code base from net48 to net5.0 (~450 projects) and it takes around 15 minutes (previously took 1.5 minute with net48). So we will unexpectedly not be able to move our products to net5.0 under these conditions.

[nkolev92]

@lmorvan

Do you have log4net in your dependencies?

[lmorvan]

Yes, we currently have it at version 2.0.8, going to officially update it to version 2.0.14. This reduces down the restore from 15 minutes to 2min30: way better and acceptable even though it is more than the initial 1min30 ;) I'm going to hunt packages with "too many" dependencies in our solutions.

[marcin-krystianc]

@lmorvan For us, the workaround was to start using "Central package version management" with "transitive dependency pinning", which to some extent helps with the problem of packages with "too many" dependencies.
It is worth noting though, that the transitive dependency pinning is a feature that exists in SDK 5.0.100 but was removed from later versions. There is a pending PR to bring it back https://github.com/NuGet/NuGet.Client/pull/4025.

[nkolev92]

Dup of https://github.com/NuGet/Home/issues/7344.

Beyond general restore improvements, the primary changes will come from https://github.com/NuGet/Home/issues/7344.

[nkolev92]

The recent restore algorithm rewrite did fix the "restore bomb" behavior brought up in https://github.com/NuGet/Home/issues/10030#issuecomment-716432112.

https://github.com/NuGet/Home/issues/13692 was the original tracking issue for that.

On my local machine, the restore-bom netcoreapp3.1 restores in 2s vs the 1 minute with the old algorithm.

So this is very much fixed with https://github.com/NuGet/Home/issues/13692.

https://github.com/NuGet/Home/issues/7344 will just reduce the number of packages even being considered.