From eab0a7c36762becbee788fdc4fdb69c4d578b738 Mon Sep 17 00:00:00 2001 From: Reiley Yang Date: Tue, 23 Jan 2024 13:59:44 -0800 Subject: [PATCH] Docs - logging best practice (#5246) --- docs/logs/README.md | 105 ++++++++++++++++++++++++++ test/Benchmarks/Logs/Food.cs | 8 +- test/Benchmarks/Logs/LogBenchmarks.cs | 55 +++++++------- 3 files changed, 136 insertions(+), 32 deletions(-) create mode 100644 docs/logs/README.md diff --git a/docs/logs/README.md b/docs/logs/README.md new file mode 100644 index 000000000..9432718e1 --- /dev/null +++ b/docs/logs/README.md @@ -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. diff --git a/test/Benchmarks/Logs/Food.cs b/test/Benchmarks/Logs/Food.cs index 235b3c333..4b5288f4e 100644 --- a/test/Benchmarks/Logs/Food.cs +++ b/test/Benchmarks/Logs/Food.cs @@ -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); } diff --git a/test/Benchmarks/Logs/LogBenchmarks.cs b/test/Benchmarks/Logs/LogBenchmarks.cs index b4139b302..100400863 100644 --- a/test/Benchmarks/Logs/LogBenchmarks.cs +++ b/test/Benchmarks/Logs/LogBenchmarks.cs @@ -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