Introduce ExecutionAttemptArguments (#1326)

Author: martintmk

bench/BenchmarkDotNet.Artifacts/results/Polly.Core.Benchmarks.MultipleStrategiesBenchmark-report-github.md

@@ -9,8 +9,8 @@ Job=MediumRun  Toolchain=InProcessEmitToolchain  IterationCount=15
 LaunchCount=2  WarmupCount=10  
 
 ```
-|                               Method |     Mean |     Error |    StdDev | Ratio |   Gen0 | Allocated | Alloc Ratio |
-|------------------------------------- |---------:|----------:|----------:|------:|-------:|----------:|------------:|
-|           ExecuteStrategyPipeline_V7 | 2.269 μs | 0.0136 μs | 0.0204 μs |  1.00 | 0.1106 |    2824 B |        1.00 |
-|           ExecuteStrategyPipeline_V8 | 1.861 μs | 0.0111 μs | 0.0155 μs |  0.82 |      - |      40 B |        0.01 |
-| ExecuteStrategyPipeline_Telemetry_V8 | 2.402 μs | 0.0104 μs | 0.0156 μs |  1.06 |      - |      40 B |        0.01 |
+|                               Method |     Mean |     Error |    StdDev | Ratio | RatioSD |   Gen0 | Allocated | Alloc Ratio |
+|------------------------------------- |---------:|----------:|----------:|------:|--------:|-------:|----------:|------------:|
+|           ExecuteStrategyPipeline_V7 | 2.220 μs | 0.0164 μs | 0.0236 μs |  1.00 |    0.00 | 0.1106 |    2824 B |        1.00 |
+|           ExecuteStrategyPipeline_V8 | 1.901 μs | 0.0089 μs | 0.0127 μs |  0.86 |    0.01 |      - |      40 B |        0.01 |
+| ExecuteStrategyPipeline_Telemetry_V8 | 2.947 μs | 0.0077 μs | 0.0115 μs |  1.33 |    0.02 |      - |      40 B |        0.01 |

src/Polly.Core/Hedging/Controller/HedgingController.cs

@@ -1,4 +1,5 @@
 using Polly.Hedging.Controller;
+using Polly.Telemetry;
 
 namespace Polly.Hedging.Utils;
 
@@ -10,6 +11,7 @@ internal sealed class HedgingController<T>
     private int _rentedExecutions;
 
     public HedgingController(
+        ResilienceStrategyTelemetry telemetry,
         TimeProvider provider,
         HedgingHandler<T> handler,
         int maxAttempts)
@@ -20,7 +22,7 @@ public HedgingController(
         _executionPool = new ObjectPool<TaskExecution<T>>(() =>
         {
             Interlocked.Increment(ref _rentedExecutions);
-            return new TaskExecution<T>(handler, pool);
+            return new TaskExecution<T>(handler, pool, provider, telemetry);
         },
         _ =>
         {

src/Polly.Core/Hedging/Controller/TaskExecution.cs

@@ -1,4 +1,6 @@
+using System;
 using Polly.Hedging.Utils;
+using Polly.Telemetry;
 
 namespace Polly.Hedging.Controller;
 
@@ -21,15 +23,21 @@ internal sealed class TaskExecution<T>
 {
     private readonly ResilienceContext _cachedContext = ResilienceContext.Get();
     private readonly CancellationTokenSourcePool _cancellationTokenSourcePool;
+    private readonly TimeProvider _timeProvider;
+    private readonly ResilienceStrategyTelemetry _telemetry;
     private readonly HedgingHandler<T> _handler;
     private CancellationTokenSource? _cancellationSource;
     private CancellationTokenRegistration? _cancellationRegistration;
     private ResilienceContext? _activeContext;
+    private long _startExecutionTimestamp;
+    private long _stopExecutionTimestamp;
 
-    public TaskExecution(HedgingHandler<T> handler, CancellationTokenSourcePool cancellationTokenSourcePool)
+    public TaskExecution(HedgingHandler<T> handler, CancellationTokenSourcePool cancellationTokenSourcePool, TimeProvider timeProvider, ResilienceStrategyTelemetry telemetry)
     {
         _handler = handler;
         _cancellationTokenSourcePool = cancellationTokenSourcePool;
+        _timeProvider = timeProvider;
+        _telemetry = telemetry;
     }
 
     /// <summary>
@@ -56,6 +64,10 @@ public TaskExecution(HedgingHandler<T> handler, CancellationTokenSourcePool canc
 
     public Action<TaskExecution<T>>? OnReset { get; set; }
 
+    public TimeSpan ExecutionTime => _timeProvider.GetElapsedTime(_startExecutionTimestamp, _stopExecutionTimestamp);
+
+    public int Attempt { get; private set; }
+
     public void AcceptOutcome()
     {
         if (ExecutionTaskSafe?.IsCompleted == true)
@@ -83,8 +95,10 @@ public async ValueTask<bool> InitializeAsync<TResult, TState>(
         TState state,
         int attempt)
     {
+        Attempt = attempt;
         Type = type;
         _cancellationSource = _cancellationTokenSourcePool.Get(System.Threading.Timeout.InfiniteTimeSpan);
+        _startExecutionTimestamp = _timeProvider.GetTimestamp();
         Properties.Replace(snapshot.OriginalProperties);
 
         if (snapshot.OriginalCancellationToken.CanBeCanceled)
@@ -109,6 +123,7 @@ public async ValueTask<bool> InitializeAsync<TResult, TState>(
             }
             catch (Exception e)
             {
+                _stopExecutionTimestamp = _timeProvider.GetTimestamp();
                 ExecutionTaskSafe = ExecuteCreateActionException<TResult>(e);
                 return true;
             }
@@ -164,9 +179,12 @@ public async ValueTask ResetAsync()
         IsHandled = false;
         Properties.Clear();
         OnReset = null;
+        Attempt = 0;
         _activeContext = null;
         _cachedContext.Reset();
         _cancellationSource = null!;
+        _startExecutionTimestamp = 0;
+        _stopExecutionTimestamp = 0;
     }
 
     private async Task ExecuteSecondaryActionAsync<TResult>(Func<ValueTask<Outcome<TResult>>> action)
@@ -182,6 +200,7 @@ private async Task ExecuteSecondaryActionAsync<TResult>(Func<ValueTask<Outcome<T
             outcome = new Outcome<TResult>(e);
         }
 
+        _stopExecutionTimestamp = _timeProvider.GetTimestamp();
         await UpdateOutcomeAsync(outcome).ConfigureAwait(Context.ContinueOnCapturedContext);
     }
 
@@ -203,6 +222,7 @@ private async Task ExecutePrimaryActionAsync<TResult, TState>(Func<ResilienceCon
             outcome = new Outcome<TResult>(e);
         }
 
+        _stopExecutionTimestamp = _timeProvider.GetTimestamp();
         await UpdateOutcomeAsync(outcome).ConfigureAwait(Context.ContinueOnCapturedContext);
     }
 
@@ -211,6 +231,7 @@ private async Task UpdateOutcomeAsync<TResult>(Outcome<TResult> outcome)
         var args = new OutcomeArguments<TResult, HedgingPredicateArguments>(Context, outcome, new HedgingPredicateArguments());
         Outcome = outcome.AsOutcome();
         IsHandled = await _handler.ShouldHandle.HandleAsync(args).ConfigureAwait(Context.ContinueOnCapturedContext);
+        TelemetryUtil.ReportExecutionAttempt(_telemetry, Context, outcome, Attempt, ExecutionTime, IsHandled);
     }
 
     private void PrepareContext(ref ContextSnapshot snapshot)

src/Polly.Core/Hedging/HedgingResilienceStrategy.cs

@@ -7,6 +7,7 @@ namespace Polly.Hedging;
 
 internal sealed class HedgingResilienceStrategy<T> : ResilienceStrategy
 {
+    private readonly TimeProvider _timeProvider;
     private readonly ResilienceStrategyTelemetry _telemetry;
     private readonly HedgingController<T> _controller;
 
@@ -22,11 +23,12 @@ public HedgingResilienceStrategy(
         HedgingDelay = hedgingDelay;
         MaxHedgedAttempts = maxHedgedAttempts;
         HedgingDelayGenerator = hedgingDelayGenerator;
+        _timeProvider = timeProvider;
         HedgingHandler = hedgingHandler;
         OnHedging = onHedging;
 
         _telemetry = telemetry;
-        _controller = new HedgingController<T>(timeProvider, HedgingHandler, maxHedgedAttempts);
+        _controller = new HedgingController<T>(telemetry, timeProvider, HedgingHandler, maxHedgedAttempts);
     }
 
     public TimeSpan HedgingDelay { get; }
@@ -75,7 +77,7 @@ private async ValueTask<Outcome<TResult>> ExecuteCoreAsync<TResult, TState>(
             attempt++;
             var continueOnCapturedContext = context.ContinueOnCapturedContext;
             var cancellationToken = context.CancellationToken;
-
+            var start = _timeProvider.GetTimestamp();
             if (cancellationToken.IsCancellationRequested)
             {
                 return new Outcome<TResult>(new OperationCanceledException(cancellationToken).TrySetStackTrace());
@@ -97,7 +99,7 @@ private async ValueTask<Outcome<TResult>> ExecuteCoreAsync<TResult, TState>(
                 await HandleOnHedgingAsync(
                     context,
                     new Outcome<TResult>(default(TResult)),
-                    new OnHedgingArguments(attempt, HasOutcome: false)).ConfigureAwait(context.ContinueOnCapturedContext);
+                    new OnHedgingArguments(attempt, HasOutcome: false, ExecutionTime: delay)).ConfigureAwait(context.ContinueOnCapturedContext);
                 continue;
             }
 
@@ -109,10 +111,11 @@ await HandleOnHedgingAsync(
                 return outcome;
             }
 
+            var executionTime = _timeProvider.GetElapsedTime(start);
             await HandleOnHedgingAsync(
                 context,
                 outcome,
-                new OnHedgingArguments(attempt, HasOutcome: true)).ConfigureAwait(context.ContinueOnCapturedContext);
+                new OnHedgingArguments(attempt, HasOutcome: true, executionTime)).ConfigureAwait(context.ContinueOnCapturedContext);
         }
     }
 

src/Polly.Core/Hedging/OnHedgingArguments.cs

@@ -8,4 +8,8 @@ namespace Polly.Hedging;
 /// Determines whether the outcome is available before loading the next hedged task.
 /// No outcome indicates that the previous action did not finish within the hedging delay.
 /// </param>
-public record OnHedgingArguments(int Attempt, bool HasOutcome);
+/// <param name="ExecutionTime">
+/// The execution time of hedging attempt or the hedging delay
+/// in case the attempt was not finished in time.
+/// </param>
+public record OnHedgingArguments(int Attempt, bool HasOutcome, TimeSpan ExecutionTime);

src/Polly.Core/Retry/OnRetryArguments.cs

@@ -5,4 +5,5 @@ namespace Polly.Retry;
 /// </summary>
 /// <param name="Attempt">The zero-based attempt number. The first attempt is 0, the second attempt is 1, and so on.</param>
 /// <param name="RetryDelay">The delay before the next retry.</param>
-public record OnRetryArguments(int Attempt, TimeSpan RetryDelay);
+/// <param name="ExecutionTime">The execution time of this attempt.</param>
+public record OnRetryArguments(int Attempt, TimeSpan RetryDelay, TimeSpan ExecutionTime);

src/Polly.Core/Retry/RetryResilienceStrategy.cs

@@ -57,10 +57,15 @@ protected internal override async ValueTask<Outcome<TResult>> ExecuteCoreAsync<T
 
         while (true)
         {
+            var startTimestamp = _timeProvider.GetTimestamp();
             var outcome = await ExecuteCallbackSafeAsync(callback, context, state).ConfigureAwait(context.ContinueOnCapturedContext);
             var shouldRetryArgs = new OutcomeArguments<TResult, RetryPredicateArguments>(context, outcome, new RetryPredicateArguments(attempt));
+            var handle = await ShouldRetry.HandleAsync(shouldRetryArgs).ConfigureAwait(context.ContinueOnCapturedContext);
+            var executionTime = _timeProvider.GetElapsedTime(startTimestamp);
 
-            if (context.CancellationToken.IsCancellationRequested || IsLastAttempt(attempt) || !await ShouldRetry.HandleAsync(shouldRetryArgs).ConfigureAwait(context.ContinueOnCapturedContext))
+            TelemetryUtil.ReportExecutionAttempt(_telemetry, context, outcome, attempt, executionTime, handle);
+
+            if (context.CancellationToken.IsCancellationRequested || IsLastAttempt(attempt) || !handle)
             {
                 return outcome;
             }
@@ -76,7 +81,7 @@ protected internal override async ValueTask<Outcome<TResult>> ExecuteCoreAsync<T
                 }
             }
 
-            var onRetryArgs = new OutcomeArguments<TResult, OnRetryArguments>(context, outcome, new OnRetryArguments(attempt, delay));
+            var onRetryArgs = new OutcomeArguments<TResult, OnRetryArguments>(context, outcome, new OnRetryArguments(attempt, delay, executionTime));
             _telemetry.Report(RetryConstants.OnRetryEvent, onRetryArgs);
 
             if (OnRetry is not null)

src/Polly.Core/Telemetry/ExecutionAttemptArguments.Pool.cs

@@ -0,0 +1,22 @@
+namespace Polly.Telemetry;
+
+public partial class ExecutionAttemptArguments
+{
+    private static readonly ObjectPool<ExecutionAttemptArguments> Pool = new(() => new ExecutionAttemptArguments(), args =>
+    {
+        args.ExecutionTime = TimeSpan.Zero;
+        args.Attempt = 0;
+        args.Handled = false;
+    });
+
+    internal static ExecutionAttemptArguments Get(int attempt, TimeSpan executionTime, bool handled)
+    {
+        var args = Pool.Get();
+        args.Attempt = attempt;
+        args.ExecutionTime = executionTime;
+        args.Handled = handled;
+        return args;
+    }
+
+    internal static void Return(ExecutionAttemptArguments args) => Pool.Return(args);
+}

src/Polly.Core/Telemetry/ExecutionAttemptArguments.cs

@@ -0,0 +1,39 @@
+namespace Polly.Telemetry;
+
+/// <summary>
+/// Arguments that encapsulate the execution attempt for retries or hedging.
+/// </summary>
+public partial class ExecutionAttemptArguments
+{
+    /// <summary>
+    /// Initializes a new instance of the <see cref="ExecutionAttemptArguments"/> class.
+    /// </summary>
+    /// <param name="attempt">The execution attempt.</param>
+    /// <param name="executionTime">The execution time.</param>
+    /// <param name="handled">Determines whether the attempt was handled by the strategy.</param>
+    public ExecutionAttemptArguments(int attempt, TimeSpan executionTime, bool handled)
+    {
+        Attempt = attempt;
+        ExecutionTime = executionTime;
+        Handled = handled;
+    }
+
+    private ExecutionAttemptArguments()
+    {
+    }
+
+    /// <summary>
+    /// Gets the attempt number.
+    /// </summary>
+    public int Attempt { get; private set; }
+
+    /// <summary>
+    /// Gets the execution time of the attempt.
+    /// </summary>
+    public TimeSpan ExecutionTime { get; private set; }
+
+    /// <summary>
+    /// Gets a value indicating whether the outcome was handled by retry or hedging strategy.
+    /// </summary>
+    public bool Handled { get; private set; }
+}

src/Polly.Core/Telemetry/ResilienceStrategyTelemetry.cs

@@ -18,6 +18,11 @@ internal ResilienceStrategyTelemetry(ResilienceTelemetrySource source, Diagnosti
 
     internal ResilienceTelemetrySource TelemetrySource { get; }
 
+    /// <summary>
+    /// Gets a value indicating whether telemetry is enabled.
+    /// </summary>
+    public bool IsEnabled => DiagnosticSource is not null;
+
     /// <summary>
     /// Reports an event that occurred in a resilience strategy.
     /// </summary>
@@ -31,7 +36,7 @@ public void Report<TArgs>(string eventName, ResilienceContext context, TArgs arg
         Guard.NotNull(eventName);
         Guard.NotNull(context);
 
-        context.AddResilienceEvent(new ResilienceEvent(eventName));
+        AddResilienceEvent(eventName, context, args);
 
         if (DiagnosticSource is null || !DiagnosticSource.IsEnabled(eventName))
         {
@@ -57,7 +62,7 @@ public void Report<TArgs, TResult>(string eventName, OutcomeArguments<TResult, T
     {
         Guard.NotNull(eventName);
 
-        args.Context.AddResilienceEvent(new ResilienceEvent(eventName));
+        AddResilienceEvent(eventName, args.Context, args.Arguments);
 
         if (DiagnosticSource is null || !DiagnosticSource.IsEnabled(eventName))
         {
@@ -70,5 +75,17 @@ public void Report<TArgs, TResult>(string eventName, OutcomeArguments<TResult, T
 
         TelemetryEventArguments.Return(telemetryArgs);
     }
+
+    private static void AddResilienceEvent<TArgs>(string eventName, ResilienceContext context, TArgs args)
+    {
+        // ExecutionAttemptArguments is not reported as resilience event because that information is already contained
+        // in OnHedgingArguments and OnRetryArguments
+        if (args is ExecutionAttemptArguments attempt)
+        {
+            return;
+        }
+
+        context.AddResilienceEvent(new ResilienceEvent(eventName));
+    }
 }
 

src/Polly.Core/Telemetry/TelemetryUtil.cs

@@ -4,6 +4,8 @@ internal static class TelemetryUtil
 {
     internal const string PollyDiagnosticSource = "Polly";
 
+    internal const string ExecutionAttempt = "ExecutionAttempt";
+
     internal static readonly ResiliencePropertyKey<string> StrategyKey = new("Polly.StrategyKey");
 
     public static ResilienceStrategyTelemetry CreateTelemetry(
@@ -17,4 +19,22 @@ public static ResilienceStrategyTelemetry CreateTelemetry(
 
         return new ResilienceStrategyTelemetry(telemetrySource, diagnosticSource);
     }
+
+    public static void ReportExecutionAttempt<TResult>(
+        ResilienceStrategyTelemetry telemetry,
+        ResilienceContext context,
+        Outcome<TResult> outcome,
+        int attempt,
+        TimeSpan executionTime,
+        bool handled)
+    {
+        if (!telemetry.IsEnabled)
+        {
+            return;
+        }
+
+        var attemptArgs = ExecutionAttemptArguments.Get(attempt, executionTime, handled);
+        telemetry.Report<ExecutionAttemptArguments, TResult>(ExecutionAttempt, new(context, outcome, attemptArgs));
+        ExecutionAttemptArguments.Return(attemptArgs);
+    }
 }

src/Polly.Core/Utils/TimeProvider.cs

@@ -1,3 +1,5 @@
+using System.Diagnostics.CodeAnalysis;
+
 namespace Polly.Utils;
 
 #pragma warning disable S3872 // Parameter names should not duplicate the names of their methods
@@ -6,6 +8,7 @@ namespace Polly.Utils;
 /// TEMPORARY ONLY, to be replaced with System.TimeProvider - https://github.com/dotnet/runtime/issues/36617 later.
 /// </summary>
 /// <remarks>We trimmed some of the API that's not relevant for us too.</remarks>
+[ExcludeFromCodeCoverage]
 internal abstract class TimeProvider
 {
     private readonly double _tickFrequency;
@@ -22,7 +25,7 @@ protected TimeProvider(long timestampFrequency)
 
     public long TimestampFrequency { get; }
 
-    public abstract long GetTimestamp();
+    public virtual long GetTimestamp() => Environment.TickCount;
 
     public TimeSpan GetElapsedTime(long startingTimestamp, long endingTimestamp) => new((long)((endingTimestamp - startingTimestamp) * _tickFrequency));