[Performance]: GetTargetPathWithTargetPlatformMoniker and GetTargetPath target post-processing can take multiple minutes on large projects.

[veleek]

Issue Description

On large highly interdependent projects the GetTargetPathWithTargetPlatformMoniker and GetTargetPath targets (from Microsoft.Common.CurrentVersion.targets) can end up taking multiple minutes to run. GetTargetPathWithTargetPlatformMonike doesn't do anything expensive, it just creates a new project Item with some metadata, but it has a Returns attrribute that returns @(TargetPathWithTargetPlatformMoniker) which due to post processing in MSBuild to handle the returns, can take a long time to execute. Since the GetTargetPath target is essentially a passthrough for this value, it takes almost the exact same amount of time. For our large project we have seen each of these targets take upwards of 3.5 minutes to run.

The behavior can be seen to a lesser effect on other projects in the solution where each target takes ~20 second or ~1 minute to run.

Overall build time:

Time spent on the two targets (note: these targets are serial, not parallel, so it is almost minutes in total)

Steps to Reproduce

I'm happy to privately share a binlog of the build, but the descript here should be enough to identify the source of the problem.

Data

Call stack during 3minute hangs:

System.Collections.Immutable.dll!System.Collections.Immutable.SortedInt32KeyNode`1.Freeze+0x1a
System.Collections.Immutable.dll!System.Collections.Immutable.SortedInt32KeyNode`1.Freeze+0xbb
System.Collections.Immutable.dll!System.Collections.Immutable.SortedInt32KeyNode`1.Freeze+0xc9
System.Collections.Immutable.dll!System.Collections.Immutable.SortedInt32KeyNode`1.Freeze+0xc9
System.Collections.Immutable.dll!System.Collections.Immutable.ImmutableDictionary`2..ctor+0x7f
System.Collections.Immutable.dll!System.Collections.Immutable.ImmutableDictionary`2.Wrap+0x5d
System.Collections.Immutable.dll!System.Collections.Immutable.ImmutableDictionary`2.SetItem+0xb3
Microsoft.Build.dll!Microsoft.Build.Collections.CopyOnWritePropertyDictionary`1.Set+0x58
Microsoft.Build.dll!TaskItem.get_MetadataCollection+0x242
Microsoft.Build.dll!TaskItem.Equals+0x263
mscorlib.dll!System.Collections.Generic.GenericEqualityComparer`1.Equals+0x56
System.Core.dll!System.Collections.Generic.HashSet`1.Contains+0xda
Microsoft.Build.dll!<ExecuteTarget>d__44.MoveNext+0xd3f
mscorlib.dll!System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start+0x80
Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetEntry.ExecuteTarget+0x79
Microsoft.Build.dll!<ProcessTargetStack>d__23.MoveNext+0x911
mscorlib.dll!System.Threading.ExecutionContext.RunInternal+0x172
mscorlib.dll!System.Threading.ExecutionContext.Run+0x15
mscorlib.dll!MoveNextRunner.Run+0x6f
mscorlib.dll!<>c.<Run>b__2_0+0x36
mscorlib.dll!System.Threading.Tasks.Task.Execute+0x47
mscorlib.dll!System.Threading.Tasks.Task.ExecuteWithThreadLocal+0x18c
mscorlib.dll!System.Threading.Tasks.Task.ExecuteEntry+0xa1
Microsoft.Build.dll!DedicatedThreadsTaskScheduler.<InjectThread>b__6_0+0x78
mscorlib.dll!System.Threading.ExecutionContext.RunInternal+0x172
mscorlib.dll!System.Threading.ExecutionContext.Run+0x15
mscorlib.dll!System.Threading.ExecutionContext.Run+0x55
mscorlib.dll!System.Threading.ThreadHelper.ThreadStart+0x55
[Unmanaged to Managed Transition]
clr.dll!DllCanUnloadNowInternal+0x10f3
clr.dll!DllCanUnloadNowInternal+0x1000
clr.dll!DllCanUnloadNowInternal+0x18b0
clr.dll!MetaDataGetDispenser+0xcdaf
clr.dll!DllCanUnloadNowInternal+0x2498
clr.dll!DllCanUnloadNowInternal+0x2403
clr.dll!DllCanUnloadNowInternal+0x2342
clr.dll!DllCanUnloadNowInternal+0x2533
clr.dll!MetaDataGetDispenser+0xcc99
clr.dll!DllCanUnloadNowInternal+0x6015
KERNEL32.dll!BaseThreadInitThunk+0x14
ntdll.dll!RtlUserThreadStart+0x21

Analysis

Example project structure:

• Service.Stuff.csproj
  • Service.Core.csproj
    • Service.Interfaces.csproj
      • Common.csproj
  • Service.Interfaces.csproj
    • Common.csproj
  • Common.csproj

GetTargetPath gets called on each of these, and because of the metadata introduced at different levels, it produces 7 different TargetPathWithTargetPlatformMoniker items. For Common.csproj, these items all have the same ItemSpec (essentially just "Common.csproj") but they differ in their metadata.

This example has 7 items. In our solution with 385 projects we have a PostBuild project that references every other project. When this runs, the @(TargetPathWithTargetPlatformMoniker) collection has ~50K items.

As part of the post-processing for the target, since they have a Returns attribute, there is some work done to dedupe this collection. It uses a HashSet<TaskItem> to do the deduping. However, the hashcode for the TaskItem only takes into account the ItemSpec so there ends up being a lot of hash collisions and it falls back to doing an expensive comparison which generates and compares the entire metadata collection of the item.

Our PostBuild project is the most extreme example of this, but you can see that this problem appears even in projects that are significantly smaller, but this step still ends up taking an excessively long time (we have multiple projects that take >10s for each of these targets and it compounds over all the projects).

Versions & Configurations

We are using MSBuild 17.2.0, but i've analyzed the call paths and I don't see any changes between that version and the most recent build that would change this behavior.

Microsoft (R) Build Engine version 17.2.1+52cd2da31 for .NET Framework
Copyright (C) Microsoft Corporation. All rights reserved.

17.2.1.25201

Regression

• yes
• no

Regression Details

We have been using this common PostBuild project for years, but apparently the slowdowns have only really started as part of modernizing to newer versions of MSBuild and .NET.

[rainersigwald]

This is very surprising behavior. I'm pretty confused as to how materializing a one-item-long list with a few metadata could be a bottleneck like you're observing.

I'd like to see the binlog--to share it only with Microsoft folks, please open a feedback ticket instead and link it here so we can short-circuit the routing process.

I'm also interested to see a test on 17.7-preview3 when it's available; I suspect #8747 would alleviate this by chopping off the top several methods of the callstack. But I suspect there's a deeper problem somewhere.

[veleek]

@rainersigwald - The Returns="@(TargetPathWithTargetPlatformMoniker)" doesn't resolve in a one item list. The target executor takes the string @(TargetPathWithTargetPlatformMoniker) and expands it at runtime. So each time the target gets run an additiontal item gets added to the collection.

Opening a feedback ticket shortly. I'm setup to build MSBuild and I can try to do a drop-in replacement of a small set of the binaries if possible.

[veleek]

I also tried disabling the de-dupe on the target to see if it would speed it up, but the list ended up with more than 200k items in it before it even made it to my project with all the references.

  <Target
      Name="GetTargetPathWithTargetPlatformMoniker"
      BeforeTargets="GetTargetPath"
      DependsOnTargets="$(GetTargetPathWithTargetPlatformMonikerDependsOn)"
      Returns="@(TargetPathWithTargetPlatformMoniker)"
      KeepDuplicateOutputs="True">
    <ItemGroup>
      <TargetPathWithTargetPlatformMoniker Include="$(TargetPath)">
        <TargetPlatformMoniker>$(TargetPlatformMoniker)</TargetPlatformMoniker>
        <TargetPlatformIdentifier>$(TargetPlatformIdentifier)</TargetPlatformIdentifier>
        <TargetFrameworkIdentifier>$(TargetFrameworkIdentifier)</TargetFrameworkIdentifier>
        <TargetFrameworkVersion>$(TargetFrameworkVersion.TrimStart('vV'))</TargetFrameworkVersion>
        <ReferenceAssembly Condition="'$(ProduceReferenceAssembly)' == 'true'">$(TargetRefPath)</ReferenceAssembly>
        <CopyUpToDateMarker>@(CopyUpToDateMarker)</CopyUpToDateMarker>
      </TargetPathWithTargetPlatformMoniker>
    </ItemGroup>
  </Target>

[veleek]

Feedback item created and binlog attached: https://developercommunity.visualstudio.com/t/Performance:-GetTargetPathWithTargetPl/10405139

[rainersigwald]

the list ended up with more than 200k items in it before it even made it to my project with all the references.

What list exactly?

There should only be one item per project returned by GetTargetPathWithTargetPlatformMoniker/GetTargetPath, the one that is $(TargetPath) plus 6 metadata.

Hmm, actually could you share a memory dump in the feedback issue, maybe?

[rainersigwald]

Ah, I'm seeing something interesting in the log now. Looking . . .

[rainersigwald]

Ah, found it.

This looks like a bug to me:

msbuild/src/Tasks/Microsoft.Common.CurrentVersion.targets

Lines 2701 to 2709 in 39e20dc

	<Target Name="GetReferenceTargetPlatformMonikers" DependsOnTargets="PrepareProjectReferences">
	<MSBuild
	Projects="@(_MSBuildProjectReferenceExistent)"
	Properties="%(_MSBuildProjectReferenceExistent.SetConfiguration); %(_MSBuildProjectReferenceExistent.SetPlatform); %(_MSBuildProjectReferenceExistent.SetTargetFramework)"
	Targets="GetTargetPathWithTargetPlatformMoniker"
	BuildInParallel="$(BuildInParallel)"
	ContinueOnError="!$(BuildingProject)"
	RemoveProperties="%(_MSBuildProjectReferenceExistent.GlobalPropertiesToRemove)$(_GlobalPropertiesToRemoveFromProjectReferences)">
	<Output TaskParameter="TargetOutputs" ItemName="TargetPathWithTargetPlatformMoniker" />

Nothing else makes that item transitive.

This is triggered only when $(FindInvalidProjectReferences) is set to true, which it is in your shared\online\source\Online.targets. Can you avoid setting that and see if the perf improves?

[veleek]

Success! If that's false this project builds in 1:23 instead of 16+ minutes.

Okay, so you're saying GetReferenceTargetPlatformMonikers is outputing TargetPathWithTargetPlatformMoniker and as a result the @(TargetPathWithTargetPlatformMoniker) is growing when it's only supposed to be one item long. Correct? What's the long term fix for this? And what's the impact of not using FindInvalidProjectReferences)? We reference a copy of Microsoft.Common.CurrentVersion.targets in our build system (instead of a shared on in Program Files or something), so we could make temporary changes to that file if we need to.

Just in case you need it, by "the list" I'm referring to the one here which is what gets expanded from @(TargetPathWithTargetPlatformMoniker) -
https://github.com/dotnet/msbuild/blob/main/src/Build/BackEnd/Components/RequestBuilder/TargetEntry.cs#L635

[rainersigwald]

Okay, so you're saying GetReferenceTargetPlatformMonikers is outputing TargetPathWithTargetPlatformMoniker and as a result the @(TargetPathWithTargetPlatformMoniker) is growing when it's only supposed to be one item long. Correct?

Correct.

What's the long term fix for this?

That's a good question and will require more thought than I'm willing to put in at this time on Friday before a holiday weekend :)

You don't have that many items, and we shouldn't take so long.

• Is that fixed by the PR I linked? If not we should see if we can improve perf in that situation.

And what's the impact of not using FindInvalidProjectReferences)?

Have you ever seen it fail? I suspect it's not actually helpful but am not willing to commit either way at the moment.

• Audit FindInvalidProjectReferences -- does it do anything useful? Original change (internal link only): https://vstfdevdiv/DevDiv2/DevDiv/_versionControl/changeset/1033157, only message is Add designtime or buildtime warning when referencing Dev12/WinBlue projects from Dev11/Win8 C++ projects

• If it is still useful, should it really be adding to TargetPathWithTargetPlatformMoniker? Would it break the functionality if it was only one level deep?

[veleek]

That's a good question and will require more thought than I'm willing to put in at this time on Friday before a holiday weekend :)

I posted this and had a working resolution before the end of the workday. My expectations have already been exceeded! :D It'll take me some time to work through all of the other suggestions and I'll update when I get some more data. Thank you for the work so far!

[danmoseley]

However, the hashcode for the TaskItem only takes into account the ItemSpec

I wonder whether this could somehow be cheaply improved as well. Do these all have the same metadata count?

[veleek]

However, the hashcode for the TaskItem only takes into account the ItemSpec

I wonder whether this could somehow be cheaply improved as well. Do these all have the same metadata count?

They do not. It was different depending on which project it's referenced from and in our case there was a property called "NuGetPackageId" with the name of the referencing project, but I know there were more. In the brief look I took there were some items with a half dozen extra properties for the same ItemSpec.

However, for this specific case (the de-duping logic) we could just use a custom comparer to override the get hash code logic since the hash set is ONLY used for the deduping (and immediately discarded) so there's no chance of bugs caused by the item metadata changing. That could be a perf improvement worth doing even if we fix the reference leaking problem.

[veleek]

• Is that fixed by the PR I linked? If not we should see if we can improve perf in that situation.

Okay, it was a little bit clunky but I was able to get it building with a build from the dev tree successfully. I deleted the output folder and built with FindInvalidProjectReferences=true using new binaries and it still takes about 15 minutes to complete. Using FindInvalidProjectReferences=false the build completes in under two minutes.

And what's the impact of not using FindInvalidProjectReferences)?

Have you ever seen it fail? I suspect it's not actually helpful but am not willing to commit either way at the moment.

• Audit FindInvalidProjectReferences -- does it do anything useful? Original change (internal link only): https://vstfdevdiv/DevDiv2/DevDiv/_versionControl/changeset/1033157, only message is Add designtime or buildtime warning when referencing Dev12/WinBlue projects from Dev11/Win8 C++ projects

FindInvalidProjectReferences never fails, but it does output a few warnings. They're mostly a result of some older projects (maybe Windows executables or something targetting Win 7) we have, referencing some newer projects that are building against .NET 6 (I think). They're valid warnings, and they should be fixed eventually, but in our case I think we're probably fine to disable this day to day. We can manually enable it for CI runs just to verify that we're still seeing the warnings if we need to.

• If it is still useful, should it really be adding to TargetPathWithTargetPlatformMoniker? Would it break the functionality if it was only one level deep?

Yeah, this is definitely worth investigating more deeply. I dunno if there's anything that depends on those objects being output. Presumably not because you'd only see it when FindInvalidProjectReferences is enabled.

[veleek]

Tried out using a hashcode that includes all object metadata instead of just ItemSpec: (warning: VERY janky code ahead) https://github.com/veleek/msbuild/pull/1/files?w=1.

This is definitely faster, but took about 4 minutes. With the check disabled it takes about 1.5 minutes. I fiddled around with a few other things like caching the hashcodes so they were only ever generated once and that didn't seem to move the needle, so it's literally just the sheer quantity of items (46k) that increases the build time.

With the check disabled, all these GetTargetPathWithTargetPlatformMoniker targets still run, but they're 0ms.

[danmoseley]

I looked at adding metadata into the hashcode but it's likely to be much more expensive in the general case as it has to resolve several dictionaries. I put up a PR with just a small change that still uses only itemspec.
Possibly it could include something of the metadata in some special cases like when there's literally none. I haven't had a chance to look at your change.

[veleek]

Yeah, I'm not sure it makes sense to include the metadata in the general case, most because it's not immutable (I think?).

In this de-duping scenario the HashSet isn't persistent so mutability doesn't matter. just using a custom comparator to override GetHashCode means that the object metadata is traversed at most once for each item in the list (assuming no hash collisions which should be rare) so it'd be good enough and avoid calls to Equals which forces the metadata enumeration for both objects.