5% of a build is due ResolveAssemblyReferences's cache checking

[davkean]

See: dotnet/sdk#1496.

This is probably going to be all RAR, how do we make this play nicely with incremental?

[davkean]

Here's where most of the time is spent:

Why are we computing closure?

[davkean]

I assumed computing the closure only occurred when FindDependencies is on, turns out we always compute the closure. The shear number of assemblies coming in, is killing us here.

[davkean]

I can see that 5% of our build is just doing a QueryAttributes in GetFileState:

Is this a broken cache?

[davkean]

Okay, I can see very quickly that we're doing a GetLastWriteFileUtcTime on a given file, 10s and 10s of times. Why, I don't know yet.

[davkean]

First stack:

>	Microsoft.Build.dll!Microsoft.Build.Shared.NativeMethodsShared.GetLastWriteFileUtcTime(string fullPath) Line 867	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetUpToDateChecker.IsAnyOutOfDate<string>(out Microsoft.Build.BackEnd.DependencyAnalysisLogDetail dependencyAnalysisDetailEntry, string projectDirectory, System.Collections.Generic.IList<string> inputs, System.Collections.Generic.IList<string> outputs) Line 1011	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetUpToDateChecker.PerformDependencyAnalysisIfDiscreteOutputs(System.Collections.Generic.Dictionary<string, System.Collections.Generic.Dictionary<string, System.Collections.Generic.IList<Microsoft.Build.Execution.ProjectItemInstance>>> itemVectorsInTargetInputs, System.Collections.Generic.Dictionary<string, System.Collections.Generic.Dictionary<string, System.Collections.Generic.IList<Microsoft.Build.Execution.ProjectItemInstance>>> itemVectorTransformsInTargetInputs, System.Collections.Generic.Dictionary<string, string> discreteItemsInTargetInputs, System.Collections.Generic.List<string> targetOutputItemSpecs) Line 792	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetUpToDateChecker.PerformDependencyAnalysis(Microsoft.Build.BackEnd.ItemBucket bucket, out Microsoft.Build.Collections.ItemDictionary<Microsoft.Build.Execution.ProjectItemInstance> changedTargetInputs, out Microsoft.Build.Collections.ItemDictionary<Microsoft.Build.Execution.ProjectItemInstance> upToDateTargetInputs) Line 242	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetEntry.ExecuteTarget(Microsoft.Build.BackEnd.ITaskBuilder taskBuilder, Microsoft.Build.BackEnd.BuildRequestEntry requestEntry, Microsoft.Build.BackEnd.Logging.ProjectLoggingContext projectLoggingContext, System.Threading.CancellationToken cancellationToken) Line 448	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetBuilder.ProcessTargetStack(Microsoft.Build.BackEnd.ITaskBuilder taskBuilder) Line 465	C#	Symbols loaded.

[davkean]

Second stack:

>	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Shared.NativeMethodsShared.GetLastWriteFileUtcTime(string fullPath) Line 867	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.SystemState.GetFileState(string path) Line 376	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.SystemState.GetRuntimeVersion(string path) Line 453	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.AssemblyInformation.IsWinMDFile(string fullPath, Microsoft.Build.Tasks.GetAssemblyRuntimeVersion getAssemblyRuntimeVersion, Microsoft.Build.Shared.FileExists fileExists, out string imageRuntimeVersion, out bool isManagedWinmd) Line 251	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.Reference.FullPath.set(string value) Line 661	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.ReferenceTable.NameAssemblyFileReference(Microsoft.Build.Tasks.Reference reference, string assemblyFileName) Line 418	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.ReferenceTable.SetPrimaryFileItem(Microsoft.Build.Framework.ITaskItem referenceAssemblyFile) Line 846	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.ReferenceTable.SetPrimaryItems(Microsoft.Build.Framework.ITaskItem[] referenceAssemblyFiles, Microsoft.Build.Framework.ITaskItem[] referenceAssemblyNames, System.Collections.ArrayList exceptions) Line 490	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.ReferenceTable.ComputeClosure(Microsoft.Build.Tasks.DependentAssembly[] remappedAssembliesValue, Microsoft.Build.Framework.ITaskItem[] referenceAssemblyFiles, Microsoft.Build.Framework.ITaskItem[] referenceAssemblyNames, System.Collections.ArrayList exceptions) Line 1634	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.ResolveAssemblyReference.Execute(Microsoft.Build.Shared.FileExists fileExists, Microsoft.Build.Shared.DirectoryExists directoryExists, Microsoft.Build.Tasks.GetDirectories getDirectories, Microsoft.Build.Tasks.GetAssemblyName getAssemblyName, Microsoft.Build.Tasks.GetAssemblyMetadata getAssemblyMetadata, Microsoft.Build.Shared.GetRegistrySubKeyNames getRegistrySubKeyNames, Microsoft.Build.Shared.GetRegistrySubKeyDefaultValue getRegistrySubKeyDefaultValue, Microsoft.Build.Tasks.GetLastWriteTime getLastWriteTime, Microsoft.Build.Tasks.GetAssemblyRuntimeVersion getRuntimeVersion, Microsoft.Build.Shared.OpenBaseKey openBaseKey, Microsoft.Build.Tasks.GetAssemblyPathInGac getAssemblyPathInGac, Microsoft.Build.Tasks.IsWinMDFile isWinMDFile, Microsoft.Build.Tasks.ReadMachineTypeFromPEHeader readMachineTypeFromPEHeader) Line 2194	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.ResolveAssemblyReference.Execute() Line 2912	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute() Line 631	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(Microsoft.Build.BackEnd.ITaskExecutionHost taskExecutionHost, Microsoft.Build.BackEnd.Logging.TaskLoggingContext taskLoggingContext, Microsoft.Build.BackEnd.TaskHost taskHost, Microsoft.Build.BackEnd.ItemBucket bucket, Microsoft.Build.BackEnd.TaskExecutionMode howToExecuteTask) Line 787	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.InitializeAndExecuteTask(Microsoft.Build.BackEnd.Logging.TaskLoggingContext taskLoggingContext, Microsoft.Build.BackEnd.ItemBucket bucket, System.Collections.Generic.IDictionary<string, string> taskIdentityParameters, Microsoft.Build.BackEnd.TaskHost taskHost, Microsoft.Build.BackEnd.TaskExecutionMode howToExecuteTask) Line 659	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.ExecuteBucket(Microsoft.Build.BackEnd.TaskHost taskHost, Microsoft.Build.BackEnd.ItemBucket bucket, Microsoft.Build.BackEnd.TaskExecutionMode howToExecuteTask, System.Collections.Generic.Dictionary<string, string> lookupHash) Line 434	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.ExecuteTask(Microsoft.Build.BackEnd.TaskExecutionMode mode, Microsoft.Build.BackEnd.Lookup lookup) Line 331	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.ExecuteTask(Microsoft.Build.BackEnd.Logging.TargetLoggingContext loggingContext, Microsoft.Build.BackEnd.BuildRequestEntry requestEntry, Microsoft.Build.BackEnd.ITargetBuilderCallback targetBuilderCallback, Microsoft.Build.Execution.ProjectTargetInstanceChild taskInstance, Microsoft.Build.BackEnd.TaskExecutionMode mode, Microsoft.Build.BackEnd.Lookup inferLookup, Microsoft.Build.BackEnd.Lookup executeLookup, System.Threading.CancellationToken cancellationToken) Line 180	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetEntry.ProcessBucket(Microsoft.Build.BackEnd.ITaskBuilder taskBuilder, Microsoft.Build.BackEnd.Logging.TargetLoggingContext targetLoggingContext, Microsoft.Build.BackEnd.TaskExecutionMode mode, Microsoft.Build.BackEnd.Lookup lookupForInference, Microsoft.Build.BackEnd.Lookup lookupForExecution) Line 818	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetEntry.ExecuteTarget(Microsoft.Build.BackEnd.ITaskBuilder taskBuilder, Microsoft.Build.BackEnd.BuildRequestEntry requestEntry, Microsoft.Build.BackEnd.Logging.ProjectLoggingContext projectLoggingContext, System.Threading.CancellationToken cancellationToken) Line 483	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetBuilder.ProcessTargetStack(Microsoft.Build.BackEnd.ITaskBuilder taskBuilder) Line 465	C#	Symbols loaded.

third stack:

>	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Shared.NativeMethodsShared.GetLastWriteFileUtcTime(string fullPath) Line 867	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.SystemState.GetFileState(string path) Line 376	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.SystemState.GetAssemblyName(string path) Line 424	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.ReferenceTable.SetPrimaryAssemblyReferenceItem(Microsoft.Build.Framework.ITaskItem referenceAssemblyName) Line 624	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.ReferenceTable.SetPrimaryItems(Microsoft.Build.Framework.ITaskItem[] referenceAssemblyFiles, Microsoft.Build.Framework.ITaskItem[] referenceAssemblyNames, System.Collections.ArrayList exceptions) Line 504	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.ReferenceTable.ComputeClosure(Microsoft.Build.Tasks.DependentAssembly[] remappedAssembliesValue, Microsoft.Build.Framework.ITaskItem[] referenceAssemblyFiles, Microsoft.Build.Framework.ITaskItem[] referenceAssemblyNames, System.Collections.ArrayList exceptions) Line 1634	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.ResolveAssemblyReference.Execute(Microsoft.Build.Shared.FileExists fileExists, Microsoft.Build.Shared.DirectoryExists directoryExists, Microsoft.Build.Tasks.GetDirectories getDirectories, Microsoft.Build.Tasks.GetAssemblyName getAssemblyName, Microsoft.Build.Tasks.GetAssemblyMetadata getAssemblyMetadata, Microsoft.Build.Shared.GetRegistrySubKeyNames getRegistrySubKeyNames, Microsoft.Build.Shared.GetRegistrySubKeyDefaultValue getRegistrySubKeyDefaultValue, Microsoft.Build.Tasks.GetLastWriteTime getLastWriteTime, Microsoft.Build.Tasks.GetAssemblyRuntimeVersion getRuntimeVersion, Microsoft.Build.Shared.OpenBaseKey openBaseKey, Microsoft.Build.Tasks.GetAssemblyPathInGac getAssemblyPathInGac, Microsoft.Build.Tasks.IsWinMDFile isWinMDFile, Microsoft.Build.Tasks.ReadMachineTypeFromPEHeader readMachineTypeFromPEHeader) Line 2194	C#	Symbols loaded.
 	Microsoft.Build.Tasks.Core.dll!Microsoft.Build.Tasks.ResolveAssemblyReference.Execute() Line 2912	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute() Line 631	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(Microsoft.Build.BackEnd.ITaskExecutionHost taskExecutionHost, Microsoft.Build.BackEnd.Logging.TaskLoggingContext taskLoggingContext, Microsoft.Build.BackEnd.TaskHost taskHost, Microsoft.Build.BackEnd.ItemBucket bucket, Microsoft.Build.BackEnd.TaskExecutionMode howToExecuteTask) Line 787	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.InitializeAndExecuteTask(Microsoft.Build.BackEnd.Logging.TaskLoggingContext taskLoggingContext, Microsoft.Build.BackEnd.ItemBucket bucket, System.Collections.Generic.IDictionary<string, string> taskIdentityParameters, Microsoft.Build.BackEnd.TaskHost taskHost, Microsoft.Build.BackEnd.TaskExecutionMode howToExecuteTask) Line 659	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.ExecuteBucket(Microsoft.Build.BackEnd.TaskHost taskHost, Microsoft.Build.BackEnd.ItemBucket bucket, Microsoft.Build.BackEnd.TaskExecutionMode howToExecuteTask, System.Collections.Generic.Dictionary<string, string> lookupHash) Line 434	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.ExecuteTask(Microsoft.Build.BackEnd.TaskExecutionMode mode, Microsoft.Build.BackEnd.Lookup lookup) Line 331	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.ExecuteTask(Microsoft.Build.BackEnd.Logging.TargetLoggingContext loggingContext, Microsoft.Build.BackEnd.BuildRequestEntry requestEntry, Microsoft.Build.BackEnd.ITargetBuilderCallback targetBuilderCallback, Microsoft.Build.Execution.ProjectTargetInstanceChild taskInstance, Microsoft.Build.BackEnd.TaskExecutionMode mode, Microsoft.Build.BackEnd.Lookup inferLookup, Microsoft.Build.BackEnd.Lookup executeLookup, System.Threading.CancellationToken cancellationToken) Line 180	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetEntry.ProcessBucket(Microsoft.Build.BackEnd.ITaskBuilder taskBuilder, Microsoft.Build.BackEnd.Logging.TargetLoggingContext targetLoggingContext, Microsoft.Build.BackEnd.TaskExecutionMode mode, Microsoft.Build.BackEnd.Lookup lookupForInference, Microsoft.Build.BackEnd.Lookup lookupForExecution) Line 818	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetEntry.ExecuteTarget(Microsoft.Build.BackEnd.ITaskBuilder taskBuilder, Microsoft.Build.BackEnd.BuildRequestEntry requestEntry, Microsoft.Build.BackEnd.Logging.ProjectLoggingContext projectLoggingContext, System.Threading.CancellationToken cancellationToken) Line 483	C#	Symbols loaded.
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetBuilder.ProcessTargetStack(Microsoft.Build.BackEnd.ITaskBuilder taskBuilder) Line 465	C#	Symbols loaded.

[davkean]

Okay I can see why this is happening; we have a cache in SystemState.GetFileState - but we always check the modified date time to see if we throw the cache away, even if we only checked 10ms ago. That is the cost. Our invalidation code is costing 4.9% of a build.

[AlgorithmsAreCool]

I'm going to spitball some quick ideas since RAR is by far the biggest time sink in my build right now.

I need to set up a workbench to test out ideas for myself but at first glance I see a few options to soften the impact on the file system.

Option 1 : Throttle GetFileState cache invalidation to n per second.

This option is easy to implement and would cut the IO traffic significantly but has obvious drawbacks.

Option 2 : Use FileSystemWatcher(s)

The idea is to use a watcher to monitor each file in the cache to see if it changes and then push those updates into the backend of the cache.

Advantages :

• 'In theory' this keeps the cache evergreen and eliminates the time stamp check.

Drawbacks :

• The FSW isn't bulletproof and can drop updates, but I believe that with filtering and eager asynchronous event handling this isn't much of an issue (I've used a dataflow ActionBlock to implement this nicely)

• Dubious reliability on non-local disks (e.g. file shares, mapped drives...).

• Scalability. I have no idea how many files are in this cache, if it is hundreds or thousands then we must combine watchers and filter the aggregate data. This gets messy and increases the chance of missing and update.

• XPlat reliability is an unknown. It might be just fine, but I don't have insight into implementation specifics on non-windows platforms.

Option 3 : Lock files active in the cache

Might be an unacceptable change, but if the state of files involved in the build is static then the cache will always be up to date eliminating the need for the lock. If the build is expected to modify some of the files in the cache, then perhaps inheritable files locks are a solution.

[davkean]

Sounds good, make note that the build does produce some of the assemblies in the cache - think project-to-project references.

[AlgorithmsAreCool]

Before I get started, do you see any issue with locking the cached files? I'm thinking I like option 3 the best at the moment.

[davkean]

I see no problem if the state does not change over the lifetime of a single RAR call. Over multiple RAR calls, however, will be problematic.

[davkean]

Changed this bug to be about the cache checking, https://github.com/dotnet/core-setup/issues/3297 is tracking other performance overhead.

[davkean]

Fixed in: davkean@99d4c83.