Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Add unit to execution time in telemetry events #2069

Merged
merged 4 commits into from
Apr 22, 2024
Merged

Add unit to execution time in telemetry events #2069

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
fc7f583
Add unit to execution time in telemetry event
peter-csala Apr 22, 2024
bd44d93
Use constants to reduce repetitive message format fragments
peter-csala Apr 22, 2024
98c6ef5
Update documentation
peter-csala Apr 22, 2024
00ea17c
Rename executionTime to executionTimeMs
peter-csala Apr 22, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
64 changes: 32 additions & 32 deletions docs/advanced/telemetry.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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:

Expand Down Expand Up @@ -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

Expand All @@ -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`

Expand All @@ -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

Expand Down Expand Up @@ -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
Expand Down
4 changes: 2 additions & 2 deletions docs/strategies/hedging.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()
...
Expand Down
8 changes: 4 additions & 4 deletions docs/strategies/retry.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
...
Expand All @@ -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)
...
Expand All @@ -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)
...
Expand Down
35 changes: 21 additions & 14 deletions src/Polly.Extensions/Telemetry/Log.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand All @@ -31,8 +38,8 @@ internal static partial class Log
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,
Expand All @@ -43,10 +50,10 @@ internal static partial class Log
[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,
Expand All @@ -55,18 +62,18 @@ internal static partial class Log
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}'",
peter-csala marked this conversation as resolved.
Show resolved Hide resolved
ExecutionTime,
EventName = "ExecutionAttempt",
SkipEnabledCheck = true)]
public static partial void ExecutionAttempt(
Expand Down
6 changes: 3 additions & 3 deletions test/Polly.Extensions.Tests/Telemetry/TelemetryListenerImplTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)]
Expand All @@ -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);
Expand Down