diff --git a/src/Common.Tests/PluginSettingsTests.cs b/src/Common.Tests/PluginSettingsTests.cs index dc7c598..9ea0fef 100644 --- a/src/Common.Tests/PluginSettingsTests.cs +++ b/src/Common.Tests/PluginSettingsTests.cs @@ -351,16 +351,20 @@ public void GlobalPropertiesToIgnoreSetting(string? settingValue, string[] expec CollectionAssert.AreEqual(expectedValue, pluginSettings.GlobalPropertiesToIgnore.ToList()); } + [TestMethod] + public void GetResultsForUnqueriedDependenciesSetting() + => TestBoolSetting(nameof(PluginSettings.GetResultsForUnqueriedDependencies), pluginSettings => pluginSettings.GetResultsForUnqueriedDependencies); + private static void TestBoolSetting(string settingName, Func valueAccessor) => TestBasicSetting( settingName, valueAccessor, - testValues: new[] { false, true }); + testValues: [false, true]); private static void TestBasicSetting( string settingName, Func valueAccessor, - T[] testValues) + ReadOnlySpan testValues) { T defaultValue = valueAccessor(DefaultPluginSettings); diff --git a/src/Common/Caching/CacheClient.cs b/src/Common/Caching/CacheClient.cs index 1d3fcb7..8d831a2 100644 --- a/src/Common/Caching/CacheClient.cs +++ b/src/Common/Caching/CacheClient.cs @@ -385,6 +385,7 @@ await AddNodeAsync( if (!selector.HasValue) { // GetMatchingSelectorAsync logs sufficiently + MSBuildCachePluginBase.DumpPartialFingerprintLog("weak", nodeContext, weakFingerprint); return (null, null); } diff --git a/src/Common/Fingerprinting/FingerprintFactory.cs b/src/Common/Fingerprinting/FingerprintFactory.cs index c78e24e..92cab94 100644 --- a/src/Common/Fingerprinting/FingerprintFactory.cs +++ b/src/Common/Fingerprinting/FingerprintFactory.cs @@ -96,7 +96,7 @@ void AddSettingToFingerprint(IReadOnlyCollection? patterns, string setting string vcToolsVersion = nodeContext.ProjectInstance.GetPropertyValue("VCToolsVersion"); if (!string.IsNullOrEmpty(vcToolsVersion)) { - entries.Add(CreateFingerprintEntry($"VCToolsVersion: {vcToolsVersion}")); + //entries.Add(CreateFingerprintEntry($"VCToolsVersion: {vcToolsVersion}")); } // If the .NET SDK changes, the node should rebuild. diff --git a/src/Common/MSBuildCachePluginBase.cs b/src/Common/MSBuildCachePluginBase.cs index 7cb94e0..3bb4fe7 100644 --- a/src/Common/MSBuildCachePluginBase.cs +++ b/src/Common/MSBuildCachePluginBase.cs @@ -67,6 +67,7 @@ public abstract class MSBuildCachePluginBase : ProjectCachePlug private DirectoryLock? _localCacheDirectoryLock; private SemaphoreSlim? _singlePluginInstanceMutex; private PathNormalizer? _pathNormalizer; + private Func>? _getCacheResultAsync; private int _cacheHitCount; private long _cacheHitDurationMilliseconds; @@ -122,7 +123,8 @@ static MSBuildCachePluginBase() => nameof(_fileAccessRepository), nameof(_cacheClient), nameof(_ignoredOutputPatterns), - nameof(_identicalDuplicateOutputPatterns) + nameof(_identicalDuplicateOutputPatterns), + nameof(_getCacheResultAsync) )] protected bool Initialized { get; private set; } @@ -321,6 +323,16 @@ private async Task BeginBuildInnerAsync(CacheContext context, PluginLoggerBase l _fileAccessRepository = new FileAccessRepository(logger, Settings); _cacheClient = await CreateCacheClientAsync(logger, cancellationToken); + if (Settings.GetResultsForUnqueriedDependencies) + { + ConcurrentDictionary>> cacheResults = new(concurrencyLevel: Environment.ProcessorCount, _nodeContexts.Count); + _getCacheResultAsync = (nodeContext, logger, cancellationToken) => GetCacheResultRecursivelyAsync(cacheResults, nodeContext, logger, cancellationToken); + } + else + { + _getCacheResultAsync = GetCacheResultNonRecursiveAsync; + } + // Ensure all logs are written await Task.WhenAll(dumpParserInfoTasks); await dumpNodeContextsTask; @@ -356,6 +368,7 @@ private async Task GetCacheResultInnerAsync(BuildRequestData buildR if (!Initialized) { // BeginBuild didn't finish successfully. It's expected to log sufficiently, so just bail. + logger.LogWarning($"Cache Miss for build {buildRequest.ProjectFullPath}: cache is not initialized."); return CacheResult.IndicateNonCacheHit(CacheResultType.CacheNotApplicable); } @@ -369,20 +382,87 @@ private async Task GetCacheResultInnerAsync(BuildRequestData buildR NodeDescriptor nodeDescriptor = _nodeDescriptorFactory.Create(projectInstance); if (!_nodeContexts.TryGetValue(nodeDescriptor, out NodeContext? nodeContext)) { + logger.LogWarning($"Cache Miss for build {buildRequest.ProjectFullPath}: cannot find node context {nodeDescriptor}"); return CacheResult.IndicateNonCacheHit(CacheResultType.CacheNotApplicable); } nodeContext.SetStartTime(); - if (!nodeContext.TargetNames.SetEquals(buildRequest.TargetNames)) + if (!nodeContext.TargetNames.IsSupersetOf(buildRequest.TargetNames)) { - logger.LogMessage($"`TargetNames` does not match for {nodeContext.Id}. `{string.Join(";", nodeContext.TargetNames)}` vs `{string.Join(";", buildRequest.TargetNames)}`."); + logger.LogWarning($"Cache Miss for build {buildRequest.ProjectFullPath}: `TargetNames` does not match for {nodeContext.Id}. `{string.Join(";", nodeContext.TargetNames)}` vs `{string.Join(";", buildRequest.TargetNames)}`."); return CacheResult.IndicateNonCacheHit(CacheResultType.CacheNotApplicable); } + var result = await _getCacheResultAsync(nodeContext, logger, cancellationToken); + + string targets = string.Join(";", buildRequest.TargetNames); + logger.LogWarning($"Cache {result.ResultType} for build {buildRequest.ProjectFullPath} ({targets})"); + + return result; + } + + private async Task GetCacheResultRecursivelyAsync( + ConcurrentDictionary>> cacheResults, + NodeContext nodeContext, + PluginLoggerBase logger, + CancellationToken cancellationToken) + { + // Ensure we only query a node exactly once. MSBuild won't query a project more than once, but when recursion is enabled, + // we might have multiple build requests querying the same unqueried dependency. + return await cacheResults.GetOrAdd(nodeContext, new Lazy>( + async () => + { + foreach (NodeContext dependency in nodeContext.Dependencies) + { + if (dependency.BuildResult == null) + { + logger.LogMessage($"Querying cache for missing build result for dependency '{dependency.Id}'"); + CacheResult dependencyResult = await GetCacheResultRecursivelyAsync(cacheResults, dependency, logger, cancellationToken); + logger.LogMessage($"Dependency '{dependency.Id}' cache result: '{dependencyResult.ResultType}'"); + + if (dependencyResult.ResultType != CacheResultType.CacheHit) + { + logger.LogWarning($"Cache miss due to failed build result for dependency '{dependency.Id}'"); + Interlocked.Increment(ref _cacheMissCount); + return CacheResult.IndicateNonCacheHit(CacheResultType.CacheMiss); + } + } + } + + return await GetCacheResultSingleAsync(nodeContext, logger, cancellationToken); + })).Value; + } + + private async Task GetCacheResultNonRecursiveAsync(NodeContext nodeContext, PluginLoggerBase logger, CancellationToken cancellationToken) + { + foreach (NodeContext dependency in nodeContext.Dependencies) + { + if (dependency.BuildResult == null) + { + logger.LogWarning($"Cache miss due to failed or missing build result for dependency '{dependency.Id}'"); + Interlocked.Increment(ref _cacheMissCount); + return CacheResult.IndicateNonCacheHit(CacheResultType.CacheMiss); + } + } + + return await GetCacheResultSingleAsync(nodeContext, logger, cancellationToken); + } + + private async Task GetCacheResultSingleAsync(NodeContext nodeContext, PluginLoggerBase logger, CancellationToken cancellationToken) + { + if (!Initialized) + { + throw new InvalidOperationException(); + } + + nodeContext.SetStartTime(); + (PathSet? pathSet, NodeBuildResult? nodeBuildResult) = await _cacheClient.GetNodeAsync(nodeContext, cancellationToken); if (nodeBuildResult is null) { + logger.LogWarning($"Cache miss due to failed to find build result '{nodeContext.Id}'"); + Interlocked.Increment(ref _cacheMissCount); return CacheResult.IndicateNonCacheHit(CacheResultType.CacheMiss); } @@ -472,6 +552,7 @@ private async Task HandleProjectFinishedInnerAsync(FileAccessContext fileAccessC // If file access reports are disabled in MSBuild we can't cache anything as we don't know what to cache. if (!_hasHadFileAccessReport) { + await DumpFingerprintLogAsync(logger, nodeContext, null); return; } @@ -798,36 +879,53 @@ private async Task DumpFingerprintLogAsync( { logger.LogWarning($"Non-fatal exception while writing {filePath}. {ex.GetType().Name}: {ex.Message}"); } + } - static void WriteFingerprintJson(Utf8JsonWriter jsonWriter, string propertyName, Fingerprint? fingerprint) + internal static void DumpPartialFingerprintLog(string fingerprintType, NodeContext nodeContext, Fingerprint fingerprint) + { + string filePath = Path.Combine(nodeContext.LogDirectory, $"fingerprint_{fingerprintType}.json"); + try { - jsonWriter.WritePropertyName(propertyName); - - if (fingerprint == null) - { - jsonWriter.WriteNullValue(); - return; - } + using FileStream fileStream = File.Create(filePath); + using var jsonWriter = new Utf8JsonWriter(fileStream, SerializationHelper.WriterOptions); jsonWriter.WriteStartObject(); + WriteFingerprintJson(jsonWriter, fingerprintType, fingerprint); + jsonWriter.WriteEndObject(); + } + catch (Exception) + { + } + } - jsonWriter.WriteString("hash", fingerprint.Hash.ToHex()); + private static void WriteFingerprintJson(Utf8JsonWriter jsonWriter, string propertyName, Fingerprint? fingerprint) + { + jsonWriter.WritePropertyName(propertyName); - jsonWriter.WritePropertyName("entries"); - jsonWriter.WriteStartArray(); + if (fingerprint == null) + { + jsonWriter.WriteNullValue(); + return; + } - foreach (FingerprintEntry entry in fingerprint.Entries) - { - jsonWriter.WriteStartObject(); - jsonWriter.WriteString("hash", entry.Hash.ToHex()); - jsonWriter.WriteString("description", entry.Description); - jsonWriter.WriteEndObject(); - } + jsonWriter.WriteStartObject(); + + jsonWriter.WriteString("hash", fingerprint.Hash.ToHex()); - jsonWriter.WriteEndArray(); // entries array + jsonWriter.WritePropertyName("entries"); + jsonWriter.WriteStartArray(); + foreach (FingerprintEntry entry in fingerprint.Entries) + { + jsonWriter.WriteStartObject(); + jsonWriter.WriteString("hash", entry.Hash.ToHex()); + jsonWriter.WriteString("description", entry.Description); jsonWriter.WriteEndObject(); } + + jsonWriter.WriteEndArray(); // entries array + + jsonWriter.WriteEndObject(); } private static async Task DumpBuildResultLogAsync( diff --git a/src/Common/NodeDescriptor.cs b/src/Common/NodeDescriptor.cs index 1378326..264ceef 100644 --- a/src/Common/NodeDescriptor.cs +++ b/src/Common/NodeDescriptor.cs @@ -3,9 +3,11 @@ using System; using System.Collections.Generic; +using System.Diagnostics; namespace Microsoft.MSBuildCache; +[DebuggerDisplay($"{{{nameof(DebuggerDisplay)}, nq}}")] internal readonly struct NodeDescriptor : IEquatable { private readonly string _projectFullPath; @@ -23,6 +25,8 @@ public NodeDescriptor(string projectFullPath, SortedDictionary f /// public IReadOnlyDictionary FilteredGlobalProperties => _filteredGlobalProperties; + private string DebuggerDisplay => $"{_projectFullPath} ({_filteredGlobalProperties.Count})"; + public bool Equals(NodeDescriptor other) { if (!_projectFullPath.Equals(other._projectFullPath, StringComparison.OrdinalIgnoreCase)) diff --git a/src/Common/PluginSettings.cs b/src/Common/PluginSettings.cs index fed4b7b..a10dd70 100644 --- a/src/Common/PluginSettings.cs +++ b/src/Common/PluginSettings.cs @@ -101,6 +101,8 @@ public string LocalCacheRootPath public IReadOnlyList GlobalPropertiesToIgnore { get; init; } = Array.Empty(); + public bool GetResultsForUnqueriedDependencies { get; init; } + public static T Create( IReadOnlyDictionary settings, PluginLoggerBase logger, diff --git a/src/Common/build/Microsoft.MSBuildCache.Common.targets b/src/Common/build/Microsoft.MSBuildCache.Common.targets index 75cc593..8ae961b 100644 --- a/src/Common/build/Microsoft.MSBuildCache.Common.targets +++ b/src/Common/build/Microsoft.MSBuildCache.Common.targets @@ -20,6 +20,17 @@ $(MSBuildCacheGlobalPropertiesToIgnore);MSBuildCacheAllowFileAccessAfterProjectFinishFilePatterns $(MSBuildCacheGlobalPropertiesToIgnore);MSBuildCacheAllowProcessCloseAfterProjectFinishProcessPatterns $(MSBuildCacheGlobalPropertiesToIgnore);MSBuildCacheGlobalPropertiesToIgnore + $(MSBuildCacheGlobalPropertiesToIgnore);MSBuildCachePackageName + $(MSBuildCacheGlobalPropertiesToIgnore);MSBuildCachePackageVersion + $(MSBuildCacheGlobalPropertiesToIgnore);IsGraphBuild + $(MSBuildCacheGlobalPropertiesToIgnore);UseHostCompilerIfAvailable + $(MSBuildCacheGlobalPropertiesToIgnore);LangID + $(MSBuildCacheGlobalPropertiesToIgnore);LangName + $(MSBuildCacheGlobalPropertiesToIgnore);DefineExplicitDefaults + $(MSBuildCacheGlobalPropertiesToIgnore);EnableCaching + $(MSBuildCacheGlobalPropertiesToIgnore);VSIDEResolvedNonMSBuildProjectOutputs + $(MSBuildCacheGlobalPropertiesToIgnore);DevEnvDir + $(MSBuildCacheGlobalPropertiesToIgnore);MSBuildCacheGetResultsForUnqueriedDependencies @@ -39,6 +50,7 @@ $(MSBuildCacheAllowFileAccessAfterProjectFinishFilePatterns) $(MSBuildCacheAllowProcessCloseAfterProjectFinishProcessPatterns) $(MSBuildCacheGlobalPropertiesToIgnore) + $(MSBuildCacheGetResultsForUnqueriedDependencies)