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

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

通常のロガー

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

    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);
            }
        }
    }

呼び出し側：

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

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

改善したロガー

    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);
        }
    }

呼び出し側：

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

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

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

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

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

ベンチマーク

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

ベンチマークコード

    [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!");
        }
    }

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

ベンチマーク結果

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はデリゲートのため、次のように呼び出せます。

FastLogger.Verbose("foo");

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

null許容参照型

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

おわり

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