Docs - logging best practice (open-telemetry#5246)

Kielek · Jan 23, 2024 · eab0a7c · eab0a7c
1 parent dca99b6
commit eab0a7c
Show file tree

Hide file tree

Showing 3 changed files with 135 additions and 31 deletions.
diff --git a/docs/logs/README.md 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
@@ -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
@@ -7,27 +7,30 @@
 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
-
-
-| 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 |
+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    | 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 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 OneProcessor()
+    public void NoListener()
     {
-        this.loggerWithOneProcessor.LogInformation("Hello from {name} {price}.", "tomato", 2.99);
+        Food.SayHello(this.loggerWithNoListener, FoodName, FoodPrice);
     }
 
     [Benchmark]
-    public void OneProcessorWithLoggerMessageGenerator()
+    public void OneProcessor()
     {
-        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>