Slow design-time builds for large solution #27738

marcin-krystianc · 2022-07-13T12:55:47Z

Issue Description

Hi,

productivity in our company is heavily hindered by the slowness of design-time builds which translates into the slowness of solution load (and reload) times in the IDE (Visual Studio and Rider).

For example, we are working with solution containing about 270 C# and F# projects and use Central Package Management to manage version of our NuGet dependencies. The load time of such solution is about 2-3 minutes which is far too long to stay focused.

The fact that we use a mix of C# and F# projects is probably irrelevant because according to my internal testing the solution load time when all projects are C# projects is the same. Also, the usage of central package version management seems to be not really affecting how long it takes to run an individual design-time build. But the concerning consequence of using central package management is that any slightest change in the central file (Directory.Packages.Props) triggers a reload of all projects in the solution so the slowness of design-time builds is exacerbated by central package management.

We've prepared a skeleton version of our solution https://github.com/marcin-krystianc/TestSolutions/tree/master/LargeAppWithPrivatePackagesCentralisedNGBVRemoved which can be used for testing.

I don't think that the problem is unique to our solution though, my suspicion (confirmed with some experiments) is that any solution of similar size has similar performance characteristics. So, given that the problem is relevant to all large solutions, we are wondering whether there are any plans to improve the performance of design-time builds for large solutions? Maybe a static graph feature can help? It turned out to be a huge win for NuGet restores (https://devblogs.microsoft.com/visualstudio/performance-improvements-in-nuget/#msbuild-static-graph-evaluation) so maybe it is possible to apply it for design-time builds as well?
Are you able to provide any hints on where to look for any improvements? Looking at text logs or binary logs (/bl) didn't give any obvious answers so far.

Steps to Reproduce

checkout https://github.com/marcin-krystianc/TestSolutions/tree/master/LargeAppWithPrivatePackagesCentralisedNGBVRemoved
go to the LargeAppWithPrivatePackagesCentralisedNGBVRemoved\solution directory
run dotnet build
Load the solution in IDE or run:

dotnet msbuild /t:GetSuggestedWorkloads;_CheckForInvalidConfigurationAndPlatform;ResolveReferences;ResolveProjectReferences;ResolveAssemblyReferences;ResolveComReferences;ResolveNativeReferences;ResolveSdkReferences;ResolveFrameworkReferences;ResolvePackageDependenciesDesignTime;Compile;CoreCompile ^
/p:AndroidPreserveUserData=True ^
/p:AndroidUseManagedDesignTimeResourceGenerator=True ^
/p:BuildingByReSharper=True ^
/p:BuildingProject=False ^
/p:BuildProjectReferences=False ^
/p:ContinueOnError=ErrorAndContinue ^
/p:DesignTimeBuild=True ^
/p:DesignTimeSilentResolution=False ^
/p:JetBrainsDesignTimeBuild=True ^
/p:ProvideCommandLineArgs=True ^
/p:ResolveAssemblyReferencesSilent=False ^
/p:SkipCompilerExecution=True ^
/p:TargetFramework=net5.0 ^
/v:n ^
/m:1 ^
/bl ^
/flp:v=n;PerformanceSummary ^
/clp:Summary ^
/clp:PerformanceSummary > log.txt

Data

Sample logs from the command above. Please note, that this is not exactly the same as loading the solution in IDE, because IDE runs desgn-time build for each project individually wehereas we run it for entire solution all at once:

...
     851 ms  d:\workspace\TestSolutions\LargeAppWithPrivatePackagesCentralisedNGBVRemoved\solution\Project53\Project53.fsproj  24 calls
                  0 ms  GetSuggestedWorkloads                      1 calls
                  7 ms  _CheckForInvalidConfigurationAndPlatform   1 calls
                600 ms  ResolveReferences                          1 calls
                  2 ms  GetTargetFrameworks                        6 calls
                  1 ms  GetTargetPath                              6 calls
                  0 ms  ResolveProjectReferences                   1 calls
                  0 ms  ResolveAssemblyReferences                  1 calls
                  0 ms  ResolveComReferences                       1 calls
                  0 ms  ResolveNativeReferences                    1 calls
                  0 ms  ResolveSdkReferences                       1 calls
                  0 ms  ResolveFrameworkReferences                 1 calls
                161 ms  ResolvePackageDependenciesDesignTime       1 calls
                 79 ms  Compile                                    1 calls
                  0 ms  CoreCompile                                1 calls
     1001 ms  d:\workspace\TestSolutions\LargeAppWithPrivatePackagesCentralisedNGBVRemoved\solution\Project12\Project12.fsproj  15 calls
                  0 ms  GetSuggestedWorkloads                      1 calls
                  7 ms  _CheckForInvalidConfigurationAndPlatform   1 calls
                791 ms  ResolveReferences                          1 calls
                  3 ms  GetTargetFrameworks                        1 calls
                  0 ms  GetTargetFrameworksWithPlatformForSingleTargetFramework   1 calls
                  0 ms  GetTargetPath                              1 calls
                  0 ms  ResolveProjectReferences                   1 calls
                  0 ms  ResolveAssemblyReferences                  1 calls
                  0 ms  ResolveComReferences                       1 calls
                  0 ms  ResolveNativeReferences                    1 calls
                  0 ms  ResolveSdkReferences                       1 calls
                  0 ms  ResolveFrameworkReferences                 1 calls
                127 ms  ResolvePackageDependenciesDesignTime       1 calls
                 70 ms  Compile                                    1 calls
                  0 ms  CoreCompile                                1 calls
     1392 ms  d:\workspace\TestSolutions\LargeAppWithPrivatePackagesCentralisedNGBVRemoved\solution\Project276\Project276.csproj  12 calls
                  0 ms  GetSuggestedWorkloads                      1 calls
                  5 ms  _CheckForInvalidConfigurationAndPlatform   1 calls
               1113 ms  ResolveReferences                          1 calls
                  0 ms  ResolveProjectReferences                   1 calls
                  0 ms  ResolveAssemblyReferences                  1 calls
                  0 ms  ResolveComReferences                       1 calls
                  0 ms  ResolveNativeReferences                    1 calls
                  0 ms  ResolveSdkReferences                       1 calls
                  0 ms  ResolveFrameworkReferences                 1 calls
                198 ms  ResolvePackageDependenciesDesignTime       1 calls
                 76 ms  Compile                                    1 calls
                  0 ms  CoreCompile                                1 calls
     3875 ms  d:\workspace\TestSolutions\LargeAppWithPrivatePackagesCentralisedNGBVRemoved\solution\Project47\Project47.fsproj  26 calls
                  1 ms  GetSuggestedWorkloads                      1 calls
                113 ms  _CheckForInvalidConfigurationAndPlatform   1 calls
               3426 ms  ResolveReferences                          1 calls
                  2 ms  GetTargetFrameworks                        7 calls
                  1 ms  GetTargetPath                              7 calls
                  0 ms  ResolveProjectReferences                   1 calls
                  0 ms  ResolveAssemblyReferences                  1 calls
                  0 ms  ResolveComReferences                       1 calls
                  0 ms  ResolveNativeReferences                    1 calls
                  0 ms  ResolveSdkReferences                       1 calls
                  0 ms  ResolveFrameworkReferences                 1 calls
                224 ms  ResolvePackageDependenciesDesignTime       1 calls
                105 ms  Compile                                    1 calls
                  0 ms  CoreCompile                                1 calls
    125614 ms  d:\workspace\TestSolutions\LargeAppWithPrivatePackagesCentralisedNGBVRemoved\solution\LargeAppWithPrivatePackagesCentralisedNGBVRemoved.sln   1 calls
              125614 ms  GetSuggestedWorkloads;_CheckForInvalidConfigurationAndPlatform;ResolveReferences;ResolveProjectReferences;ResolveAssemblyReferences;ResolveComReferences;ResolveNativeReferences;ResolveSdkReferences;ResolveFrameworkReferences;ResolvePackageDependenciesDesignTime;Compile;CoreCompile   1 calls

Target Performance Summary:
        0 ms  ValidateProjects                           1 calls
        0 ms  ValidateToolsVersions                      1 calls
        2 ms  GenerateMSBuildEditorConfigFile          155 calls
        2 ms  InitializeSourceControlInformation       276 calls
        3 ms  ResolvePackageDependenciesForBuild       276 calls
        3 ms  GetReferenceAssemblyPaths                276 calls
        3 ms  AddSourceRevisionToInformationalVersion  276 calls
        3 ms  GenerateAssemblyInfo                     276 calls
        3 ms  GetTargetPath                            212 calls
        3 ms  SetWin32ManifestProperties               276 calls
        4 ms  AfterCompile                             276 calls
        4 ms  PrepareProjectReferences                 276 calls
        4 ms  GetFrameworkPaths                        276 calls
        5 ms  _SetTargetFrameworkMonikerAttribute      155 calls
        5 ms  BeforeResolveReferences                  276 calls
        6 ms  _ReportUpgradeNetAnalyzersNuGetWarning   155 calls
        6 ms  AfterResolveReferences                   276 calls
        6 ms  EnableIntermediateOutputPathMismatchWarning 276 calls
        7 ms  BeforeCompile                            276 calls
        7 ms  _AddOutputPathToGlobalPropertiesToRemove 276 calls
        8 ms  _BeforeVBCSCoreCompile                   155 calls
        8 ms  _CheckForUnsupportedHostingUsage         276 calls
        9 ms  _GetProjectJsonPath                      276 calls
        9 ms  _DefaultMicrosoftNETPlatformLibrary      276 calls
        9 ms  CollectPackageReferences                 276 calls
       10 ms  _CheckForUnsupportedAppHostUsage          70 calls
       10 ms  ExpandSDKReferences                      276 calls
       10 ms  ResolveLockFileAnalyzers                 276 calls
       11 ms  _CheckForObsoleteDotNetCliToolReferences 276 calls
       12 ms  ValidateSolutionConfiguration              1 calls
       12 ms  ValidateCommandLineProperties            276 calls
       13 ms  AddImplicitDefineConstants               276 calls
       14 ms  _CheckForUnsupportedCppNETCoreVersion    276 calls
       14 ms  _CheckForUnsupportedNETCoreVersion       276 calls
       16 ms  _CheckForLanguageAndFeatureCombinationSupport 276 calls
       18 ms  GenerateProgramFile                       70 calls
       18 ms  GenerateMSBuildEditorConfigFileShouldRun 155 calls
       19 ms  CollectFSharpDesignTimeTools             121 calls
       23 ms  GetTargetPathWithTargetPlatformMoniker   212 calls
       27 ms  _ComputePackageReferencePublish          276 calls
       28 ms  _ComputeSkipAnalyzers                    155 calls
       35 ms  _ComputeTargetFrameworkItems             144 calls
       49 ms  AddGlobalAnalyzerConfigForPackage_MicrosoftCodeAnalysisNetAnalyzers 155 calls
       51 ms  _GenerateCompileInputs                   276 calls
       55 ms  GetAssemblyVersion                       276 calls
       58 ms  _CollectTargetFrameworkForTelemetry      276 calls
       58 ms  CheckForImplicitPackageReferenceOverrides 276 calls
       62 ms  _SetEmbeddedWin32ManifestProperties      276 calls
       68 ms  GetTargetFrameworks                      212 calls
       72 ms  GetAssemblyAttributes                    276 calls
       84 ms  GenerateFSharpTextResources              121 calls
       86 ms  GetTargetFrameworksWithPlatformForSingleTargetFramework 212 calls
       91 ms  ResolveSDKReferences                     277 calls
      109 ms  ApplyImplicitVersions                    276 calls
      111 ms  _GetRestoreProjectStyle                  276 calls
      118 ms  CheckForDuplicateItems                   276 calls
      121 ms  UpdateAspNetToFrameworkReference         276 calls
      124 ms  IncludeTransitiveProjectReferences       276 calls
      131 ms  _GetFrameworkAssemblyReferences          121 calls
      142 ms  ValidateExecutableReferences             206 calls
      143 ms  GenerateMSBuildEditorConfigFileCore      155 calls
      195 ms  PrepareForBuild                          276 calls
      216 ms  ResolveNativeReferences                    1 calls
      240 ms  ResolveComReferences                       1 calls
      288 ms  GenerateNETCompatibleDefineConstants     276 calls
      293 ms  CreateGeneratedAssemblyInfoInputsCacheFile 276 calls
      337 ms  CoreGenerateAssemblyInfo                 276 calls
      348 ms  GenerateTargetFrameworkMonikerAttribute  276 calls
      420 ms  ResolveFrameworkReferences               277 calls
      494 ms  GetTargetFrameworksWithPlatformFromInnerBuilds 144 calls
      662 ms  RedirectTPReferenceToNewRedistributableLocation 121 calls
      733 ms  _GenerateCompileDependencyCache          121 calls
      735 ms  ProcessFrameworkReferences               276 calls
      760 ms  ResolveLockFileCopyLocalFiles            276 calls
      939 ms  ResolveTargetingPackAssets               276 calls
     1044 ms  RedirectFSharpCoreReferenceToNewRedistributableLocation 121 calls
     1123 ms  ResolveLockFileReferences                276 calls
     1146 ms  ResolveAssemblyReferencesDesignTime      276 calls
     1527 ms  AssignProjectConfiguration               276 calls
     2019 ms  _SplitProjectReferencesByFileExistence   276 calls
     2084 ms  _CheckForInvalidConfigurationAndPlatform 277 calls
     4153 ms  ResolvePackageAssets                     276 calls
     4199 ms  CoreCompile                              277 calls
     5660 ms  ResolveProjectReferences                 277 calls
     7393 ms  FindReferenceAssembliesForReferences     276 calls
     8683 ms  GetSuggestedWorkloads                      1 calls
     9185 ms  _HandlePackageFileConflicts              276 calls
    11768 ms  _GetProjectReferenceTargetFrameworkProperties 276 calls
    14755 ms  Compile                                  277 calls
    18153 ms  ResolveAssemblyReferences                277 calls
    31281 ms  RunResolvePackageDependencies            276 calls
    40710 ms  ResolvePackageDependenciesDesignTime     277 calls
    60595 ms  ResolveReferences                        277 calls

Task Performance Summary:
        3 ms  Message                                    1 calls
       12 ms  GetFrameworkPath                         276 calls
       13 ms  FSharpEmbedResXSource                    121 calls
       17 ms  FSharpEmbedResourceText                  121 calls
       24 ms  GetAssemblyVersion                       276 calls
       24 ms  FindAppConfigFile                        276 calls
       29 ms  AllowEmptyTelemetry                      276 calls
       31 ms  CheckForDuplicateFrameworkReferences     276 calls
       31 ms  CombineXmlElements                       212 calls
       32 ms  CheckForImplicitPackageReferenceOverrides 276 calls
       33 ms  CombineTargetFrameworkInfoProperties     212 calls
       45 ms  ApplyImplicitVersions                    276 calls
       48 ms  ResolveFrameworkReferences               276 calls
       62 ms  GenerateMSBuildEditorConfig              155 calls
       67 ms  GetRestoreProjectStyleTask               276 calls
       69 ms  ResolveAppHosts                          276 calls
       72 ms  CheckForDuplicateItems                   828 calls
       83 ms  CheckIfPackageReferenceShouldBeFrameworkReference 552 calls
      124 ms  ValidateExecutableReferences             206 calls
      138 ms  Hash                                     397 calls
      153 ms  GetPackageDirectory                      2208 calls
      163 ms  MakeDir                                  397 calls
      342 ms  JoinItems                                276 calls
      343 ms  WriteLinesToFile                         397 calls
      534 ms  ProcessFrameworkReferences               276 calls
      858 ms  ResolveTargetingPackAssets               276 calls
     1331 ms  GetReferenceNearestTargetFrameworkTask   304 calls
     1341 ms  AssignProjectConfiguration               276 calls
     1350 ms  Fsc                                      121 calls
     3434 ms  PreprocessPackageDependenciesDesignTime  276 calls
     3854 ms  ResolvePackageAssets                     276 calls
     7038 ms  ResolvePackageFileConflicts              276 calls
    16436 ms  ResolveAssemblyReference                 276 calls
    30768 ms  ResolvePackageDependencies               276 calls
    139515 ms  MSBuild                                  736 calls

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

Time Elapsed 00:02:06.04

Analysis

Using higher parallelism (/m) doesn't really make it much faster as it seems that msbuild utilised more machine resources, but at the same time it also does much more work as caching inside msbuild is less effective.

Versions & Configurations

dotnet 6.0.300
VS 17.2.3

Regression?

I don't think so.

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

benvillalobos · 2022-07-14T16:18:58Z

Team Triage: Thanks for filing a great bug/repro! Hopefully we'll be able to dedicate some time to analyze this in the coming weeks!

yuehuang010 · 2022-07-19T19:46:41Z

Could you share the binlog?

marcin-krystianc · 2022-07-21T10:21:17Z

Could you share the binlog?

Sure, it is 40MB though, so it is split into two parts:

Part1 - msbuild_001.zip (Rename to msbuild.zip.001)
Part2 - msbuild_002.zip (Rename to msbuild.zip.002)

yuehuang010 · 2022-07-21T23:51:00Z

Is there a reason why maxcpucount is /m:1?
Could you explain the /target list? Can you reduce it to a single target? What is the actual target you want to run? If this not something you control, then checkout my recent PR dotnet/msbuild#7512 to address parallelism with Targets and Sln.

There is a strange 3s gap at the 63s mark.

yuehuang010 · 2022-07-22T00:11:42Z

Btw, what are your computer specs? On my 2990 threadripper, it took 25s for /m:1 and 15s for /m.

Could Windows Defender or other AntiMalware be interfering?

marcin-krystianc · 2022-07-22T09:44:30Z

Is there a reason why maxcpucount is /m:1?

Adding more MSBuild processes doesn't improve performance that much (maybe by 50% at max) and it definitely makes the analysis much harder.

Could you explain the /target list?

This list is what Rider uses for design-time builds (it is possible to collect binary logs with Rider by checking Help -> Diagnostic Tools -> Enable Design Time Logging). VisualStudio uses a different list of targets (see docs on how to get logs from VS), but to my understanding, these are targets defined internally in VS so it is not as easy to call them from the CLI.

Can you reduce it to a single target?

The point is to mimic the design-time build behavior as close as possible. We could focus on a single target for now but the goal is to make the entire design-time build performant.

If this not something you control, then checkout my recent PR dotnet/msbuild#7512 to address parallelism with Targets and Sln.

Actually, IDEs don't run the design time build for the entire sln at once - they make a new request for each individual project, so your PR will not help in this case.

Btw, what are your computer specs?

I'm using a mobile i7-8550u, but I've just tested it on the much faster AMD EPYC 7571 and still, it took ~2 min. Did you build the solution, before running the design-time build? When it is not built it is much faster, but that is not the use case we care about.

safesparrow · 2022-07-23T22:21:18Z

Did you build the solution, before running the design-time build? When it is not built it is much faster, but that is not the use case we care about.

What matters is running dotnet restore as that populates all the required dependencies.
Build is irrelevant, I think.

That's what makes things like Ionide.ProjInfo able to populate compiler options for F# code analysis using FSharp.Compiler.Service. Without a restore lots of things fail early and are thus much quicker.

I ran a slightly modified command - mainly different logging.

Full command (click to expand)

dotnet msbuild '/t:GetSuggestedWorkloads;_CheckForInvalidConfigurationAndPlatform;ResolveReferences;ResolveProjectReferences;ResolveAssemblyReferences;ResolveComReferences;ResolveNativeReferences;ResolveSdkReferences;ResolveFrameworkReferences;ResolvePackageDependenciesDesignTime;Compile;CoreCompile' /p:AndroidPreserveUserData=True /p:AndroidUseManagedDesignTimeResourceGenerator=True /p:BuildingByReSharper=True /p:BuildingProject=False /p:BuildProjectReferences=False /p:ContinueOnError=ErrorAndContinue /p:DesignTimeBuild=True /p:DesignTimeSilentResolution=False /p:JetBrainsDesignTimeBuild=True /p:ProvideCommandLineArgs=True /p:ResolveAssemblyReferencesSilent=False /p:SkipCompilerExecution=True /p:TargetFramework=net5.0 /v:q /m /bl /clp:Summary /clp:PerformanceSummary

Results:

Restore	/m	Time
Before restore	/m:1	18.36s
Before restore	/m	11.43s
After restore	/m:1	54.92s
After restore	/m	24.22s

CPU: Ryzen 5700g (8-core / 16-thread)

Btw, what are your computer specs? On my 2990 threadripper, it took 25s for /m:1 and 15s for /m.

Worth noting that it is well known (lots of experiments done) at our company that /m is rarely optimal for shorter builds like design-time build due to, I presume, increased IPC and lack of inter-process project cache.
That's why when using Rider we suggest to users to set it to the equivalent of /m:8 for solution loading, even though the CPUs we use are 16 core/32 thread Xeons.
This obviously depends on the size of the solution and project structure.

The below results demonstrate that:

Restore	/m	Time
After restore	/m:1	54.92s
After restore	/m:5	26.05s
After restore	/m:7	24.39s
After restore	/m:10	23.07s
After restore	/m:12	23.98s
After restore	/m (/m:16)	24.22s

If this not something you control, then checkout my recent PR dotnet/msbuild#7512 to address parallelism with Targets and Sln.

Actually, IDEs don't run the design time build for the entire sln at once - they make a new request for each individual project, so your PR will not help in this case.

To clarify: IDEs (at least Rider) already parallelise this completely by sending multiple requests to MSBuild in parallel, one per project.

Rider defaults to /m:1

Will describe this Rider example just as another confirmation that this is a widespread issue:

Rider has a semi-recent setting that allows one to increase the number of MSBuild processes for solution loading.
As seen below, it defaults to 1.
That is because the Rider team observed that higher numbers don't necessarily yield better results, so they kept it at a conservative number that at least doesn't waste machine resources.

You can also see that the full build does automatically use lots of processes (14/16 in this case).
While full build can also suffer from the same IPC/cache issues, the impact is much smaller relative to the amount of actual work required by the build target.

safesparrow · 2022-07-23T23:50:25Z

I did some profiling and realized that GC plays quite a role in slowing the main MSBuild process down.

I then ran the following test with and without server GC:

Function Go{ %LocalAppData%\JetBrains\Toolbox\apps\Rider\ch-0\222.3345.88\bin\rider64.exe D:\projekty\TestSolutions\LargeAppWithPrivatePackagesCentralised\solution\LargeAppWithPrivatePackagesCentralised.sln }

# Test 1
$env:DOTNET_gcServer=1;$env:COMPlus_gcServer=1;Go

# Test 2
$env:DOTNET_gcServer=0;$env:COMPlus_gcServer=0;Go

I used 7 MSBuild parallel processes as show in the above comment.

This yielded the following results/logs in Rider's backend (logs that Rider outputs about MSBuild design-time build requests upon solution load):

gcServer=0 (using workstation GC):

00:43:50.463 |I| ProjectModel                   | RequestBuilder thread:9        | Reloading has finished, statistic: 
	Total: 46.84 sec
	Binding: 21.49 sec
	Evaluation: 20.00 sec
00:43:50.466 |I| Build                          | .NET ThreadPool Worker:52      | Build succeeded.

gcServer=1 (using server GC):

00:44:45.377 |I| ProjectModel                   | RequestBuilder thread:9        | Reloading has finished, statistic: 
	Total: 31.81 sec
	Binding: 9.50 sec
	Evaluation: 11.53 sec
00:44:45.380 |I| Build                          | .NET ThreadPool Worker:58      | Build succeeded.

So forcing server GC for MSBuild (all) node processes yielded 32% reduction in design-time build 🎉

Below I'm attaching screenshots from DotTrace profiling the main MSBuild node.
This is from a different test than the above ones, and I didn't perfectly align the start/stop, but the GC impact can be clearly observed (43% GC time -> 12% GC time).

Workstation GC

Server GC

For reference, here is a ticket I raised with JetBrains to consider enabling Server GC for design-time MSBuild: https://youtrack.jetbrains.com/issue/RIDER-80141/Consider-forcing-server-GC-for-MSBuild-processes-or-at-least-provide-a-button-to-opt-in

Do we know if Visual Studio already has that option enabled?

I'm aware that if too many processes are spawned, all using Server GC, they might start throttling each other too much and causing too much context switching.
However the tests I've done show a huge improvement on very big solutions, so clearly there is lots of headroom.

yuehuang010 · 2022-07-24T00:20:30Z

I tried various /m and between /m:4 to /m:8 yielded the best results. 25s to 11s
FYI. I added /nr:false to your command line to close finished nodes afterwards to free up the resources. With the flag, it should yield a more consistent result for testing purposes.

I presume, increased IPC and lack of inter-process project cache.

I have noticed this too. dotnet/msbuild#7625

I haven't noticed an improvement with gcServer. Perhaps there are other factors involved or it is machine dependent.

rokonec · 2022-09-02T14:23:08Z

I took perfview traces and binlogs of this repro (sln open in VS).
By looking at the traces and binary logs I have not identified any MSBuild core functionality inefficiency.

But when looking at project system what strikes me was ResolvePackageDependencies task cumulative duration. When looking deeper at it, I noticed that almost 2/3 of of its time is taken by loading and parsing nuget lock files project.assets.json:

This sln has project.assets.json size of almost 1MB. Although it is cached, we still have to, during DTB, parse it at least once per each project ie ~270 times.

My knowledge of SDK targets, nuget lock files and DTB is very limited, at best, so I can't tell if this is expected, inefficient or bug. To me it is just a little bit suspicious.
@dsplaisted what do you reckon?

dsplaisted · 2022-09-02T14:38:34Z

I thought that ResolvePackageDependencies was deprecated and shouldn't be called by default anymore. I think the project system in Visual Studio was updated so that it parses the assets file directly.

@tmeschter @drewnoakes Can you clarify whether the ResolvePackageDependencies task should still be called in a VS design -time build?

drewnoakes · 2022-09-07T04:50:30Z

The change @dsplaisted is referring to was to stop returning the full list of all transitively-reachable package references and their contents to the project system, in order to display them in the dependencies tree. After the change, only the top level dependencies were returned, and transitive dependencies were populated lazily as the user expands the tree (or during search in Solution Explorer).

I'm not intimate with the details, but I would expect ResolvePackageDependencies to still be called as part of reference resolution. The DTB needs to resolve referenced assemblies (including those coming from packages) in order to pass that information to Roslyn's language service.

drewnoakes · 2022-09-07T04:56:51Z

Skimming through a DTB binlog, it seems that the output of ResolvePackageDependencies ends up feeding through ResolveAssemblyReferences.

dsplaisted · 2022-09-07T14:54:08Z

Looking at this more, it looks like ResolvePackageDependencies does normally run, but it does less work unless EmitLegacyAssetsFileItems is true.

However, it still has to read the assets file. It uses an in-memory cache for this so it won't read the same assets file multiple times in the same build, but it looks like this may still be a perf hit in this scenario with a lot of projects in the solution.

Most of the logic for reading the assets file is now in ResolvePackageAssets, which maintains its own optimized cache of the results and won't read the assets file at all unless the cache is out of date. So we may want to consider reading the PackageDefinitions and PackageDependencies items in ResolvePackageAssets, so that ResolvePackageDependencies doesn't need to be called at all unless EmitLegacyAssetsFileItems is true. That should improve incremental build perf and might also significantly improve the design time build perf for this large solution scenario.

@dotnet/msbuild @marcpopMSFT

marcpopMSFT · 2022-09-14T21:33:39Z

@rokonec did you want to look into making the SDK side change to have ResolvePackageAssets output the values that RPD currently gets or did you want the SDK to take a look?

ocallesp · 2022-09-27T19:59:31Z

The pr added two new properties to the NuGet assets cache file, so it will invalidate the old one.

Please clean the solution and run NuGet restore.

dsplaisted · 2022-12-01T00:31:50Z

This should be fixed in 7.0.200 via #28405.

Thanks a bunch @marcin-krystianc for the detailed information which enabled us to investigate and address this!

Improves dotnet/sdk#27738 It is another attempt to introduce changes proposed in #8098, which was reverted due to a bug.

marcin-krystianc added needs-triage performance labels Jul 13, 2022

AR-May removed the needs-triage label Jul 20, 2022

rainersigwald assigned rokonec Aug 2, 2022

ghost added Area-NetSDK untriaged Request triage from a team member labels Sep 7, 2022

dsplaisted added needs team triage Requires a full team discussion and removed untriaged Request triage from a team member Area-NetSDK labels Sep 7, 2022

dsplaisted transferred this issue from dotnet/msbuild Sep 7, 2022

marcpopMSFT added this to the 7.0.2xx milestone Sep 14, 2022

marcpopMSFT removed the needs team triage Requires a full team discussion label Sep 14, 2022

ocallesp self-assigned this Sep 19, 2022

ocallesp mentioned this issue Sep 20, 2022

Read PackageDefinitions and PackageDependencies from the cache assets file instead of ResolvePackageDependencies #28057

Merged

ocallesp closed this as completed in #28057 Sep 26, 2022

ocallesp mentioned this issue Sep 29, 2022

Read PackageDefinitions and PackageDependencies from the cache assets file instead of ResolvePackageDependencies #28263

Closed

ocallesp reopened this Sep 29, 2022

This was referenced Oct 24, 2022

Add PackageDependenciesDesignTime to cache assets file #28405

Merged

Batch metadata updates for better performance dotnet/msbuild#8098

Merged

dsplaisted closed this as completed Dec 1, 2022

marcin-krystianc mentioned this issue Dec 14, 2022

Batch metadata updates for better performance (attempt 2) dotnet/msbuild#8240

Merged

rainersigwald pushed a commit to dotnet/msbuild that referenced this issue Mar 28, 2023

Batch metadata updates for better performance (attempt 2) (#8240)

ea90db2

Improves dotnet/sdk#27738 It is another attempt to introduce changes proposed in #8098, which was reverted due to a bug.

Slow design-time builds for large solution #27738

Slow design-time builds for large solution #27738

Comments

marcin-krystianc commented Jul 13, 2022

Issue Description

Steps to Reproduce

Data

Analysis

Versions & Configurations

Regression?

benvillalobos commented Jul 14, 2022

Uh oh!

yuehuang010 commented Jul 19, 2022

Uh oh!

marcin-krystianc commented Jul 21, 2022

Uh oh!

yuehuang010 commented Jul 21, 2022

Uh oh!

yuehuang010 commented Jul 22, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

marcin-krystianc commented Jul 22, 2022

Uh oh!

safesparrow commented Jul 23, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Rider defaults to /m:1

Uh oh!

safesparrow commented Jul 23, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

yuehuang010 commented Jul 24, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

rokonec commented Sep 2, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

dsplaisted commented Sep 2, 2022

Uh oh!

drewnoakes commented Sep 7, 2022

Uh oh!

drewnoakes commented Sep 7, 2022

Uh oh!

dsplaisted commented Sep 7, 2022

Uh oh!

marcpopMSFT commented Sep 14, 2022

Uh oh!

ocallesp commented Sep 27, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

dsplaisted commented Dec 1, 2022

Uh oh!

yuehuang010 commented Jul 22, 2022 •

edited

Loading

safesparrow commented Jul 23, 2022 •

edited

Loading

safesparrow commented Jul 23, 2022 •

edited

Loading

yuehuang010 commented Jul 24, 2022 •

edited

Loading

rokonec commented Sep 2, 2022 •

edited

Loading

ocallesp commented Sep 27, 2022 •

edited

Loading