Merged PR 729087: Separate cache miss types and their associated counters

Previously the values of cache miss types are aligned with their counters. This can cause an issue when performing analysis with BXL that has a different version from the on producing the execution log. The BXL used for performing the analysis may include changes that modify the counter enums. When doing the analysis, the analysis shows no error, but the miss type shown can be misleading because the cache miss types have different values.

Ideally, one uses the same BXL for analysis as the one used for producing the execution log. However, there's nothing preventing the customers from using a different version of BXL so long as the execution log format is compatible.

This PR also includes a fix in counting cache hits and misses.

Related work items: #2082529

Author: narasamdya

Public/Src/Engine/Scheduler/PipCacheMissType.cs

@@ -1,75 +1,110 @@
 // Copyright (c) Microsoft Corporation.
 // Licensed under the MIT License.
 
+using System;
+using System.Collections.Generic;
+using System.Linq;
+
 namespace BuildXL.Scheduler
 {
     /// <summary>
     /// Mutually exclusive reasons for pip cache misses.
-    /// These are 1:1 correlated with cache miss counters <see cref="PipExecutorCounter"/>. If those counters
-    /// are deprecated, then this can become the main enum for cache misses. 
     /// </summary>
     public enum PipCacheMissType : byte
     {
         /// <summary>
-        /// default
+        /// Default
         /// </summary>
         Invalid = 0,
 
         /// <summary>
         /// Number of times a process pip cache descriptor was not usable due to mismatched strong fingerprints
         /// </summary>
-        MissForDescriptorsDueToStrongFingerprints = PipExecutorCounter.CacheMissesForDescriptorsDueToStrongFingerprints,
+        MissForDescriptorsDueToStrongFingerprints,
 
         /// <summary>
         /// Number of times a process pip cache entry was not found (no prior execution information).
         /// </summary>
-        MissForDescriptorsDueToWeakFingerprints = PipExecutorCounter.CacheMissesForDescriptorsDueToWeakFingerprints,
+        MissForDescriptorsDueToWeakFingerprints,
 
         /// <summary>
         /// Number of times a process pip cache entry was not found (no prior execution information).
         /// </summary>
-        MissForDescriptorsDueToAugmentedWeakFingerprints = PipExecutorCounter.CacheMissesForDescriptorsDueToAugmentedWeakFingerprints,
+        MissForDescriptorsDueToAugmentedWeakFingerprints,
 
         /// <summary>
         /// Number of times a process pip was forced to be a cache miss (despite finding a descriptor) due to artifial cache miss injection.
         /// </summary>
-        MissForDescriptorsDueToArtificialMissOptions = PipExecutorCounter.CacheMissesForDescriptorsDueToArtificialMissOptions,
+        MissForDescriptorsDueToArtificialMissOptions,
 
         /// <summary>
         /// Numter of times strong fingerprint match was found but the corresponding <see cref="BuildXL.Engine.Cache.Fingerprints.CacheEntry"/> was not retrievable
         /// </summary>
-        MissForCacheEntry = PipExecutorCounter.CacheMissesForCacheEntry,
+        MissForCacheEntry,
 
         /// <summary>
         /// Number of times a process pip cache descriptor was found, but was invalid
         /// </summary>
-        MissDueToInvalidDescriptors = PipExecutorCounter.CacheMissesDueToInvalidDescriptors,
+        MissDueToInvalidDescriptors,
 
         /// <summary>
         /// Number of times a process pip cache descriptor was found but the metadata was not retrievable
         /// </summary>
-        MissForProcessMetadata = PipExecutorCounter.CacheMissesForProcessMetadata,
+        MissForProcessMetadata,
 
         /// <summary>
         /// Number of times a process pip cache descriptor was found but the metadata was not retrievable
         /// </summary>
-        MissForProcessMetadataFromHistoricMetadata = PipExecutorCounter.CacheMissesForProcessMetadataFromHistoricMetadata,
+        MissForProcessMetadataFromHistoricMetadata,
 
         /// <summary>
         /// Number of times a process pip cache descriptor was found, but the referenced output content was not available when needed.
         /// The cache descriptor has been counted as a part of <see cref="PipExecutorCounter.CacheHitsForProcessPipDescriptors"/>.
         /// </summary>
-        MissForProcessOutputContent = PipExecutorCounter.CacheMissesForProcessOutputContent,
+        MissForProcessOutputContent,
 
         /// <summary>
         /// Number of times a process pip cache descriptor was found, and the output content was available when needed.
         /// The cache descriptor has been counted as a part of <see cref="PipExecutorCounter.CacheHitsForProcessPipDescriptors"/>.
         /// </summary>
-        Hit = PipExecutorCounter.CacheHitsForProcessPipDescriptors,
+        Hit,
 
         /// <summary>
         /// Number of times a process pip was a miss due to being configured to always miss on cache lookup.
         /// </summary>
-        MissForProcessConfiguredUncacheable = PipExecutorCounter.CacheMissesForProcessConfiguredUncacheable,
+        MissForProcessConfiguredUncacheable,
+    }
+
+    /// <summary>
+    /// Extensions for <see cref="PipCacheMissType"/>.
+    /// </summary>
+    public static class PipCacheMissTypeExtensions
+    {
+        /// <summary>
+        /// Gets the counter associated with the cache miss type.
+        /// </summary>
+        public static PipExecutorCounter ToCounter(this PipCacheMissType type) => type switch
+        {
+            PipCacheMissType.MissForDescriptorsDueToStrongFingerprints => PipExecutorCounter.CacheMissesForDescriptorsDueToStrongFingerprints,
+            PipCacheMissType.MissForDescriptorsDueToWeakFingerprints => PipExecutorCounter.CacheMissesForDescriptorsDueToWeakFingerprints,
+            PipCacheMissType.MissForDescriptorsDueToAugmentedWeakFingerprints => PipExecutorCounter.CacheMissesForDescriptorsDueToAugmentedWeakFingerprints,
+            PipCacheMissType.MissForDescriptorsDueToArtificialMissOptions => PipExecutorCounter.CacheMissesForDescriptorsDueToArtificialMissOptions,
+            PipCacheMissType.MissForCacheEntry => PipExecutorCounter.CacheMissesForCacheEntry,
+            PipCacheMissType.MissDueToInvalidDescriptors => PipExecutorCounter.CacheMissesDueToInvalidDescriptors,
+            PipCacheMissType.MissForProcessMetadata => PipExecutorCounter.CacheMissesForProcessMetadata,
+            PipCacheMissType.MissForProcessMetadataFromHistoricMetadata => PipExecutorCounter.CacheMissesForProcessMetadataFromHistoricMetadata,
+            PipCacheMissType.MissForProcessOutputContent => PipExecutorCounter.CacheMissesForProcessOutputContent,
+            PipCacheMissType.Hit => PipExecutorCounter.CacheHitsForProcessPipDescriptors,
+            PipCacheMissType.MissForProcessConfiguredUncacheable => PipExecutorCounter.CacheMissesForProcessConfiguredUncacheable,
+            _ => throw new ArgumentException($"Invalid or unknown {nameof(PipCacheMissType)}: {type}")
+        };
+
+        /// <summary>
+        /// Gets all valid cache miss types indicating cache misses.
+        /// </summary>
+        public static readonly IEnumerable<PipCacheMissType> AllCacheMisses = Enum.GetValues(typeof(PipCacheMissType))
+            .Cast<PipCacheMissType>()
+            .Where(e => e != PipCacheMissType.Invalid && e != PipCacheMissType.Hit)
+            .ToArray();
     }
 }

Public/Src/Engine/Scheduler/PipExecutor.cs

@@ -2222,8 +2222,7 @@ public static async Task<RunnableFromCacheResult> TryCheckProcessRunnableFromCac
             {
                 Kind = FingerprintComputationKind.CacheCheck,
                 PipId = cacheableProcess.Process.PipId,
-                StrongFingerprintComputations =
-                    CollectionUtilities.EmptyArray<ProcessStrongFingerprintComputationData>(),
+                StrongFingerprintComputations = CollectionUtilities.EmptyArray<ProcessStrongFingerprintComputationData>(),
             };
 
             var operationContext = processRunnable.OperationContext;
@@ -2269,7 +2268,8 @@ public static async Task<RunnableFromCacheResult> TryCheckProcessRunnableFromCac
                         Logger.Log.ScheduleProcessPipCacheMiss(
                             processRunnable.OperationContext,
                             cacheableProcess.Description,
-                            runnableFromCacheResult.Fingerprint.ToString());
+                            runnableFromCacheResult.Fingerprint.ToString(),
+                            pipCacheMiss.Value.CacheMissType.ToString());
 
                         processRunnable.Environment.State.ExecutionLog?.PipCacheMiss(pipCacheMiss.Value);
                     }
@@ -2336,9 +2336,9 @@ private static async Task<RunnableFromCacheResult> TryCheckProcessRunnableFromCa
             if (isWeakFingerprintAugmented && !traversedAugmentedWeakFingerprintSet.Add(weakFingerprint))
             {
                 Logger.Log.TwoPhaseCacheDescriptorDuplicatedAugmentedFingerprint(
-                                        operationContext,
-                                        processRunnable.Description,
-                                        weakFingerprint.ToString());
+                    operationContext,
+                    processRunnable.Description,
+                    weakFingerprint.ToString());
 
                 // The miss reasons might have been slightly different the first time (e.g. we could have failed because content couldn't be downloaded)
                 // but it is not worth storing the original reason and the extra complexity that would bring. The original reason for the miss was also
@@ -2395,7 +2395,7 @@ async Task<RunnableFromCacheResult> innerCheckRunnableFromCacheAsync()
                     refLocality = null;
                 }
                 else
-                {                  
+                {
 
                     // Chapter 1: Determine Strong Fingerprint
                     // First, we will evaluate a sequence of (path set, strong fingerprint) pairs.
@@ -2698,13 +2698,12 @@ await TryComputeStrongFingerprintBasedOnPriorObservedPathSetAsync(
                             PublishedEntryRef usableEntryRef = maybeUsableEntryRef.Value;
 
                             // The speed of Chapter2 is basically all just this call to GetContentHashList
-                            Possible<CacheEntry?> entryFetchResult =
-                                await cache.TryGetCacheEntryAsync(
-                                    cacheableProcess.Process,
-                                    weakFingerprint,
-                                    usableEntryRef.PathSetHash,
-                                    usableEntryRef.StrongFingerprint,
-                                    hints);
+                            Possible<CacheEntry?> entryFetchResult = await cache.TryGetCacheEntryAsync(
+                                cacheableProcess.Process,
+                                weakFingerprint,
+                                usableEntryRef.PathSetHash,
+                                usableEntryRef.StrongFingerprint,
+                                hints);
 
                             if (entryFetchResult.Succeeded)
                             {
@@ -2777,19 +2776,19 @@ await cache.TryGetCacheEntryAsync(
                     if (maybeUsableCacheEntry.HasValue)
                     {
                         cacheHitData = await TryConvertToRunnableFromCacheResultAsync(
-                         processRunnable,
-                         operationContext,
-                         environment,
-                         state,
-                         cacheableProcess,
-                         refLocality.Value,
-                         description,
-                         weakFingerprint,
-                         maybeUsableEntryRef.Value.PathSetHash,
-                         maybeUsableEntryRef.Value.StrongFingerprint,
-                         maybeUsableCacheEntry,
-                         maybePathSet,
-                         pipCacheMiss);
+                            processRunnable,
+                            operationContext,
+                            environment,
+                            state,
+                            cacheableProcess,
+                            refLocality.Value,
+                            description,
+                            weakFingerprint,
+                            maybeUsableEntryRef.Value.PathSetHash,
+                            maybeUsableEntryRef.Value.StrongFingerprint,
+                            maybeUsableCacheEntry,
+                            maybePathSet,
+                            pipCacheMiss);
                     }
                 }
 
@@ -5510,28 +5509,6 @@ private static FileRealizationMode GetFileRealizationMode(IPipExecutionEnvironme
                 : FileRealizationMode.Copy;
         }
 
-        /// <summary>
-        /// Returns an enumerable containing all mutually exclusive counters for different cache miss reasons
-        /// </summary>
-        public static IEnumerable<PipExecutorCounter> GetListOfCacheMissTypes()
-        {
-            // All mutually exclusive counters for cache miss reasons
-            // Note: frontier variants of the counters should not be included in this list
-            return new PipExecutorCounter[]
-            {
-                PipExecutorCounter.CacheMissesForDescriptorsDueToWeakFingerprints,
-                PipExecutorCounter.CacheMissesForDescriptorsDueToAugmentedWeakFingerprints,
-                PipExecutorCounter.CacheMissesForDescriptorsDueToStrongFingerprints,
-                PipExecutorCounter.CacheMissesForDescriptorsDueToArtificialMissOptions,
-                PipExecutorCounter.CacheMissesForCacheEntry,
-                PipExecutorCounter.CacheMissesDueToInvalidDescriptors,
-                PipExecutorCounter.CacheMissesForProcessMetadata,
-                PipExecutorCounter.CacheMissesForProcessMetadataFromHistoricMetadata,
-                PipExecutorCounter.CacheMissesForProcessOutputContent,
-                PipExecutorCounter.CacheMissesForProcessConfiguredUncacheable,
-            };
-        }
-
         /// <summary>
         /// Gets a PipFragmentRenderer for a WriteFile operation.
         /// </summary>

Public/Src/Engine/Scheduler/Scheduler.cs

@@ -2073,8 +2073,8 @@ public SchedulerPerformanceInfo LogStats(LoggingContext loggingContext, [AllowNu
             Logger.Log.CacheFingerprintHitSources(loggingContext, m_cacheIdHits);
 
             List<PipCachePerfInfo> cacheLookupPerfInfos = m_runnablePipPerformance.Values.Where(a => a.CacheLookupPerfInfo != null).Select(a => a.CacheLookupPerfInfo).ToList();
-            List<PipCachePerfInfo> cacheLookupPerfInfosForHits = cacheLookupPerfInfos.Where(a => a.CacheMissType == PipCacheMissType.Invalid).DefaultIfEmpty().ToList();
-            List<PipCachePerfInfo> cacheLookupPerfInfosForMisses = cacheLookupPerfInfos.Where(a => a.CacheMissType != PipCacheMissType.Invalid).DefaultIfEmpty().ToList();
+            List<PipCachePerfInfo> cacheLookupPerfInfosForHits = cacheLookupPerfInfos.Where(a => a.CacheMissType == PipCacheMissType.Hit).DefaultIfEmpty().ToList();
+            List<PipCachePerfInfo> cacheLookupPerfInfosForMisses = cacheLookupPerfInfos.Where(a => a.CacheMissType != PipCacheMissType.Hit).DefaultIfEmpty().ToList();
 
             PipExecutionCounters.AddToCounter(PipExecutorCounter.MaxCacheEntriesVisitedForHit, cacheLookupPerfInfosForHits.Max(a => a?.NumCacheEntriesVisited) ?? -1);
             PipExecutionCounters.AddToCounter(PipExecutorCounter.MinCacheEntriesVisitedForHit, cacheLookupPerfInfosForHits.Min(a => a?.NumCacheEntriesVisited) ?? -1);
@@ -2095,19 +2095,19 @@ public SchedulerPerformanceInfo LogStats(LoggingContext loggingContext, [AllowNu
             m_groupedPipCounters.LogAsPipCounters();
 
             // Verify counters for different types of cache misses sum to pips executed due to cache misses
-            IEnumerable<PipExecutorCounter> cacheMissTypes = PipExecutor.GetListOfCacheMissTypes();
             long cacheMissSum = 0;
             using (var pooledStringBuilder = Pools.GetStringBuilder()) {
                 var sb = pooledStringBuilder.Instance;
-                foreach (var missType in cacheMissTypes)
+                foreach (var missType in PipCacheMissTypeExtensions.AllCacheMisses)
                 {
-                    var counterValue = PipExecutionCounters.GetCounterValue(missType);
+                    var counter = missType.ToCounter();
+                    var counterValue = PipExecutionCounters.GetCounterValue(counter);
                     cacheMissSum += counterValue;
 
-                    var frontierPipCounterValue = PipExecutionCounters.GetCounterValue(missType.ToFrontierPipCacheMissCounter());
+                    var frontierPipCounterValue = PipExecutionCounters.GetCounterValue(counter.ToFrontierPipCacheMissCounter());
                     if (frontierPipCounterValue > counterValue)
                     {
-                        sb.Append($"{(sb.Length == 0 ? "" : ", ")}['{missType}' : {counterValue} != {frontierPipCounterValue}]");
+                        sb.Append($"{(sb.Length == 0 ? "" : ", ")}['{counter}' : {counterValue} != {frontierPipCounterValue}]");
                     }
                 }
 
@@ -4668,11 +4668,11 @@ private async Task<PipExecutionStep> ExecutePipStep(RunnablePip runnablePip)
                     {
                         // It's a cache miss, update the counters.
                         Contract.Assert(cacheResult.CacheMissType != PipCacheMissType.Invalid, "Must have valid cache miss reason");
-                        environment.Counters.IncrementCounter((PipExecutorCounter)cacheResult.CacheMissType);
+                        environment.Counters.IncrementCounter(cacheResult.CacheMissType.ToCounter());
 
                         if (pipRunTimeInfo.IsFrontierMissCandidate)
                         {
-                            environment.Counters.IncrementCounter(((PipExecutorCounter)cacheResult.CacheMissType).ToFrontierPipCacheMissCounter());
+                            environment.Counters.IncrementCounter(cacheResult.CacheMissType.ToCounter().ToFrontierPipCacheMissCounter());
                         }
 
                         if (cacheResult.CacheMissType == PipCacheMissType.MissForProcessMetadata

Public/Src/Engine/Scheduler/Tracing/Log.cs

@@ -245,8 +245,8 @@ internal abstract void SchedulePipOutputDeployedFromCache(
             EventLevel = Level.Verbose,
             Keywords = (int)Keywords.UserMessage,
             EventTask = (ushort)Tasks.Storage,
-            Message = "[{pipDescription}] Cache miss (fingerprint '{fingerprint}'): Process will be executed.")]
-        internal abstract void ScheduleProcessPipCacheMiss(LoggingContext loggingContext, string pipDescription, string fingerprint);
+            Message = "[{pipDescription}] Cache miss (fingerprint: '{fingerprint}', miss type: {missType}): Process will be executed.")]
+        internal abstract void ScheduleProcessPipCacheMiss(LoggingContext loggingContext, string pipDescription, string fingerprint, string missType);
 
         [GeneratedEvent(
             (ushort)LogEventId.ProcessPipProcessWeight,

Public/Src/Engine/UnitTests/Scheduler.IntegrationTest/ScheduleRunResult.cs

@@ -186,12 +186,10 @@ private void ValidateCacheMissTypesSumToTotal()
         {
             // All mutually exclusive counters for cache miss reasons
 
-            IEnumerable<PipExecutorCounter> cacheMissTypes = PipExecutor.GetListOfCacheMissTypes();
-
             long sum = 0;
-            foreach (var missType in cacheMissTypes)
+            foreach (var missType in PipCacheMissTypeExtensions.AllCacheMisses)
             {
-                sum += PipExecutorCounters.GetCounterValue(missType);
+                sum += PipExecutorCounters.GetCounterValue(missType.ToCounter());
             }
 
             XAssert.AreEqual(PipExecutorCounters.GetCounterValue(PipExecutorCounter.ProcessPipsExecutedDueToCacheMiss), sum);