From af57ae87871aac7e201a03255ac8c81e5747bc07 Mon Sep 17 00:00:00 2001
From: Reiley Yang <reyang@microsoft.com>
Date: Tue, 19 Mar 2024 16:05:01 -0700
Subject: [PATCH] Docs - best practices for ILogger.IsEnabled (#5459)

---
 docs/logs/README.md                   | 45 +++++++++++++++++++++++++++
 test/Benchmarks/Logs/Food.cs          |  2 +-
 test/Benchmarks/Logs/LogBenchmarks.cs | 20 +++++++++---
 3 files changed, 61 insertions(+), 6 deletions(-)

diff --git a/docs/logs/README.md b/docs/logs/README.md
index 77a46c847..860702930 100644
--- a/docs/logs/README.md
+++ b/docs/logs/README.md
@@ -179,6 +179,51 @@ logger.LogInformation("Hello from {food} {price}.", food, price);
 Refer to the [logging performance
 benchmark](../../test/Benchmarks/Logs/LogBenchmarks.cs) for more details.
 
+:heavy_check_mark: You should hold a high bar while using
+[`ILogger.IsEnabled`](https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.ilogger.isenabled).
+
+The logging API is highly optimized for the scenario where most loggers are
+**disabled** for certain log levels. Making an extra call to `IsEnabled` before
+logging will not give you any performance gain.
+
+> [!WARNING]
+> The `logger.IsEnabled(LogLevel.Information)` call in the following code is not
+  going to give any performance gain. Refer to the [logging performance
+  benchmark](../../test/Benchmarks/Logs/LogBenchmarks.cs) for more details.
+
+```csharp
+var food = "tomato";
+var price = 2.99;
+
+if (logger.IsEnabled(LogLevel.Information)) // do not do this, there is no perf gain
+{
+    logger.SayHello(food, price);
+}
+
+internal static partial class LoggerExtensions
+{
+    [LoggerMessage(Level = LogLevel.Information, Message = "Hello from {food} {price}.")]
+    public static partial void SayHello(this ILogger logger, string food, double price);
+}
+```
+
+`IsEnabled` can give performance benefits when it is expensive to evaluate the
+arguments. For example, in the following code the `Database.GetFoodPrice`
+invocation will be skipped if the logger is not enabled:
+
+```csharp
+if (logger.IsEnabled(LogLevel.Information))
+{
+    logger.SayHello(food, Database.GetFoodPrice(food));
+}
+```
+
+Although `IsEnabled` can give some performance benefits in the above scenario,
+for most users it can cause more problems. For example, the performance of the
+code is now depending on which logger is being enabled, not to mention the
+argument evaluation might have significant side effects that are now depending
+on the logging configuration.
+
 ## LoggerFactory
 
 In many cases, you can use [ILogger](#ilogger) without having to interact with
diff --git a/test/Benchmarks/Logs/Food.cs b/test/Benchmarks/Logs/Food.cs
index 4b5288f4e..b3a9096cc 100644
--- a/test/Benchmarks/Logs/Food.cs
+++ b/test/Benchmarks/Logs/Food.cs
@@ -8,5 +8,5 @@ namespace Benchmarks.Logs;
 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);
+    public static partial void SayHello(this ILogger logger, string food, double price);
 }
diff --git a/test/Benchmarks/Logs/LogBenchmarks.cs b/test/Benchmarks/Logs/LogBenchmarks.cs
index 5c0f4ad28..ed1d637e7 100644
--- a/test/Benchmarks/Logs/LogBenchmarks.cs
+++ b/test/Benchmarks/Logs/LogBenchmarks.cs
@@ -19,6 +19,7 @@ BenchmarkDotNet v0.13.10, Windows 11 (10.0.22621.3007/22H2/2022Update/SunValley2
 | 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 |      - |         - |
+| UnnecessaryIsEnabledCheck     |   1.332 ns | 0.0225 ns | 0.0188 ns |      - |         - |
 | CreateLoggerRepeatedly        |  48.295 ns | 0.5951 ns | 0.4970 ns | 0.0038 |      24 B |
 | 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 |
@@ -96,32 +97,41 @@ public class LogBenchmarks
     [Benchmark]
     public void NoListener()
     {
-        Food.SayHello(this.loggerWithNoListener, FoodName, FoodPrice);
+        this.loggerWithNoListener.SayHello(FoodName, FoodPrice);
+    }
+
+    [Benchmark]
+    public void UnnecessaryIsEnabledCheck()
+    {
+        if (this.loggerWithNoListener.IsEnabled(LogLevel.Information))
+        {
+            this.loggerWithNoListener.SayHello(FoodName, FoodPrice);
+        }
     }
 
     [Benchmark]
     public void CreateLoggerRepeatedly()
     {
         var logger = this.loggerFactoryWithNoListener.CreateLogger<LogBenchmarks>();
-        Food.SayHello(logger, FoodName, FoodPrice);
+        logger.SayHello(FoodName, FoodPrice);
     }
 
     [Benchmark]
     public void OneProcessor()
     {
-        Food.SayHello(this.loggerWithOneProcessor, FoodName, FoodPrice);
+        this.loggerWithOneProcessor.SayHello(FoodName, FoodPrice);
     }
 
     [Benchmark]
     public void TwoProcessors()
     {
-        Food.SayHello(this.loggerWithTwoProcessors, FoodName, FoodPrice);
+        this.loggerWithTwoProcessors.SayHello(FoodName, FoodPrice);
     }
 
     [Benchmark]
     public void ThreeProcessors()
     {
-        Food.SayHello(this.loggerWithThreeProcessors, FoodName, FoodPrice);
+        this.loggerWithThreeProcessors.SayHello(FoodName, FoodPrice);
     }
 
     internal class DummyLogProcessor : BaseProcessor<LogRecord>