microsoft · Jan Provazník (JanProvaznik) · Sep 3, 2026 · Sep 3, 2026 · Sep 3, 2026 · David Federman (dfederm)
diff --git a/README.md b/README.md
@@ -73,6 +73,7 @@ These settings are common across all plugins, although different implementations
 | `$(MSBuildCacheTargetsToIgnore)` | `string[]` | `GetTargetFrameworks;GetNativeManifest;GetCopyToOutputDirectoryItems;GetTargetFrameworksWithPlatformForSingleTargetFramework` | The list of targets to ignore when determining if a build request matches a cache entry. This is intended for "information gathering" targets which do not have side-effect. eg. a build with `/t:Build` and `/t:Build;GetTargetFrameworks` should be considered to have equivalent results. Note: This only works "one-way" in that the build request is allowed to have missing targets, while the cache entry is not. This is to avoid a situation where a build request receives a cache hit with missing target results, where a cache hit with extra target results is acceptable. |
 | `$(MSBuildCacheSkipUnchangedOutputFiles)` | `bool` | false | Whether to avoid writing output files on cache hit if the file is unchanged, which can improve performance for incremental builds. A file is considered unchanged if it exists, the previously placed file and file to be placed have the same hash, and the the previously placed file and current file on disk have the same timestamp and file size. |
 | `$(MSBuildCacheTouchOutputFiles)` | `bool` | false | Whether to update the last write time for output files on cache hit. All files for a given cache entry will have the same timestamp. Note that outputs which skip materialization via `MSBuildCacheSkipUnchangedOutputFiles` are still touched. |
+| `$(MSBuildCacheLogCacheOperationTimings)` | `bool` | false | Whether to log per-node timings for fingerprinting, remote cache queries, cache metadata processing, dependency waits, and output materialization. Intended for performance diagnostics; enabling it produces several messages per project. Operations can overlap, so their durations must not be summed to infer wall-clock time. |
 | `$(MSBuildCacheIgnoreDotNetSdkPatchVersion)` | `bool` | false | Whether to ignore the patch version when doing cache lookups. This trades off some correctness for the sake of getting cache hits when the SDK version isn't exactly the same. The default behavior is to consider the exact SDK version, eg. "8.0.404". With this setting set to true, it will instead use something like "8.0.4XX". Note that the major version, minor version, and feature bands are still considered. |
 | `$(MSBuildCacheEnableProbeAndEnumerationFingerprinting)` | `bool` | true | Whether file probes (existence checks) and directory enumerations contribute to the strong fingerprint, enabling correct caching for incremental builds — including cases where MSBuild source globs match different files. Requires an MSBuild that reports directory enumeration patterns; on older versions this is forced to `false` and a message is logged. |
 

diff --git a/src/Common.Tests/PluginSettingsTests.cs b/src/Common.Tests/PluginSettingsTests.cs
@@ -89,6 +89,12 @@ public void MaxConcurrentCacheContentOperationsSetting()
             pluginSettings => pluginSettings.MaxConcurrentCacheContentOperations,
             new[] { 123, 456, 789 });
 
+    [TestMethod]
+    public void LogCacheOperationTimingsSetting()
+        => TestBoolSetting(
+            nameof(PluginSettings.LogCacheOperationTimings),
+            pluginSettings => pluginSettings.LogCacheOperationTimings);
+
     [TestMethod]
     public void LocalCacheRootPathSetting()
         => TestBasicSetting(

diff --git a/src/Common/Caching/CacheClient.cs b/src/Common/Caching/CacheClient.cs
@@ -4,6 +4,7 @@
 using System;
 using System.Collections.Concurrent;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.IO;
 using System.Text.Json;
 using System.Text.Json.Serialization.Metadata;
@@ -46,6 +47,7 @@ public abstract class CacheClient : ICacheClient
     private readonly ICopyOnWriteFilesystem _copyOnWriteFilesystem = CopyOnWriteFilesystemFactory.GetInstance();
     private readonly IContentHasher _hasher;
     private readonly IFingerprintFactory _fingerprintFactory;
+    private readonly AsyncLocal<Action<NodeContext, string, long>?> _operationCompleted = new();
     private readonly bool _enableAsyncMaterialization;
     private readonly bool _touchOutputFiles;
     private readonly ICache _localCache;
@@ -126,6 +128,9 @@ protected CacheClient(
 
     protected Func<string, FileRealizationMode> GetFileRealizationMode { get; }
 
+    internal IDisposable TrackOperationTimings(Action<NodeContext, string, long> operationCompleted)
+        => new OperationTimingScope(_operationCompleted, operationCompleted);
+
     /* abstract methods for subclasses to implement */
     protected abstract Task<OpenStreamResult> OpenStreamAsync(Context context, ContentHash contentHash, CancellationToken cancellationToken);
 
@@ -380,7 +385,10 @@ public async Task AddNodeInternalAsync(
             {
                 if (_materializationTasks.TryGetValue(dependency, out Task? dependencyMaterializationTask))
                 {
-                    await dependencyMaterializationTask;
+                    using (StartOperation(nodeContext, "dependency-materialization-wait"))
+                    {
+                        await dependencyMaterializationTask;
+                    }
                 }
             }
         }
@@ -397,7 +405,12 @@ public async Task AddNodeInternalAsync(
 
         Tracer.Debug(context, $"{nameof(GetNodeAsync)}: {nodeContext.Id}");
 
-        Fingerprint? weakFingerprint = await _fingerprintFactory.GetWeakFingerprintAsync(nodeContext);
+        Fingerprint? weakFingerprint;
+        using (StartOperation(nodeContext, "weak-fingerprint"))
+        {
+            weakFingerprint = await _fingerprintFactory.GetWeakFingerprintAsync(nodeContext);
+        }
+
         if (weakFingerprint == null)
         {
             Tracer.Debug(context, $"Weak fingerprint is null for {nodeContext.Id}");
@@ -406,7 +419,7 @@ public async Task AddNodeInternalAsync(
 
         WeakFingerprint cacheWeakFingerprint = new(weakFingerprint.Hash);
 
-        (Selector? selector, PathSet? pathSet) = await GetMatchingSelectorAsync(context, cacheWeakFingerprint, cancellationToken);
+        (Selector? selector, PathSet? pathSet) = await GetMatchingSelectorAsync(context, nodeContext, cacheWeakFingerprint, cancellationToken);
         if (!selector.HasValue)
         {
             // GetMatchingSelectorAsync logs sufficiently
@@ -415,22 +428,39 @@ public async Task AddNodeInternalAsync(
 
         StrongFingerprint cacheStrongFingerprint = new(cacheWeakFingerprint, selector.Value);
 
-        ICacheEntry? cacheEntry = await GetCacheEntryAsync(context, cacheStrongFingerprint, cancellationToken);
+        ICacheEntry? cacheEntry;
+        using (StartOperation(nodeContext, "cache-entry-lookup"))
+        {
+            cacheEntry = await GetCacheEntryAsync(context, cacheStrongFingerprint, cancellationToken);
+        }
+
         if (cacheEntry is null)
         {
             Tracer.Debug(context, $"{nameof(GetCacheEntryAsync)} did not find an entry for {cacheStrongFingerprint}.");
             return (null, null);
         }
 
-        using Stream? nodeBuildResultStream = await cacheEntry.GetNodeBuildResultAsync(context, cancellationToken);
+        Stream? nodeBuildResultStream;
+        using (StartOperation(nodeContext, "node-result-fetch"))
+        {
+            nodeBuildResultStream = await cacheEntry.GetNodeBuildResultAsync(context, cancellationToken);
+        }
+
         if (nodeBuildResultStream is null)
         {
             Tracer.Debug(context, $"Failed to fetch NodeBuildResult for {cacheStrongFingerprint}");
             return (null, null);
         }
 
+        using Stream nodeBuildResultStreamToDispose = nodeBuildResultStream;
+
         // The first file is special: it is a serialized NodeBuildResult file.
-        NodeBuildResult? nodeBuildResult = await DeserializeAsync(context, nodeBuildResultStream, SourceGenerationContext.Default.NodeBuildResult, cancellationToken);
+        NodeBuildResult? nodeBuildResult;
+        using (StartOperation(nodeContext, "node-result-deserialize"))
+        {
+            nodeBuildResult = await DeserializeAsync(context, nodeBuildResultStreamToDispose, SourceGenerationContext.Default.NodeBuildResult, cancellationToken);
+        }
+
         if (nodeBuildResult is null)
         {
             Tracer.Debug(context, $"Failed to deserialize NodeBuildResult for {cacheStrongFingerprint}");
@@ -542,14 +572,21 @@ async Task PlaceFilesAsync(CancellationToken ct)
                     Task.Run(
                         async () =>
                         {
-                            await PlaceFilesAsync(CancellationToken.None);
+                            using (StartOperation(nodeContext, "output-materialization"))
+                            {
+                                await PlaceFilesAsync(CancellationToken.None);
+                            }
+
                             _materializationTasks.TryRemove(nodeContext, out _);
                         },
                         CancellationToken.None));
             }
             else
             {
-                await PlaceFilesAsync(cancellationToken);
+                using (StartOperation(nodeContext, "output-materialization"))
+                {
+                    await PlaceFilesAsync(cancellationToken);
+                }
             }
         }
 
@@ -558,13 +595,27 @@ async Task PlaceFilesAsync(CancellationToken ct)
 
     private async Task<(Selector? Selector, PathSet? PathSet)> GetMatchingSelectorAsync(
         Context context,
+        NodeContext nodeContext,
         WeakFingerprint weakFingerprint,
         CancellationToken cancellationToken)
     {
         context = new(context);
 
-        await foreach (Selector selector in GetSelectors(context, weakFingerprint, cancellationToken))
+        await using IAsyncEnumerator<Selector> selectors = GetSelectors(context, weakFingerprint, cancellationToken).GetAsyncEnumerator(cancellationToken);
+        while (true)
         {
+            bool hasSelector;
+            using (StartOperation(nodeContext, "selector-query"))
+            {
+                hasSelector = await selectors.MoveNextAsync();
+            }
+
+            if (!hasSelector)
+            {
+                break;
+            }
+
+            Selector selector = selectors.Current;
             if (selector == EmptySelector)
             {
                 // Special-case for the empty selector, which always matches.
@@ -575,7 +626,11 @@ async Task PlaceFilesAsync(CancellationToken ct)
             ContentHash pathSetHash = selector.ContentHash;
             byte[]? selectorStrongFingerprint = selector.Output;
 
-            PathSet? pathSet = await FetchAndDeserializeFromCacheAsync(context, pathSetHash, SourceGenerationContext.Default.PathSet, cancellationToken);
+            PathSet? pathSet;
+            using (StartOperation(nodeContext, "path-set-fetch"))
+            {
+                pathSet = await FetchAndDeserializeFromCacheAsync(context, pathSetHash, SourceGenerationContext.Default.PathSet, cancellationToken);
+            }
 
             if (pathSet is null)
             {
@@ -587,13 +642,24 @@ async Task PlaceFilesAsync(CancellationToken ct)
             // state into the strong fingerprint rather than anything read from disk, so the comparison below
             // cannot detect that they no longer hold. This check is what enforces them. The fingerprint
             // comparison still covers file-content changes.
-            if (!_fingerprintFactory.MatchesCurrentState(pathSet))
+            bool matchesCurrentState;
+            using (StartOperation(nodeContext, "path-set-validation"))
+            {
+                matchesCurrentState = _fingerprintFactory.MatchesCurrentState(pathSet);
+            }
+
+            if (!matchesCurrentState)
             {
                 Tracer.Debug(context, $"Skipping selector with PathSet hash {pathSetHash}. Probes/enumerations no longer match current filesystem state.");
                 continue;
             }
 
-            Fingerprint? possibleStrongFingerprint = await _fingerprintFactory.GetStrongFingerprintAsync(pathSet);
+            Fingerprint? possibleStrongFingerprint;
+            using (StartOperation(nodeContext, "strong-fingerprint"))
+            {
+                possibleStrongFingerprint = await _fingerprintFactory.GetStrongFingerprintAsync(pathSet);
+            }
+
             if (possibleStrongFingerprint != null && ByteArrayComparer.ArraysEqual(possibleStrongFingerprint.Hash, selectorStrongFingerprint))
             {
                 Tracer.Debug(context, $"Matched matching selector with PathSet hash {pathSetHash} for weak fingerprint {weakFingerprint}");
@@ -605,6 +671,53 @@ async Task PlaceFilesAsync(CancellationToken ct)
         return (null, null);
     }
 
+    private OperationTimer StartOperation(NodeContext nodeContext, string operation)
+        => new(_operationCompleted.Value, nodeContext, operation);
+
+    private sealed class OperationTimingScope : IDisposable
+    {
+        private readonly AsyncLocal<Action<NodeContext, string, long>?> _operationCompleted;
+        private readonly Action<NodeContext, string, long>? _previousOperationCompleted;
+
+        public OperationTimingScope(
+            AsyncLocal<Action<NodeContext, string, long>?> operationCompleted,
+            Action<NodeContext, string, long> currentOperationCompleted)
+        {
+            _operationCompleted = operationCompleted;
+            _previousOperationCompleted = operationCompleted.Value;
+            operationCompleted.Value = currentOperationCompleted;
+        }
+
+        public void Dispose()
+        {
+            _operationCompleted.Value = _previousOperationCompleted;
+        }
+    }
+
+    private readonly struct OperationTimer : IDisposable
+    {
+        private readonly Action<NodeContext, string, long>? _operationCompleted;
+        private readonly NodeContext _nodeContext;
+        private readonly string _operation;
+        private readonly long _startTimestamp;
+
+        public OperationTimer(Action<NodeContext, string, long>? operationCompleted, NodeContext nodeContext, string operation)
+        {
+            _operationCompleted = operationCompleted;
+            _nodeContext = nodeContext;
+            _operation = operation;
+            _startTimestamp = operationCompleted is null ? 0 : Stopwatch.GetTimestamp();
+        }
+
+        public void Dispose()
+        {
+            _operationCompleted?.Invoke(
+                _nodeContext,
+                _operation,
+                (long)((Stopwatch.GetTimestamp() - _startTimestamp) * 1_000_000.0 / Stopwatch.Frequency));
+        }
+    }
+
     private static async Task<byte[]> SerializeAsync<T>(T data, JsonTypeInfo<T> typeInfo, CancellationToken cancellationToken)
         where T : class
     {

diff --git a/src/Common/MSBuildCachePluginBase.cs b/src/Common/MSBuildCachePluginBase.cs
@@ -114,6 +114,7 @@ static MSBuildCachePluginBase() =>
         nameof(_pluginLogger),
         nameof(_repoRoot),
         nameof(NugetPackageRoot),
+        nameof(Settings),
         nameof(_pathNormalizer),
         nameof(ContentHasher),
         nameof(InputHasher),
@@ -472,7 +473,23 @@ private async Task<CacheResult> GetCacheResultSingleAsync(NodeContext nodeContex
 
         nodeContext.SetStartTime();
 
-        (PathSet? pathSet, NodeBuildResult? nodeBuildResult) = await _cacheClient.GetNodeAsync(nodeContext, materializeOutputs, cancellationToken);
+        IDisposable? operationTimingScope = null;
+        if (Settings.LogCacheOperationTimings && _cacheClient is CacheClient cacheClient)
+        {
+            operationTimingScope = cacheClient.TrackOperationTimings(
+                (timedNodeContext, operation, elapsedMicroseconds) =>
+                    logger.LogMessage(
+                        $"MSBuildCache phase \"{operation}\" for \"{timedNodeContext.Id}\" elapsed {elapsedMicroseconds} us.",
+                        MessageImportance.High));
+        }
+
+        PathSet? pathSet;
+        NodeBuildResult? nodeBuildResult;
+        using (operationTimingScope)
+        {
+            (pathSet, nodeBuildResult) = await _cacheClient.GetNodeAsync(nodeContext, materializeOutputs, cancellationToken);
+        }
+
         if (nodeBuildResult is null)
         {
             Interlocked.Increment(ref _cacheMissCount);

diff --git a/src/Common/PluginSettings.cs b/src/Common/PluginSettings.cs
@@ -114,6 +114,8 @@ public string LocalCacheRootPath
 
     public bool TouchOutputFiles { get; init; }
 
+    public bool LogCacheOperationTimings { get; init; }
+
     /// <summary>
     /// Enables probe and directory-enumeration tracking in fingerprints. When false, only file content
     /// reads contribute to the fingerprint, matching pre-feature behavior.

diff --git a/src/Common/build/Microsoft.MSBuildCache.Common.targets b/src/Common/build/Microsoft.MSBuildCache.Common.targets
@@ -26,6 +26,7 @@
     <MSBuildCacheGlobalPropertiesToIgnore>$(MSBuildCacheGlobalPropertiesToIgnore);MSBuildCacheIgnoreDotNetSdkPatchVersion</MSBuildCacheGlobalPropertiesToIgnore>
     <MSBuildCacheGlobalPropertiesToIgnore>$(MSBuildCacheGlobalPropertiesToIgnore);MSBuildCacheSkipUnchangedOutputFiles</MSBuildCacheGlobalPropertiesToIgnore>
     <MSBuildCacheGlobalPropertiesToIgnore>$(MSBuildCacheGlobalPropertiesToIgnore);MSBuildCacheTouchOutputFiles</MSBuildCacheGlobalPropertiesToIgnore>
+    <MSBuildCacheGlobalPropertiesToIgnore>$(MSBuildCacheGlobalPropertiesToIgnore);MSBuildCacheLogCacheOperationTimings</MSBuildCacheGlobalPropertiesToIgnore>
     <MSBuildCacheGlobalPropertiesToIgnore>$(MSBuildCacheGlobalPropertiesToIgnore);MSBuildCacheEnableProbeAndEnumerationFingerprinting</MSBuildCacheGlobalPropertiesToIgnore>
   </PropertyGroup>
 
@@ -52,6 +53,7 @@
       <IgnoreDotNetSdkPatchVersion>$(MSBuildCacheIgnoreDotNetSdkPatchVersion)</IgnoreDotNetSdkPatchVersion>
       <SkipUnchangedOutputFiles>$(MSBuildCacheSkipUnchangedOutputFiles)</SkipUnchangedOutputFiles>
       <TouchOutputFiles>$(MSBuildCacheTouchOutputFiles)</TouchOutputFiles>
+      <LogCacheOperationTimings>$(MSBuildCacheLogCacheOperationTimings)</LogCacheOperationTimings>
       <EnableProbeAndEnumerationFingerprinting>$(MSBuildCacheEnableProbeAndEnumerationFingerprinting)</EnableProbeAndEnumerationFingerprinting>
     </ProjectCachePlugin>
   </ItemGroup>