open-telemetry
/
opentelemetry-dotnet
mirror of https://github.com/open-telemetry/opentelemetry-dotnet.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Docs - logging best practice (#5246)

This commit is contained in:
Reiley Yang 2024-01-23 13:59:44 -08:00 committed by GitHub
parent dca99b6e66
commit eab0a7c367
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
3 changed files with 136 additions and 32 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

105
docs/logs/README.md Normal file
View File

@ -0,0 +1,105 @@
# OpenTelemetry .NET Logs
## Best Practices
The following tutorials have demonstrated the best practices for logging with
OpenTelemetry .NET:
* [Getting Started - Console Application](./getting-started-console/README.md)
* [Getting Started - ASP.NET Core
Application](./getting-started-aspnetcore/README.md)
* [Logging with Complex Objects](./complex-objects/README.md)
## Structured Logging
:heavy_check_mark: You should use structured logging.
* Structured logging is more efficient than unstructured logging.
* Filtering and redaction can happen on invidual key-value pairs instead of
the entire log message.
* Storage and indexing are more efficient.
* Structured logging makes it easier to manage and consume logs.
:stop_sign: You should avoid string interpolation.
> [!WARNING]
> The following code has bad performance due to [string
interpolation](https://learn.microsoft.com/dotnet/csharp/tutorials/string-interpolation):
```csharp
var food = "tomato";
var price = 2.99;
logger.LogInformation($"Hello from {food} {price}.");
```
Refer to the [logging performance
benchmark](../../test/Benchmarks/Logs/LogBenchmarks.cs) for more details.
## Package Version
:heavy_check_mark: You should always use the
[`ILogger`](https://docs.microsoft.com/dotnet/api/microsoft.extensions.logging.ilogger)
interface from the latest stable version of
[Microsoft.Extensions.Logging](https://www.nuget.org/packages/Microsoft.Extensions.Logging/)
package, regardless of the .NET runtime version being used:
* If you're using the latest stable version of [OpenTelemetry .NET
SDK](../../src/OpenTelemetry/README.md), you don't have to worry about the
version of `Microsoft.Extensions.Logging` package because it is already taken
care of for you via [package dependency](../../Directory.Packages.props).
* Starting from version `3.1.0`, the .NET runtime team is holding a high bar for
backward compatibility on `Microsoft.Extensions.Logging` even during major
version bumps, so compatibility is not a concern here.
## Logging API
:heavy_check_mark: You should use [compile-time logging source
generation](https://docs.microsoft.com/dotnet/core/extensions/logger-message-generator)
pattern to achieve the best performance.
```csharp
public static partial class Food
{
[LoggerMessage(Level = LogLevel.Information, Message = "Hello from {food} {price}.")]
public static partial void SayHello(ILogger logger, string food, double price);
}
var food = "tomato";
var price = 2.99;
Food.SayHello(logger, food, price);
```
> [!NOTE]
> There is no need to pass in an explicit
[EventId](https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.eventid)
while using
[LoggerMessageAttribute](https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.loggermessageattribute).
A durable `EventId` will be automatically assigned based on the hash of the
method name during code generation.
:heavy_check_mark: You can use
[LogPropertiesAttribute](https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.logpropertiesattribute)
from
[Microsoft.Extensions.Telemetry.Abstractions](https://www.nuget.org/packages/Microsoft.Extensions.Telemetry.Abstractions/)
if you need to log complex objects. Check out the [Logging with Complex
Objects](./complex-objects/README.md) tutorial for more details.
:stop_sign: You should avoid the extension methods from
[LoggerExtensions](https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.loggerextensions),
these methods are not optimized for performance.
> [!WARNING]
> The following code has bad performance due to
[boxing](https://learn.microsoft.com/dotnet/csharp/programming-guide/types/boxing-and-unboxing):
```csharp
var food = "tomato";
var price = 2.99;
logger.LogInformation("Hello from {food} {price}.", food, price);
```
Refer to the [logging performance
benchmark](../../test/Benchmarks/Logs/LogBenchmarks.cs) for more details.

8
test/Benchmarks/Logs/Food.cs
View File

@ -7,10 +7,6 @@ namespace Benchmarks.Logs;
public static partial class Food
{
[LoggerMessage(
EventId = 0,
Level = LogLevel.Information,
Message = "Hello from {food} {price}.")]
public static partial void SayHello(
ILogger logger, string food, double price);
[LoggerMessage(Level = LogLevel.Information, Message = "Hello from {food} {price}.")]
public static partial void SayHello(ILogger logger, string food, double price);
}

55
test/Benchmarks/Logs/LogBenchmarks.cs
View File

@ -7,27 +7,30 @@ using OpenTelemetry;
using OpenTelemetry.Logs;
/*
BenchmarkDotNet v0.13.10, Windows 11 (10.0.23424.1000)
Intel Core i7-9700 CPU 3.00GHz, 1 CPU, 8 logical and 8 physical cores
.NET SDK 8.0.100
[Host] : .NET 8.0.0 (8.0.23.53103), X64 RyuJIT AVX2
DefaultJob : .NET 8.0.0 (8.0.23.53103), X64 RyuJIT AVX2
BenchmarkDotNet v0.13.10, Windows 11 (10.0.22621.3007/22H2/2022Update/SunValley2)
11th Gen Intel Core i7-1185G7 3.00GHz, 1 CPU, 8 logical and 4 physical cores
.NET SDK 8.0.101
[Host] : .NET 8.0.1 (8.0.123.58001), X64 RyuJIT AVX2
DefaultJob : .NET 8.0.1 (8.0.123.58001), X64 RyuJIT AVX2
| Method | Mean | Error | StdDev | Median | Gen0 | Allocated |
|--------------------------------------- |-----------:|----------:|----------:|-----------:|-------:|----------:|
| NoListener | 44.633 ns | 0.8442 ns | 1.9733 ns | 43.683 ns | 0.0102 | 64 B |
| NoListenerWithLoggerMessageGenerator | 1.880 ns | 0.0141 ns | 0.0125 ns | 1.879 ns | - | - |
| OneProcessor | 126.857 ns | 1.1861 ns | 1.0514 ns | 126.730 ns | 0.0165 | 104 B |
| OneProcessorWithLoggerMessageGenerator | 112.677 ns | 1.0021 ns | 0.8884 ns | 112.605 ns | 0.0063 | 40 B |
| TwoProcessors | 129.967 ns | 0.8315 ns | 0.7371 ns | 129.850 ns | 0.0165 | 104 B |
| ThreeProcessors | 130.117 ns | 1.1359 ns | 1.0626 ns | 129.991 ns | 0.0165 | 104 B |
| Method | Mean | Error | StdDev | Gen0 | Allocated |
|------------------------------ |-----------:|----------:|----------:|-------:|----------:|
| NoListenerStringInterpolation | 124.458 ns | 2.5188 ns | 2.2329 ns | 0.0114 | 72 B |
| NoListenerExtensionMethod | 36.326 ns | 0.2916 ns | 0.2435 ns | 0.0102 | 64 B |
| NoListener | 1.375 ns | 0.0586 ns | 0.0896 ns | - | - |
| OneProcessor | 98.133 ns | 1.8805 ns | 1.5703 ns | 0.0063 | 40 B |
| TwoProcessors | 105.414 ns | 0.4610 ns | 0.3850 ns | 0.0063 | 40 B |
| ThreeProcessors | 102.023 ns | 1.4187 ns | 1.1847 ns | 0.0063 | 40 B |
*/
namespace Benchmarks.Logs;
public class LogBenchmarks
{
private const double FoodPrice = 2.99;
private static readonly string FoodName = "tomato";
private readonly ILogger loggerWithNoListener;
private readonly ILogger loggerWithOneProcessor;
private readonly ILogger loggerWithTwoProcessors;
@ -64,39 +67,39 @@ public class LogBenchmarks
}
[Benchmark]
public void NoListener()
public void NoListenerStringInterpolation()
{
this.loggerWithNoListener.LogInformation("Hello from {name} {price}.", "tomato", 2.99);
this.loggerWithNoListener.LogInformation($"Hello from {FoodName} {FoodPrice}.");
}
[Benchmark]
public void NoListenerWithLoggerMessageGenerator()
public void NoListenerExtensionMethod()
{
Food.SayHello(this.loggerWithNoListener, "tomato", 2.99);
this.loggerWithNoListener.LogInformation("Hello from {name} {price}.", FoodName, FoodPrice);
}
[Benchmark]
public void NoListener()
{
Food.SayHello(this.loggerWithNoListener, FoodName, FoodPrice);
}
[Benchmark]
public void OneProcessor()
{
this.loggerWithOneProcessor.LogInformation("Hello from {name} {price}.", "tomato", 2.99);
}
[Benchmark]
public void OneProcessorWithLoggerMessageGenerator()
{
Food.SayHello(this.loggerWithOneProcessor, "tomato", 2.99);
Food.SayHello(this.loggerWithOneProcessor, FoodName, FoodPrice);
}
[Benchmark]
public void TwoProcessors()
{
this.loggerWithTwoProcessors.LogInformation("Hello from {name} {price}.", "tomato", 2.99);
Food.SayHello(this.loggerWithTwoProcessors, FoodName, FoodPrice);
}
[Benchmark]
public void ThreeProcessors()
{
this.loggerWithThreeProcessors.LogInformation("Hello from {name} {price}.", "tomato", 2.99);
Food.SayHello(this.loggerWithThreeProcessors, FoodName, FoodPrice);
}
internal class DummyLogProcessor : BaseProcessor<LogRecord>