Bound repeated failure and eviction telemetry

GVFS/GVFS.Common/CircuitBreakerOpenException.cs

@@ -0,0 +1,10 @@
+namespace GVFS.Common
+{
+    public class CircuitBreakerOpenException : RetryableException
+    {
+        public CircuitBreakerOpenException()
+            : base("Circuit breaker is open - too many consecutive failures. Fast-failing to prevent resource exhaustion.")
+        {
+        }
+    }
+}

GVFS/GVFS.Common/Git/GVFSGitObjects.cs

@@ -67,13 +67,15 @@ public enum BlobHydrationFailureCategory
         /// </summary>
         internal class DownloadAttemptResult
         {
-            public DownloadAttemptResult(DownloadAndSaveObjectResult result, HttpStatusCode? httpStatusCode)
+            public DownloadAttemptResult(DownloadAndSaveObjectResult result, HttpStatusCode? httpStatusCode, bool circuitBreakerRejected = false)
             {
                 this.Result = result;
                 this.HttpStatusCode = httpStatusCode;
+                this.CircuitBreakerRejected = circuitBreakerRejected;
             }
 
             public DownloadAndSaveObjectResult Result { get; }
+            public bool CircuitBreakerRejected { get; }
 
             // The HTTP status of the last download attempt, or null when no HTTP response was
             // received (for example an exhausted retry that ended in an exception).
@@ -87,7 +89,8 @@ public virtual bool TryCopyBlobContentStream(
             CancellationToken cancellationToken,
             RequestSource requestSource,
             Action<Stream, long> writeAction,
-            out BlobHydrationFailureCategory failureCategory)
+            out BlobHydrationFailureCategory failureCategory,
+            EventMetadata failureMetadata = null)
         {
             // Short-circuit a malformed SHA (for example a corrupt placeholder's all-NUL
             // content-id) before the retry loop. GitRepo already rejects it as a clean miss,
@@ -117,8 +120,9 @@ public virtual bool TryCopyBlobContentStream(
             DownloadAttemptResult lastDownloadResult = null;
             bool downloadSucceededButCopyFailed = false;
             BlobHydrationFailureCategory capturedCategory = BlobHydrationFailureCategory.None;
+            TelemetryFailureCategory? capturedTelemetryCategory = null;
 
-            RetryWrapper<bool> retrier = new RetryWrapper<bool>(this.GitObjectRequestor.RetryConfig.MaxAttempts, cancellationToken);
+            RetryWrapper<bool> retrier = new RetryWrapper<bool>(this.GitObjectRequestor.RetryConfig.MaxAttempts, cancellationToken, tracer: this.Tracer);
             retrier.OnFailure +=
                 errorArgs =>
                 {
@@ -165,6 +169,17 @@ public virtual bool TryCopyBlobContentStream(
 
                     capturedCategory = category;
                     metadata.Add(nameof(BlobHydrationFailureCategory), category.ToString());
+                    capturedTelemetryCategory =
+                        errorArgs.Error is CircuitBreakerOpenException || (errorArgs.Error == null && lastDownloadResult?.CircuitBreakerRejected == true)
+                        ? TelemetryFailureCategory.CircuitBreakerOpen
+                        : (category == BlobHydrationFailureCategory.NetworkUnavailable ? TelemetryFailureCategory.NetworkUnavailable : null);
+                    if (capturedTelemetryCategory.HasValue)
+                    {
+                        metadata.SetTelemetryAggregation(
+                            nameof(this.TryCopyBlobContentStream),
+                            capturedTelemetryCategory.Value,
+                            errorArgs.Error is CircuitBreakerOpenException ? "Rejected" : "Failed");
+                    }
 
                     // Surface the HTTP status of the last download attempt so telemetry can tell a
                     // genuine auth failure (401/400/302) apart from a transient one (408/5xx/503),
@@ -222,6 +237,11 @@ public virtual bool TryCopyBlobContentStream(
                 });
 
             failureCategory = invokeResult.Result ? BlobHydrationFailureCategory.None : capturedCategory;
+            if (!invokeResult.Result && capturedTelemetryCategory.HasValue && failureMetadata != null)
+            {
+                failureMetadata.SetTelemetryAggregation(nameof(this.TryCopyBlobContentStream), capturedTelemetryCategory.Value, "Failed");
+            }
+
             return invokeResult.Result;
         }
 
@@ -385,7 +405,7 @@ private DownloadAttemptResult DoDownloadAndSaveObject(
                 }
             }
 
-            return new DownloadAttemptResult(DownloadAndSaveObjectResult.Error, httpStatusCode);
+            return new DownloadAttemptResult(DownloadAndSaveObjectResult.Error, httpStatusCode, output.Error is CircuitBreakerOpenException);
         }
     }
 }

GVFS/GVFS.Common/Git/GitObjects.cs

@@ -70,6 +70,7 @@ public virtual bool TryDownloadCommit(string commitSha)
                     EventMetadata metadata = CreateEventMetadata(eArgs.Error);
                     metadata.Add("Operation", "DownloadAndSaveObjects");
                     metadata.Add("WillRetry", eArgs.WillRetry);
+                    eArgs.AddTelemetryMetadata(metadata, "DownloadAndSaveObjects");
 
                     if (eArgs.WillRetry)
                     {

GVFS/GVFS.Common/Http/ConfigHttpRequestor.cs

@@ -41,7 +41,7 @@ public bool TryQueryGVFSConfig(bool logErrors, out ServerGVFSConfig serverGVFSCo
             }
 
             long requestId = HttpRequestor.GetNewRequestId();
-            RetryWrapper<ServerGVFSConfig> retrier = new RetryWrapper<ServerGVFSConfig>(this.RetryConfig.MaxAttempts, CancellationToken.None);
+            RetryWrapper<ServerGVFSConfig> retrier = new RetryWrapper<ServerGVFSConfig>(this.RetryConfig.MaxAttempts, CancellationToken.None, tracer: logErrors ? this.Tracer : null);
 
             if (logErrors)
             {

GVFS/GVFS.Common/Http/GitObjectsHttpRequestor.cs

@@ -58,7 +58,8 @@ public virtual List<GitObjectSize> QueryForFileSizes(IEnumerable<string> objectI
 
             RetryWrapper<List<GitObjectSize>> retrier = new RetryWrapper<List<GitObjectSize>>(
                 this.RetryConfig.MaxAttempts + (hasEndpointOverride && !useOrigin ? 2 : 0),
-                cancellationToken);
+                cancellationToken,
+                tracer: this.Tracer);
             retrier.OnFailure += RetryWrapper<List<GitObjectSize>>.StandardErrorHandler(this.Tracer, requestId, "QueryFileSizes");
 
             RetryWrapper<List<GitObjectSize>>.InvocationResult requestTask = retrier.Invoke(
@@ -161,7 +162,7 @@ public virtual GitRefs QueryInfoRefs(string branch)
                 return null;
             }
 
-            RetryWrapper<GitRefs> retrier = new RetryWrapper<GitRefs>(this.RetryConfig.MaxAttempts, CancellationToken.None);
+            RetryWrapper<GitRefs> retrier = new RetryWrapper<GitRefs>(this.RetryConfig.MaxAttempts, CancellationToken.None, tracer: this.Tracer);
             retrier.OnFailure += RetryWrapper<GitRefs>.StandardErrorHandler(this.Tracer, requestId, "QueryInfoRefs");
 
             RetryWrapper<GitRefs>.InvocationResult output = retrier.Invoke(
@@ -362,7 +363,8 @@ public virtual RetryWrapper<GitObjectTaskResult>.InvocationResult TrySendProtoco
 
             RetryWrapper<GitObjectTaskResult> retrier = new RetryWrapper<GitObjectTaskResult>(
                 (retryOnFailure ? this.RetryConfig.MaxAttempts : 1) + (hasFallbackEndPoint ? 1 : 0),
-                cancellationToken);
+                cancellationToken,
+                tracer: this.Tracer);
             if (onFailure != null)
             {
                 retrier.OnFailure += onFailure;

GVFS/GVFS.Common/MissingTreeTracker.cs

@@ -45,11 +45,14 @@ public MissingTreeTracker(ITracer tracer, int treeCapacity)
         /// </summary>
         public void AddMissingRootTree(string treeSha, string commitSha)
         {
+            EvictionTelemetry telemetry = default;
             lock (this.syncLock)
             {
                 this.EnsureCommitTracked(commitSha);
-                this.AddTreeToCommit(treeSha, commitSha);
+                this.AddTreeToCommit(treeSha, commitSha, ref telemetry);
             }
+
+            this.TraceEvictions(telemetry);
         }
 
         /// <summary>
@@ -58,6 +61,7 @@ public void AddMissingRootTree(string treeSha, string commitSha)
         /// </summary>
         public void AddMissingSubTrees(string parentTreeSha, string[] subTreeShas)
         {
+            EvictionTelemetry telemetry = default;
             lock (this.syncLock)
             {
                 if (!this.commitsByTree.TryGetValue(parentTreeSha, out var commits))
@@ -78,10 +82,12 @@ public void AddMissingSubTrees(string parentTreeSha, string[] subTreeShas)
                         }
                         /* Ensure we don't evict this commit while trying to add a tree to it. */
                         this.MarkCommitAsUsed(commitSha); 
-                        this.AddTreeToCommit(subTreeSha, commitSha);
+                        this.AddTreeToCommit(subTreeSha, commitSha, ref telemetry);
                     }
                 }
             }
+
+            this.TraceEvictions(telemetry);
         }
 
         /// <summary>
@@ -167,15 +173,15 @@ private void EnsureCommitTracked(string commitSha)
             }
         }
 
-        private void AddTreeToCommit(string treeSha, string commitSha)
+        private void AddTreeToCommit(string treeSha, string commitSha, ref EvictionTelemetry telemetry)
         {
             if (!this.commitsByTree.ContainsKey(treeSha))
             {
                 // Evict LRU commits until there is room for the new tree
                 while (this.commitsByTree.Count >= this.treeCapacity)
                 {
                     // If evict fails it means we only have one commit left.
-                    if (!this.EvictLruCommit())
+                    if (!this.EvictLruCommit(ref telemetry))
                     {
                         break;
                     }
@@ -198,7 +204,7 @@ private void MarkCommitAsUsed(string commitSha)
             }
         }
 
-        private bool EvictLruCommit()
+        private bool EvictLruCommit(ref EvictionTelemetry telemetry)
         {
             var last = this.commitOrder.Last;
             if (last != null && last.Value != this.commitOrder.First.Value)
@@ -207,25 +213,66 @@ private bool EvictLruCommit()
                 var treeCountBefore = this.commitsByTree.Count;
                 this.RemoveCommitNoCache(lruCommit);
 
-                EventMetadata metadata = new EventMetadata();
-                metadata.Add("Area", EtwArea);
-                metadata.Add("EvictedCommit", lruCommit);
-                metadata.Add("TreeCountBefore", treeCountBefore);
-                metadata.Add("TreeCountAfter", this.commitsByTree.Count);
-                this.tracer.RelatedEvent(EventLevel.Informational, nameof(this.EvictLruCommit), metadata, Keywords.Telemetry);
+                if (telemetry.SuccessCount++ == 0)
+                {
+                    telemetry.EvictedCommit = lruCommit;
+                    telemetry.TreeCountBefore = treeCountBefore;
+                    telemetry.TreeCountAfter = this.commitsByTree.Count;
+                }
 
                 return true;
             }
 
-            EventMetadata warnMetadata = new EventMetadata();
-            warnMetadata.Add("Area", EtwArea);
-            warnMetadata.Add("TreeCount", this.commitsByTree.Count);
-            warnMetadata.Add("CommitCount", this.commitNodes.Count);
-            this.tracer.RelatedEvent(EventLevel.Warning, $"{nameof(this.EvictLruCommit)}CouldNotEvict", warnMetadata, Keywords.Telemetry);
+            if (telemetry.FailureCount++ == 0)
+            {
+                telemetry.FailedTreeCount = this.commitsByTree.Count;
+                telemetry.FailedCommitCount = this.commitNodes.Count;
+            }
 
             return false;
         }
 
+        private void TraceEvictions(EvictionTelemetry telemetry)
+        {
+            if (telemetry.SuccessCount > 0)
+            {
+                EventMetadata metadata = new EventMetadata
+                {
+                    { "Area", EtwArea },
+                    { "EvictedCommit", telemetry.EvictedCommit },
+                    { "TreeCountBefore", telemetry.TreeCountBefore },
+                    { "TreeCountAfter", telemetry.TreeCountAfter },
+                    { "EvictionCount", telemetry.SuccessCount },
+                };
+                metadata.SetTelemetryAggregation(nameof(this.EvictLruCommit), TelemetryFailureCategory.None, "Succeeded", telemetry.SuccessCount);
+                this.tracer.RelatedEvent(EventLevel.Informational, nameof(this.EvictLruCommit), metadata, Keywords.Telemetry);
+            }
+
+            if (telemetry.FailureCount > 0)
+            {
+                EventMetadata metadata = new EventMetadata
+                {
+                    { "Area", EtwArea },
+                    { "TreeCount", telemetry.FailedTreeCount },
+                    { "CommitCount", telemetry.FailedCommitCount },
+                    { "CouldNotEvictCount", telemetry.FailureCount },
+                };
+                metadata.SetTelemetryAggregation(nameof(this.EvictLruCommit), TelemetryFailureCategory.EvictionUnavailable, "CouldNotEvict", telemetry.FailureCount);
+                this.tracer.RelatedEvent(EventLevel.Warning, $"{nameof(this.EvictLruCommit)}CouldNotEvict", metadata, Keywords.Telemetry);
+            }
+        }
+
+        private struct EvictionTelemetry
+        {
+            public long SuccessCount;
+            public long FailureCount;
+            public string EvictedCommit;
+            public int TreeCountBefore;
+            public int TreeCountAfter;
+            public int FailedTreeCount;
+            public int FailedCommitCount;
+        }
+
         /// <summary>
         /// Removes a commit without cascading tree removal to other commits.
         /// Used during LRU eviction: the trees are still missing, so other commits

GVFS/GVFS.Common/RetryCircuitBreaker.cs

@@ -1,5 +1,6 @@
 using System;
 using System.Threading;
+using GVFS.Common.Tracing;
 
 namespace GVFS.Common
 {
@@ -18,6 +19,7 @@ public static class RetryCircuitBreaker
         private static int cooldownMs = DefaultCooldownMs;
         private static int consecutiveFailures = 0;
         private static long circuitOpenedAtUtcTicks = 0;
+        private static int observedState = -1;
 
         public static bool IsOpen
         {
@@ -49,6 +51,45 @@ public static void RecordFailure()
             }
         }
 
+        internal static void TraceState(ITracer tracer, bool isOpen, string trigger)
+        {
+            if (tracer == null)
+            {
+                return;
+            }
+
+            DateTime observedAtUtc = DateTime.UtcNow;
+            int state = isOpen ? 1 : 0;
+            if (!isOpen && ConsecutiveFailures >= failureThreshold)
+            {
+                long openedAt = Volatile.Read(ref circuitOpenedAtUtcTicks);
+                if (openedAt == 0 || observedAtUtc.Ticks - openedAt < TimeSpan.FromMilliseconds(cooldownMs).Ticks)
+                {
+                    return;
+                }
+
+                state = 2;
+            }
+
+            int previousState = Interlocked.Exchange(ref observedState, state);
+            if (previousState == state)
+            {
+                return;
+            }
+
+            string[] states = { "Accepting", "Rejecting", "CooldownElapsed" };
+            string previousStateName = previousState < 0 ? "Unknown" : states[previousState];
+            EventMetadata metadata = new EventMetadata
+            {
+                { "PreviousState", previousStateName },
+                { "State", states[state] },
+                { "Trigger", trigger },
+                { "ObservedAtUtc", observedAtUtc.ToString("O") },
+            };
+            metadata.SetTelemetryAggregation(nameof(RetryCircuitBreaker), TelemetryFailureCategory.BreakerState, states[state], previousState: previousStateName);
+            tracer.RelatedEvent(EventLevel.Informational, "RetryCircuitBreakerState", metadata, Keywords.Telemetry);
+        }
+
         /// <summary>
         /// Resets the circuit breaker to its initial state. Intended for testing.
         /// </summary>
@@ -58,6 +99,7 @@ public static void Reset()
             Volatile.Write(ref circuitOpenedAtUtcTicks, 0);
             Volatile.Write(ref failureThreshold, DefaultFailureThreshold);
             Volatile.Write(ref cooldownMs, DefaultCooldownMs);
+            Volatile.Write(ref observedState, -1);
         }
 
         /// <summary>