Poor project evaluation performance for project at least under src/libraries

[ViktorHofer]

This is from a fully no-op build of a reference source project that doesn't have any dependencies:

C:\git\runtime4>.\.dotnet\dotnet.exe msbuild /t:Build /v:minimal /clp:performancesummary C:\git\runtime4\src\libraries\System.Runtime\ref\System.Runtime.csproj

  System.Runtime -> C:\git\runtime4\artifacts\bin\System.Runtime\ref\Debug\net9.0\System.Runtime.dll

Project Evaluation Performance Summary:
      557 ms  C:\git\runtime4\src\libraries\System.Runtime\ref\System.Runtime.csproj   1 calls

We should ETW trace this by following the guidance here: https://github.com/dotnet/msbuild/blob/main/documentation/specs/event-source.md

This impacts everything:

• Tooling performance (VS, VSCode, everything that uses the project system and msbuild underneath)
• CLI performance: Restore, Build, Pack, ...

cc @dotnet/area-infrastructure-libraries

[dotnet-policy-service]

Tagging subscribers to this area: @dotnet/area-infrastructure-libraries
See info in area-owners.md if you want to be subscribed.

[ViktorHofer]

Non-surprisingly, ETW traces show that MSBuild spends the most time during evaluation in phase 1 (Evaluate imports and properties) and 3 (Evaluate items):

Event Name                        	    TimeStamp (Trace Local)	Time MSec                  	Process Name	Rest                
Microsoft-Build/EvaluatePass1/Stop	      7/19/2024 12:27:01 PM	736.650                    	Process(2568) (2568)	ThreadID="19,988" ProcessorNumber="2" DURATION_MSEC="220.259" projectFile="C:\git\runtime4\src\libraries\System.Runtime\ref\System.Runtime.csproj"

Event Name                        	    TimeStamp (Trace Local)	Time MSec                  	Process Name	Rest                
Microsoft-Build/EvaluatePass3/Stop	      7/19/2024 12:27:01 PM	819.127                    	Process(2568) (2568)	ThreadID="19,988" ProcessorNumber="6" DURATION_MSEC="81.219" projectFile="C:\git\runtime4\src\libraries\System.Runtime\ref\System.Runtime.csproj" 

[ViktorHofer]

As we already knew, resolving the Microsoft.DotNet.Arcade.Sdk and then evaluating it is a big part.

Event Name                                             	    TimeStamp (Trace Local)	Time MSec                  	Process Name	Rest                
Microsoft-Build/CachedSdkResolverServiceResolveSdk/Stop	      7/19/2024 12:27:01 PM	518.254                    	Process(2568) (2568)	ThreadID="19,988" ProcessorNumber="4" DURATION_MSEC="0.562" sdkName="Microsoft.NET.Sdk" solutionPath="" projectPath="C:\git\runtime4\src\libraries\System.Runtime\ref\System.Runtime.csproj" success="True" wasResultCached="False" 
Microsoft-Build/CachedSdkResolverServiceResolveSdk/Stop	      7/19/2024 12:27:01 PM	624.613                    	Process(2568) (2568)	ThreadID="19,988" ProcessorNumber="0" DURATION_MSEC="93.476" sdkName="Microsoft.DotNet.Arcade.Sdk" solutionPath="" projectPath="C:\git\runtime4\src\libraries\System.Runtime\ref\System.Runtime.csproj" success="True" wasResultCached="False" 
Microsoft-Build/CachedSdkResolverServiceResolveSdk/Stop	      7/19/2024 12:27:01 PM	657.686                    	Process(2568) (2568)	ThreadID="19,988" ProcessorNumber="0" DURATION_MSEC="0.019" sdkName="Microsoft.NET.Sdk" solutionPath="" projectPath="C:\git\runtime4\src\libraries\System.Runtime\ref\System.Runtime.csproj" success="True" wasResultCached="True" 
Microsoft-Build/CachedSdkResolverServiceResolveSdk/Stop	      7/19/2024 12:27:01 PM	706.200                    	Process(2568) (2568)	ThreadID="19,988" ProcessorNumber="2" DURATION_MSEC="0.009" sdkName="Microsoft.DotNet.Arcade.Sdk" solutionPath="" projectPath="C:\git\runtime4\src\libraries\System.Runtime\ref\System.Runtime.csproj" success="True" wasResultCached="True" 

[ViktorHofer]

Every project imports Subsets.props which is quite huge, uses globbing and lazy item expansion. Removing its import results in an 8% improvement from in average 305ms to 280ms.