MSBuild evaluation for Netcore is 3x slower than Netframework causing slow solution load times

[arkalyanms]

Issue Description

In an effort to improve solution load for netcore projects, I have analyzed MSBuild evaluation times between netcore and netframework evaluation times and find that netcore is around 3x slower in evaluations than netframework. Some of the issues listed below smell like bugs and other need more profiling to understand the problem better. Cutting this Issue to track after meeting with Rainer and team and Ladi, Alina and Roman.

Steps to Reproduce

Measuring conditions

• The netcore and netframework projects are identical in terms of files, folders, number of projects, project types, solution folders with the only difference being one targets Netframework and the other targets Netcore.
• All traces include the Microsoft-Build events
• The measurements are for a warm load with a VS start to ensure the startup thread info gets collected for the trace.
• • After VS was installed and a few solution opens were done,
• • PerfView collect is started
• • Open VS and continue without code
• • Click File and select the measuring project from Recent and open the solution
• • Stop the PerfView collect

Data

• Full solutions and traces at \\SLNATSCALE002\CoreVsFramework shared with Ladi and Alina.
• The traces contain 20, 400 and 1000 projects for both core and framework. Again both identical except the target framework.
• The solutions will contain sln files with projects counts as a multiplier of the base project size of 20 with steps going all the way to 100. Example: MultiCore20__0050.sln is 20*50=solution containing 1000 projects.
• The 400 project solutions (MultiCore20_0020.sln and MultiFramework20_0020.sln) and traces are good to analyze without worrying about of OOM issues on the devbox, but showing issues amplified enough to narrow down problem.

Current State of Evaluation

	NETFRAMEWORK	NETFRAMEWORK	NETCORE	NETCORE
Solution size	OpenSolutionFile	ReEvaluateIfNecessary	OpenSolutionFile	ReEvaluateIfNecessary
20 projects	4776	472	7313	1274
400 projects	11383	6357	26551	15481
1000 projects	36414	15444	74555	38427

Evaluation phase split (400 projects)

	Core (in ms)	Metadata	Framework (in ms)	Metadata
Pass0	337		117
Pass1 (properties, imports)	18180	Properties = 735/project   Imports = 83/project	4535	Properties = 613/project   Imports = 56/project
Pass2 (item definitions)	36		9
Pass3 (project items properties)	7771	245/project	1796	50/project
Pass4 (NumberOfUsingTaskElements)	672	101/project	149	57/project
Pass5 (read targets)	1069	475-481/project (Cost on each project	295	332-335 / project (First project takes the bulk cost)
EvaluateCondition	109	1964	56	1397
ExpandGlob	989	4/project	14	1/project
Parse	24		23
LoadDocument	705	1298 = 3 per project + 138 common props and targets	179	1 per project + 138 common props and targets
True Evaluation Cost	28065		6901

Breakdown of issues

• Additional profiling per pass for netcore projects | #6070
• SdkResolution.SdkResolverService should be globalized for netcore evaluation | #6060
• Switch System.IO usage with Microsoft.IO usage to reduce string allocations | #6075
• Optimize string building and interning | #5663
• Glob pattern matching improvements for netcore/CPS | #6069
• Avoid disk scans for projects by relying on DirectoryTree from CPS | #6068
• LogProjectEvaluationStarted is expensive for netcore and increases with projects | #6065
• LoggingContext.LogBuildEvent is slow but has a static cost | #6066
• Microsoft.Build.Internal.EngineFileUtilities.GetFileListEscaped is 3x slower for netcore projects | #6061
• DecorateItemsWithMetadata is 3x slower for netcore projects | #6062
• ExpandPropertiesLeaveEscaped using ReuseableStringBuilder 50% slower than OpportunisticIntern | #6063
• ProcessMetadataElements 5x slower for netcore projects | #6064
• Expand the MSBuild optprof scenarios to have more representative dotnet/project-system + CPS scenarios | #6067
• Address issues with ETW traces in Evaluator | #6039
• Reduce GC pressure in InterningBinaryReader.ReadString | #3210
• TargetResult.TranslateItems is not pooling read buffers | #6291
• potential lock contention in ProjectRootElementCache.Get | #3039
• reuse CPS directory tree to resolve file globbings (instead of accessing the file system) | #5467

Full analysis at MSBuild-performance-improvements and MSBuild Performance.docx.

Versions & Configurations

VS version = 16.9.0 Preview 4.0 [30912.315.main]
MSBuild version = 16.9.0.6202

Attach a binlog

Traces and solutions are at \SLNATSCALE002\CoreVsFramework. Numbers are consistent across different runs.

@ladipro and @rainersigwald FYI.

[AR-May]

Team Triage: first step: need to identify how this issue aligns with the existing user story.

[arkalyanms]

@ladipro: Added #3210 to this parent. It looks like it was already solved by you as a part of #5663 and #6063?

[ladipro]

@arkalyanms, you're right, I've closed #3210, thank you!

[arkalyanms]

On a more recent pass with the latest evaluation fixes, there were 2 other issues that started showing - #3039 and #5467.

@AndyGerlicher #3039 seems to manifest when using the PRE cache. Do you know if using MSBUILDUSESIMPLEPROJECTROOTELEMENTCACHECONCURRENCY viable given the lock bug?

[ladipro]

All child issues are closed. Thank you @arkalyanms for driving this effort!

I have opened #6977 to track further improvements now enabled by referencing Microsoft.IO.Redist. It will be tackled as part of a different epic.

[arkalyanms]

Thank you for working on these fixes @ladipro and @AR-May!

In one of our more recent meetings, we spoke about moving the sdk resolver cache out of the evaluation context so it is shared irrespective of a caller's use of the shared evaluation context. Should we open a backlog issue for that?

[ladipro]

@arkalyanms good point, I have opened #6987. Rainer already has a draft PR out addressing the repeated SDK resolver enumerations.