[C#] Verboseなログ出力を無効化したときのパフォーマンスを100倍速くする

C#のnull条件演算子`?.`を利用して、無効化されたログ出力のオーバーヘッドを回避します。

## 通常のロガー
よくあるロガーはこんな感じだと思います。

```csharp
    public static class NormalLogger
    {
        private static bool _enabled;

        public static void Init(bool enabled)
        {
            _enabled = enabled;
        }

        public static void Verbose(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string sourceFilePath = "", [CallerLineNumber] int sourceLineNumber = 0)
        {
            if (_enabled)
            {
                Trace.WriteLine(
                    sourceFilePath
                    + ":" + sourceLineNumber
                    + " " + memberName
                    + " " + DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff")
                    + " " + message);
            }
        }
    }
```

呼び出し側：

```csharp
NormalLogger.Init(false); // ログ出力を無効化
NormalLogger.Verbose("value: " + 1); // ログ出力
```

これを実行するとログ出力が無効になっているにもかかわらず、`"value: " + 1`が評価されてしまいます。
`"value: " + 1`は、int型の数値`1`をToStringして`"value: "`文字列と結合する、というそれなりにコストがかかる処理です。
今回はこれを回避します。

## 改善したロガー

```csharp
    public delegate void LogFunc(
        string message,
        [CallerMemberName] string memberName = "",
        [CallerFilePath] string sourceFilePath = "",
        [CallerLineNumber] int sourceLineNumber = 0
    );

    public static class FastLogger
    {
        public static LogFunc? Verbose { get; private set; }

        public static void Init(bool enabled)
        {
            Verbose = enabled ? (msg, name, path, line) => Write(msg, name, path, line) : null;
        }

        private static void Write(string msg, string name, string path, int line)
        {
            Trace.WriteLine(
                path
                + ":" + line
                + " " + name
                + " " + DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff")
                + " " + msg);
        }
    }
```

呼び出し側：

```csharp
FastLogger.Init(false); // ログ無効化
FastLogger.Verbose?.Invoke("value: " + 1); // ログ出力
```

まず`Verbose`メソッドを`LogFunc`デリゲートに置き換えました。そして、呼び出し側にて`?.`を使用します。
`Verbose`はデリゲートになったので、`?.`の後に`Invoke`メソッドでデリゲートを実行します。（本当は`?.()`としたいところですが文法上不可能です。）

このコードをコンパイルすると以下のように展開されます。

```csharp
LogFunc verbose = FastLogger.Verbose;
if (verbose != null)
{
    verbose("value: " + 1, "メソッド名", "ファイルパス", 10/*行番号*/);
}
```

展開されたコードを見た通り、`Verbose`がnullの場合は、`"value: " + 1`も`Verbose`の呼び出しそのものも回避されます。
絶対速いですよね！！！

## ベンチマーク
BenchmarkDotNetでベンチマークしてみます。

<details><summary>ベンチマークコード</summary><div>

```csharp
    [MemoryDiagnoser]
    [GroupBenchmarksBy(BenchmarkLogicalGroupRule.ByCategory)]
    [CategoriesColumn]
    public class LoggingTest
    {
        static void Main()
        {
            BenchmarkRunner.Run<LoggingTest>();
        }

        [Params(true, false)]
        public bool Enabled;

        [GlobalSetup]
        public void Setup()
        {
            NormalLogger.Init(this.Enabled);
            FastLogger.Init(this.Enabled);
        }

        [Benchmark(Baseline = true), BenchmarkCategory("結合")]
        public void Normal()
        {
            NormalLogger.Verbose("value: " + 1);
        }

        [Benchmark, BenchmarkCategory("結合")]
        public void Fast__()
        {
            FastLogger.Verbose?.Invoke("value: " + 1);
        }

        [Benchmark(Baseline = true), BenchmarkCategory("文字列のみ")]
        public void NormalSimple()
        {
            NormalLogger.Verbose("verbose!");
        }

        [Benchmark, BenchmarkCategory("文字列のみ")]
        public void FastSimple__()
        {
            FastLogger.Verbose?.Invoke("verbose!");
        }
    }
```
</div></details>

`CallerMemberName`の影響を無くすため、`Fast__`のようにアンダーバーを追加して`Normal`と同じ文字数になるようにしています。

### ベンチマーク結果
``` ini
BenchmarkDotNet=v0.12.1, OS=Windows 8.1 (6.3.9600.0)
Intel Core i7-4770K CPU 3.50GHz (Haswell), 1 CPU, 8 logical and 4 physical cores
Frequency=3410067 Hz, Resolution=293.2494 ns, Timer=TSC
.NET Core SDK=5.0.101
  [Host]     : .NET Core 5.0.1 (CoreCLR 5.0.120.57516, CoreFX 5.0.120.57516), X64 RyuJIT
  DefaultJob : .NET Core 5.0.1 (CoreCLR 5.0.120.57516, CoreFX 5.0.120.57516), X64 RyuJIT
```

|       Method | Categories | Enabled |          Mean |      Error |     StdDev |        Median | Ratio |  Gen 0 | Gen 1 | Gen 2 | Allocated |
|------------- |----------- |-------- |--------------:|-----------:|-----------:|--------------:|------:|-------:|------:|------:|----------:|
|       **Normal** |         **結合** |   **False** |    **20.3541 ns** |  **0.0756 ns** |  **0.0670 ns** |    **20.3699 ns** |  **1.00** | **0.0095** |     **-** |     **-** |      **40 B** |
|       Fast__ |         結合 |   False |     0.3115 ns |  0.0067 ns |  0.0063 ns |     0.3109 ns |  0.02 |      - |     - |     - |         - |
|              |            |         |               |            |            |               |       |        |       |       |           |
| NormalSimple |      文字列のみ |   False |     1.8130 ns |  0.0098 ns |  0.0087 ns |     1.8138 ns |  1.00 |      - |     - |     - |         - |
| FastSimple__ |      文字列のみ |   False |     0.0388 ns |  0.0256 ns |  0.0240 ns |     0.0304 ns |  0.02 |      - |     - |     - |         - |
|              |            |         |               |            |            |               |       |        |       |       |           |
|       **Normal** |         **結合** |    **True** | **4,019.5700 ns** | **10.8629 ns** |  **9.6297 ns** | **4,021.0225 ns** |  **1.00** | **0.1678** |     **-** |     **-** |     **728 B** |
|       Fast__ |         結合 |    True | 4,033.7189 ns | 21.0017 ns | 19.6450 ns | 4,035.2283 ns |  1.00 | 0.1678 |     - |     - |     728 B |
|              |            |         |               |            |            |               |       |        |       |       |           |
| NormalSimple |      文字列のみ |    True | 4,178.7744 ns | 66.8528 ns | 59.2633 ns | 4,161.0348 ns |  1.00 | 0.1678 |     - |     - |     712 B |
| FastSimple__ |      文字列のみ |    True | 4,010.7709 ns | 24.1833 ns | 20.1941 ns | 4,013.7803 ns |  0.96 | 0.1678 |     - |     - |     712 B |

20.3541 / 0.3115 ≒ 65倍速くなっています。
え？タイトルの100倍は？
・・・よく考えてみてください。このベンチマークは`"value: " + 1`という単純なログです。実際のログならもっと複雑になり、100倍どころでは済まないはずです。（希望的観測）

文字列のみの場合`ToString`や結合のコストは一切かからないはずですが、staticな`Verbose`メソッドの呼び出しにオーバーヘッドがそこそこあるのは意外でした。スタック領域の確保や各引数のコピーなども馬鹿になりません。
`?.`演算子によりメソッドの呼び出し自体を回避できるため、1.8130 / 0.0388 ≒ 47倍も高速になるようです。

# 入力ミスの防止
`Verbose`はデリゲートのため、次のように呼び出せます。

```csharp
FastLogger.Verbose("foo");
```

うっかり書いてしまうと、`NullReferenceException`が発生してしまいます。

## null許容参照型
`FastLogger`のコードで既に使用していますが、`Verbose`の型を`LogFunc?`のように後ろに`?`を付けることで、null許容参照型とすることができます。
こうすることで、`Verbose(...)`と書いてしまった時にコンパイラーが警告を出してくれます。
null許容参照型はC#8以降で使用可能です。

# おわり
これでVerboseログを書きまくれます。ありがとうC#。