Add unit to execution time in telemetry events (#2069)

- Add unit to execution time in telemetry event message templates. - Use constants to reduce repetitive message format fragments. - Update documentation.
martincostello · Apr 22, 2024 · b89ce23 · b89ce23
1 parent 1393901
commit b89ce23
Show file tree

Hide file tree

Showing 5 changed files with 62 additions and 55 deletions.
diff --git a/docs/advanced/telemetry.md b/docs/advanced/telemetry.md
@@ -77,12 +77,12 @@ var serviceCollection = new ServiceCollection()
 
 The metrics are emitted under the `Polly` meter name. The subsequent sections provide insights into the metrics produced by Polly. Please note that any custom enriched tags are not depicted in the following tables.
 
-Every telemetry event has the following tags:
+Every telemetry event has the following optional tags:
 
-- `pipeline.name`: Optional, comes from `ResiliencePipelineBuilder.Name`.
-- `pipeline.instance`: Optional, comes from `ResiliencePipelineBuilder.InstanceName`.
-- `strategy.name`: Optional, comes from `RetryStrategyOptions.Name`.
-- `operation.key`: Optional, comes from `ResilienceContext.OperationKey`.
+- `pipeline.name`: comes from `ResiliencePipelineBuilder.Name`.
+- `pipeline.instance`: comes from `ResiliencePipelineBuilder.InstanceName`.
+- `strategy.name`: comes from `RetryStrategyOptions.Name`.
+- `operation.key`: comes from `ResilienceContext.OperationKey`.
 
 The sample below demonstrates how to assign these tags:
 
@@ -126,15 +126,15 @@ These values are subsequently reflected in the following metering instruments ex
 
 Tags:
 
-|Name|Description|
-|---| ---|
-|`event.name`| The name of the emitted event.|
-|`event.severity`| The severity of the event (`Debug`, `Information`, `Warning`, `Error`, `Critical`).|
-|`pipeline.name`| The name of the pipeline corresponding to the resilience pipeline.|
-|`pipeline.instance`| The instance name of the pipeline corresponding to the resilience pipeline.|
-|`strategy.name`| The name of the strategy generating this event.|
-|`operation.key`| The operation key associated with the call site. |
-|`exception.type`| The full name of the exception assigned to the execution result (`System.InvalidOperationException`). |
+| Name                | Description                                                                                           |
+|---------------------|-------------------------------------------------------------------------------------------------------|
+| `event.name`        | The name of the emitted event.                                                                        |
+| `event.severity`    | The severity of the event (`Debug`, `Information`, `Warning`, `Error`, `Critical`).                   |
+| `pipeline.name`     | The name of the pipeline corresponding to the resilience pipeline.                                    |
+| `pipeline.instance` | The instance name of the pipeline corresponding to the resilience pipeline.                           |
+| `strategy.name`     | The name of the strategy generating this event.                                                       |
+| `operation.key`     | The operation key associated with the call site.                                                      |
+| `exception.type`    | The full name of the exception assigned to the execution result (`System.InvalidOperationException`). |
 
 #### Event names
 
@@ -158,17 +158,17 @@ The `event.name` tag is reported by individual resilience strategies. The built-
 
 Tags:
 
-|Name|Description|
-|---| ---|
-|`event.name`| The name of the emitted event. Currently, the event name is always `ExecutionAttempt`. |
-|`event.severity`| The severity of the event (`Debug`, `Information`, `Warning`, `Error`, `Critical`).|
-|`pipeline.name`| The name of the pipeline corresponding to the resilience pipeline.|
-|`pipeline.instance`| The instance name of the pipeline corresponding to the resilience pipeline.|
-|`strategy.name`| The name of the strategy generating this event.|
-|`operation.key`| The operation key associated with the call site. |
-|`exception.type`| The full name of the exception assigned to the execution result (`System.InvalidOperationException`). |
-|`attempt.number`| The execution attempt number, starting at 0 (0, 1, 2, etc.). |
-|`attempt.handled`| Indicates if the execution outcome was handled. A handled outcome indicates execution failure and the need for retry (`true`, `false`). |
+| Name                | Description                                                                                                                             |
+|---------------------|-----------------------------------------------------------------------------------------------------------------------------------------|
+| `event.name`        | The name of the emitted event. Currently, the event name is always `ExecutionAttempt`.                                                  |
+| `event.severity`    | The severity of the event (`Debug`, `Information`, `Warning`, `Error`, `Critical`).                                                     |
+| `pipeline.name`     | The name of the pipeline corresponding to the resilience pipeline.                                                                      |
+| `pipeline.instance` | The instance name of the pipeline corresponding to the resilience pipeline.                                                             |
+| `strategy.name`     | The name of the strategy generating this event.                                                                                         |
+| `operation.key`     | The operation key associated with the call site.                                                                                        |
+| `exception.type`    | The full name of the exception assigned to the execution result (`System.InvalidOperationException`).                                   |
+| `attempt.number`    | The execution attempt number, starting at 0 (0, 1, 2, etc.).                                                                            |
+| `attempt.handled`   | Indicates if the execution outcome was handled. A handled outcome indicates execution failure and the need for retry (`true`, `false`). |
 
 ### Instrument: `resilience.polly.pipeline.duration`
 
@@ -179,12 +179,12 @@ Tags:
 
 Tags:
 
-|Name|Description|
-|---| ---|
-|`pipeline.name`| The name of the pipeline corresponding to the resilience pipeline.|
-|`pipeline.instance`| The instance name of the pipeline corresponding to the resilience pipeline.|
-|`operation.key`| The operation key associated with the call site. |
-|`exception.type`| The full name of the exception assigned to the execution result (`System.InvalidOperationException`). |
+| Name                | Description                                                                                           |
+|---------------------|-------------------------------------------------------------------------------------------------------|
+| `pipeline.name`     | The name of the pipeline corresponding to the resilience pipeline.                                    |
+| `pipeline.instance` | The instance name of the pipeline corresponding to the resilience pipeline.                           |
+| `operation.key`     | The operation key associated with the call site.                                                      |
+| `exception.type`    | The full name of the exception assigned to the execution result (`System.InvalidOperationException`). |
 
 ### Metering enrichment
 
@@ -241,7 +241,7 @@ Resilience pipeline executing. Source: '{PipelineName}/{PipelineInstance}', Oper
 Resilience pipeline executed. Source: '{PipelineName}/{PipelineInstance}', Operation Key: '{OperationKey}', Result: '{Result}', Execution Health: '{ExecutionHealth}', Execution Time: {ExecutionTime}ms
 
 // This log is recorded upon the completion of every execution attempt. EventId = 3
-Execution attempt. Source: '{PipelineName}/{PipelineInstance}/{StrategyName}', Operation Key: '{OperationKey}', Result: '{Result}', Handled: '{Handled}', Attempt: '{Attempt}', Execution Time: '{ExecutionTimeMs}'
+Execution attempt. Source: '{PipelineName}/{PipelineInstance}/{StrategyName}', Operation Key: '{OperationKey}', Result: '{Result}', Handled: '{Handled}', Attempt: '{Attempt}', Execution Time: '{ExecutionTime}ms'
 ```
 
 ## Emitting telemetry events

diff --git a/docs/strategies/hedging.md b/docs/strategies/hedging.md
@@ -97,9 +97,9 @@ The reported `Execution Attempt` telemetry events' severity depends on the actio
 ```none
 Resilience event occurred. EventName: 'OnHedging', Source: 'MyPipeline/MyPipelineInstance/Hedging', Operation Key: 'MyHedgingOperation', Result: ''
 
-Execution attempt. Source: 'MyPipeline/MyPipelineInstance/Hedging', Operation Key: 'MyHedgingOperation', Result: '1', Handled: 'False', Attempt: '0', Execution Time: '1505.3839'
+Execution attempt. Source: 'MyPipeline/MyPipelineInstance/Hedging', Operation Key: 'MyHedgingOperation', Result: '1', Handled: 'False', Attempt: '0', Execution Time: 1505.3839ms
 
-Execution attempt. Source: 'MyPipeline/MyPipelineInstance/Hedging', Operation Key: 'MyHedgingOperation', Result: 'Exception of type 'CustomException' was thrown.', Handled: 'True', Attempt: '1', Execution Time: '1525.2899'
+Execution attempt. Source: 'MyPipeline/MyPipelineInstance/Hedging', Operation Key: 'MyHedgingOperation', Result: 'Exception of type 'CustomException' was thrown.', Handled: 'True', Attempt: '1', Execution Time: 1525.2899ms
     CustomException: Exception of type 'CustomException' was thrown.
         at Program.<>c.<<Main>b__0_2>d.MoveNext()
         ...

diff --git a/docs/strategies/retry.md b/docs/strategies/retry.md
@@ -127,9 +127,9 @@ Here are some sample events:
 If the retry strategy does not perform any retries then the reported telemetry events' severity will be `Information`:
 
 ```none
-Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: '1', Handled: 'False', Attempt: '0', Execution Time: '110.952'
+Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: '1', Handled: 'False', Attempt: '0', Execution Time: 110.952ms
 
-Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'False', Attempt: '0', Execution Time: '5.2194'
+Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'False', Attempt: '0', Execution Time: 5.2194ms
     System.Exception: Failed
         at Program.<>c.<Main>b__0_1(ResilienceContext ctx)
         ...
@@ -141,7 +141,7 @@ Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Oper
 If the retry strategy performs some retries then the reported telemetry events' severity will be `Warning`:
 
 ```none
-Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'True', Attempt: '0', Execution Time: '5.0397'
+Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'True', Attempt: '0', Execution Time: 5.0397ms
       System.Exception: Failed
          at Program.<>c.<Main>b__0_1(ResilienceContext ctx)
          ...
@@ -154,7 +154,7 @@ Resilience event occurred. EventName: 'OnRetry', Source: 'MyPipeline/MyPipelineI
         at Polly.ResiliencePipeline.<>c.<<ExecuteAsync>b__1_0>d.MoveNext() in /_/src/Polly.Core/ResiliencePipeline.Async.cs:line 67
 
 
-Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'True', Attempt: '1', Execution Time: '0.1159'
+Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'True', Attempt: '1', Execution Time: 0.1159ms
       System.Exception: Failed
          at Program.<>c.<Main>b__0_1(ResilienceContext ctx)
          ...

diff --git a/src/Polly.Extensions/Telemetry/Log.cs b/src/Polly.Extensions/Telemetry/Log.cs
@@ -8,13 +8,20 @@ namespace Polly.Telemetry;
 [ExcludeFromCodeCoverage]
 internal static partial class Log
 {
+    internal const string Separator = ", ";
+    internal const string SourceWithStrategy = "Source: '{PipelineName}/{PipelineInstance}/{StrategyName}'";
+    internal const string SourceWithoutStrategy = "Source: '{PipelineName}/{PipelineInstance}'";
+    internal const string OperationKey = "Operation Key: '{OperationKey}'";
+    internal const string Result = "Result: '{Result}'";
+    internal const string ExecutionTime = "Execution Time: {ExecutionTimeMs}ms";
+
     [LoggerMessage(
         EventId = 0,
         Message = "Resilience event occurred. " +
                 "EventName: '{EventName}', " +
-                "Source: '{PipelineName}/{PipelineInstance}/{StrategyName}', " +
-                "Operation Key: '{OperationKey}', " +
-                "Result: '{Result}'",
+                SourceWithStrategy + Separator +
+                OperationKey + Separator +
+                Result,
         EventName = "ResilienceEvent")]
     public static partial void ResilienceEvent(
         this ILogger logger,
@@ -31,8 +38,8 @@ public static partial void ResilienceEvent(
         1,
         LogLevel.Debug,
         "Resilience pipeline executing. " +
-        "Source: '{PipelineName}/{PipelineInstance}', " +
-        "Operation Key: '{OperationKey}'",
+        SourceWithoutStrategy + Separator +
+        OperationKey,
         EventName = "StrategyExecuting")]
     public static partial void PipelineExecuting(
         this ILogger logger,
@@ -43,10 +50,10 @@ public static partial void PipelineExecuting(
     [LoggerMessage(
         EventId = 2,
         Message = "Resilience pipeline executed. " +
-            "Source: '{PipelineName}/{PipelineInstance}', " +
-            "Operation Key: '{OperationKey}', " +
-            "Result: '{Result}', " +
-            "Execution Time: {ExecutionTime}ms",
+            SourceWithoutStrategy + Separator +
+            OperationKey + Separator +
+            Result + Separator +
+            ExecutionTime,
         EventName = "StrategyExecuted")]
     public static partial void PipelineExecuted(
         this ILogger logger,
@@ -55,18 +62,18 @@ public static partial void PipelineExecuted(
         string pipelineInstance,
         string? operationKey,
         object? result,
-        double executionTime,
+        double executionTimeMs,
         Exception? exception);
 
     [LoggerMessage(
         EventId = 3,
         Message = "Execution attempt. " +
-                "Source: '{PipelineName}/{PipelineInstance}/{StrategyName}', " +
-                "Operation Key: '{OperationKey}', " +
-                "Result: '{Result}', " +
+                SourceWithStrategy + Separator +
+                OperationKey + Separator +
+                Result + Separator +
                 "Handled: '{Handled}', " +
                 "Attempt: '{Attempt}', " +
-                "Execution Time: '{ExecutionTimeMs}'",
+                ExecutionTime,
         EventName = "ExecutionAttempt",
         SkipEnabledCheck = true)]
     public static partial void ExecutionAttempt(

diff --git a/test/Polly.Extensions.Tests/Telemetry/TelemetryListenerImplTests.cs b/test/Polly.Extensions.Tests/Telemetry/TelemetryListenerImplTests.cs
@@ -128,7 +128,7 @@ public void WriteExecutionAttempt_LoggingWithException_Ok()
         var messages = _logger.GetRecords(new EventId(3, "ExecutionAttempt")).ToList();
         messages.Should().HaveCount(1);
 
-        messages[0].Message.Should().Be("Execution attempt. Source: 'my-pipeline/my-instance/my-strategy', Operation Key: 'op-key', Result: 'Dummy message.', Handled: 'True', Attempt: '4', Execution Time: '123'");
+        messages[0].Message.Should().Be("Execution attempt. Source: 'my-pipeline/my-instance/my-strategy', Operation Key: 'op-key', Result: 'Dummy message.', Handled: 'True', Attempt: '4', Execution Time: 123ms");
     }
 
     [InlineData(true, true)]
@@ -148,11 +148,11 @@ public void WriteExecutionAttempt_LoggingWithOutcome_Ok(bool noOutcome, bool han
         if (noOutcome)
         {
             string resultString = string.Empty;
-            messages[0].Message.Should().Be($"Execution attempt. Source: 'my-pipeline/my-instance/my-strategy', Operation Key: 'op-key', Result: '{resultString}', Handled: '{handled}', Attempt: '4', Execution Time: '123'");
+            messages[0].Message.Should().Be($"Execution attempt. Source: 'my-pipeline/my-instance/my-strategy', Operation Key: 'op-key', Result: '{resultString}', Handled: '{handled}', Attempt: '4', Execution Time: 123ms");
         }
         else
         {
-            messages[0].Message.Should().Be($"Execution attempt. Source: 'my-pipeline/my-instance/my-strategy', Operation Key: 'op-key', Result: '200', Handled: '{handled}', Attempt: '4', Execution Time: '123'");
+            messages[0].Message.Should().Be($"Execution attempt. Source: 'my-pipeline/my-instance/my-strategy', Operation Key: 'op-key', Result: '200', Handled: '{handled}', Attempt: '4', Execution Time: 123ms");
         }
 
         messages[0].LogLevel.Should().Be(LogLevel.Warning);