.NET での高パフォーマンス ロギング

LoggerMessage クラスは、やLogInformationなどのLogDebugと比較して、オブジェクトの割り当てが少なく、計算オーバーヘッドを削減するキャッシュ可能なデリゲートを作成する機能を公開します。 高パフォーマンスのログ記録シナリオの場合は、LoggerMessage パターンを使用します。

LoggerMessage は、ロガー拡張メソッドよりも次のパフォーマンス上の利点を提供します。

• ロガー拡張メソッドでは、int などの値の型を object に "ボックス化" (変換) する必要があります。 LoggerMessage パターンでは、静的な Action フィールドと、厳密に型指定されたパラメーターを持つ拡張メソッドを使用してボックス化を回避します。
• ロガー拡張メソッドでは、ログ メッセージが書き込まれるたびにメッセージ テンプレート (名前付きの書式文字列) を解析する必要があります。 LoggerMessage では、メッセージを定義するときに、一度テンプレートを解析する必要があるだけです。

サンプル アプリでは、優先順位キュー処理ワーカー サービスを使用した LoggerMessage 機能を示します。 アプリは、作業項目を優先順位で処理します。 これらの操作が発生すると、 LoggerMessage パターンを使用してログ メッセージが生成されます。

ロガー メッセージを定義する

Define(LogLevel、EventId、String) を使用して、メッセージをログ記録するためのAction デリゲートを作成します。 Define オーバーロードを使用すると、名前付き書式指定文字列 (テンプレート) に最大 6 つの型パラメーターを渡すことが可能です。

Define メソッドに提供される文字列はテンプレートであり、補間文字列ではありません。 プレースホルダーは、型が指定された順序で入力されます。 テンプレート内のプレースホルダー名は、テンプレート間でわかりやすい一貫性を持つ必要があります。 これらは、構造化ログ データ内のプロパティ名として機能します。 プレースホルダー名には Pascal 形式を推奨します。 たとえば、{Item}、{DateTime} のようになります。

各ログ メッセージは、Action によって作成された静的フィールドに保持されるです。 たとえば、サンプル アプリは、作業項目を処理するためのログ メッセージを記述するフィールドを作成します。

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Actionの場合は、次のように指定します。

• ログ レベル。
• 静的拡張メソッドの名前を持つ一意のイベント識別子 (EventId)。
• メッセージ テンプレート (名前付き書式指定文字列)。

作業項目が処理のためにデキューされると、ワーカー サービス アプリによって次の設定が行われます。

• LogLevel.Criticalにログレベルを設定します。
• 13にFailedToProcessWorkItemメソッドの名前を関連付けるイベント ID。
• メッセージテンプレート（名前付きフォーマット文字列）を文字列に変換する。

s_failedToProcessWorkItem = LoggerMessage.Define(
    LogLevel.Critical,
    new EventId(13, nameof(FailedToProcessWorkItem)),
    "Epic failure processing item!");

LoggerMessage.Define メソッドは、ログ メッセージを表すAction デリゲートを構成および定義するために使用されます。

構造化ログ ストアでは、イベント ID を指定したときにイベント名を使用してログ記録を強化できます。 たとえば、 Serilog はイベント名を使用します。

Actionは、厳密に型指定された拡張メソッドを介して呼び出されます。 PriorityItemProcessed メソッドは、作業項目が処理されるたびにメッセージをログに記録します。 FailedToProcessWorkItem は、例外が発生した場合に呼び出されます。

protected override async Task ExecuteAsync(
    CancellationToken stoppingToken)
{
    using (IDisposable? scope = logger.ProcessingWorkScope(DateTime.Now))
    {
        while (!stoppingToken.IsCancellationRequested)
        {
            try
            {
                WorkItem? nextItem = priorityQueue.ProcessNextHighestPriority();

                if (nextItem is not null)
                {
                    logger.PriorityItemProcessed(nextItem);
                }
            }
            catch (Exception ex)
            {
                logger.FailedToProcessWorkItem(ex);
            }

            await Task.Delay(1_000, stoppingToken);
        }
    }
}

アプリのコンソール出力を調べます。

crit: WorkerServiceOptions.Example.Worker[13]
      Epic failure processing item!
      System.Exception: Failed to verify communications.
         at WorkerServiceOptions.Example.Worker.ExecuteAsync(CancellationToken stoppingToken) in
         ..\Worker.cs:line 27

ログ メッセージにパラメーターを渡すには、静的フィールドの作成時に最大 6 つの型を定義します。 サンプル アプリでは、WorkItem フィールドのActionの種類を定義して、アイテムの処理時に作業項目の詳細をログに記録します。

private static readonly Action<ILogger, WorkItem, Exception> s_processingPriorityItem;

デリゲートのログ メッセージ テンプレートは、指定された型からプレースホルダー値を受け取ります。 サンプル アプリは、item パラメーターが WorkItemである作業項目を追加するためのデリゲートを定義します。

s_processingPriorityItem = LoggerMessage.Define<WorkItem>(
    LogLevel.Information,
    new EventId(1, nameof(PriorityItemProcessed)),
    "Processing priority item: {Item}");

作業項目が処理されていることをログに記録するための静的拡張メソッド ( PriorityItemProcessed) は、作業項目の引数値を受け取り、 Action デリゲートに渡します。

public static void PriorityItemProcessed(
    this ILogger logger, WorkItem workItem) =>
    s_processingPriorityItem(logger, workItem, default!);

ワーカー サービスの ExecuteAsync メソッドで、メッセージをログに記録するために PriorityItemProcessed が呼び出されます。

protected override async Task ExecuteAsync(
    CancellationToken stoppingToken)
{
    using (IDisposable? scope = logger.ProcessingWorkScope(DateTime.Now))
    {
        while (!stoppingToken.IsCancellationRequested)
        {
            try
            {
                WorkItem? nextItem = priorityQueue.ProcessNextHighestPriority();

                if (nextItem is not null)
                {
                    logger.PriorityItemProcessed(nextItem);
                }
            }
            catch (Exception ex)
            {
                logger.FailedToProcessWorkItem(ex);
            }

            await Task.Delay(1_000, stoppingToken);
        }
    }
}

アプリのコンソール出力を調べます。

info: WorkerServiceOptions.Example.Worker[1]
      Processing priority item: Priority-Extreme (50db062a-9732-4418-936d-110549ad79e4): 'Verify communications'

ロガー メッセージ スコープを定義する

DefineScope(string) メソッドは、Func<TResult>を定義するためのデリゲートを作成します。 DefineScope オーバーロードを使用すると、名前付き書式指定文字列 (テンプレート) に最大 6 つの型パラメーターを渡すことが可能です。

Define メソッドの場合と同様に、DefineScope メソッドに提供される文字列はテンプレートであり、補間文字列ではありません。 プレースホルダーは、型が指定された順序で入力されます。 テンプレート内のプレースホルダー名は、テンプレート間でわかりやすい一貫性を持つ必要があります。 これらは、構造化ログ データ内のプロパティ名として機能します。 プレースホルダー名には Pascal 形式を推奨します。 たとえば、{Item}、{DateTime} のようになります。

メソッドを使用して、一連のログ メッセージに適用するログ DefineScopeを定義します。 appsettings.jsonのコンソール ロガー セクションでIncludeScopesを有効にします。

{
    "Logging": {
        "Console": {
            "IncludeScopes": true
        },
        "LogLevel": {
            "Default": "Information",
            "Microsoft": "Warning",
            "Microsoft.Hosting.Lifetime": "Information"
        }
    }
}

ログ スコープを作成するには、スコープの Func<TResult> デリゲートを保持するフィールドを追加します。 サンプル アプリは、 s_processingWorkScope (Internal/LoggerExtensions.cs) という名前のフィールドを作成します。

private static readonly Func<ILogger, DateTime, IDisposable?> s_processingWorkScope;

DefineScopeを使用してデリゲートを作成します。 デリゲートの呼び出し時にテンプレート引数として使用するために、最大 6 つの型を指定できます。 サンプル アプリでは、処理が開始された日時を含むメッセージ テンプレートを使用します。

s_processingWorkScope =
    LoggerMessage.DefineScope<DateTime>(
        "Processing scope, started at: {DateTime}");

ログ メッセージの静的拡張メソッドを指定します。 メッセージ テンプレートに表示される名前付きプロパティの任意の型パラメーターを含めます。 サンプル アプリは、カスタム タイムスタンプの DateTime を受け取ってログに記録し、 _processingWorkScope返します。

public static IDisposable? ProcessingWorkScope(
    this ILogger logger, DateTime time) =>
    s_processingWorkScope(logger, time);

スコープは、ログ拡張機能の呼び出しをusingブロックでラップします。

protected override async Task ExecuteAsync(
    CancellationToken stoppingToken)
{
    using (IDisposable? scope = logger.ProcessingWorkScope(DateTime.Now))
    {
        while (!stoppingToken.IsCancellationRequested)
        {
            try
            {
                WorkItem? nextItem = priorityQueue.ProcessNextHighestPriority();

                if (nextItem is not null)
                {
                    logger.PriorityItemProcessed(nextItem);
                }
            }
            catch (Exception ex)
            {
                logger.FailedToProcessWorkItem(ex);
            }

            await Task.Delay(1_000, stoppingToken);
        }
    }
}

アプリのコンソール出力でログ メッセージを調べます。 次の結果は、ログ スコープ メッセージが含まれるログ メッセージの優先順位を示しています。

info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Extreme (7d153ef9-8894-4282-836a-8e5e38319fb3): 'Verify communications'
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: D:\source\repos\dotnet-docs\docs\core\extensions\snippets\logging\worker-service-options
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-High (dbad6558-60cd-4eb1-8531-231e90081f62): 'Validate collection'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Medium (1eabe213-dc64-4e3a-9920-f67fe1dfb0f6): 'Propagate selections'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Medium (1142688d-d4dc-4f78-95c5-04ec01cbfac7): 'Enter pooling [contention]'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Low (e85e0c4d-0840-476e-b8b0-22505c08e913): 'Health check network'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Deferred (07571363-d559-4e72-bc33-cd8398348786): 'Ping weather service'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Deferred (2bf74f2f-0198-4831-8138-03368e60bd6b): 'Set process state'
info: Microsoft.Hosting.Lifetime[0]
      Application is shutting down...

ログ レベルの保護された最適化

対応するLogLevel メソッドを呼び出す前に、ILogger.IsEnabled(LogLevel)を使用してLog*を確認することで、もう 1 つのパフォーマンス最適化を行うことができます。 特定の LogLevelに対してログ記録が構成されていない場合、次のステートメントが当てはまります。

• ILogger.Log は呼び出されません。
• パラメーターを表す object[] の割り当ては避けられます。
• 値型のボックス化は回避される。

詳細については、以下を参照してください。

• .NET ランタイムのマイクロ ベンチマーク
• ログ レベル チェックの背景と動機

こちらも参照ください

• .NET でのログの記録