次の方法で共有

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

  • [アーティクル]

LoggerMessage クラスには、LogInformation や LogDebug のようなロガー拡張メソッドと比較して、必要なオブジェクト割り当ての数が少なくコンピューティング オーバーヘッドが小さいキャッシュ可能なデリゲートを作成する機能があります。 高パフォーマンスのログ記録シナリオの場合は、LoggerMessage パターンを使用します。

LoggerMessage には、ロガー拡張メソッドに比べて次のようなパフォーマンス上の利点があります。

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

重要

LoggerMessage クラスを使ってハイ パフォーマンス ログを作成する代わりに、.NET 6.0 以降のバージョンで LoggerMessage 属性を使用できます。 LoggerMessageAttribute は、最新の .NET アプリケーションに対して、非常に使いやすくパフォーマンスの高いログ ソリューションを提供するように設計されています。 詳細については、「コンパイル時のログ ソース生成(.NETの基礎)」を参照してください。

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

ヒント

ログのサンプル ソース コードはすべて、サンプル ブラウザーでダウンロードできます。 詳細については、コード サンプルの参照: .NET でのログ記録に関するページをご覧ください。

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

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

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

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

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Action の場合は、次を指定します。

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

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

  • ログ レベルを LogLevel.Critical に設定します。
  • イベント ID を FailedToProcessWorkItem メソッドの名前を含む 13 に設定します。
  • メッセージ テンプレート (名前付き書式文字列) を文字列に設定します。
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 個の型を定義します。 このサンプル アプリには、Action フィールドに WorkItem 型が定義されており、項目を処理するときに作業項目の詳細がログに記録されます。

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

Worker サービスの 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...

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

対応する Log* メソッドへの呼び出しの前に ILogger.IsEnabled(LogLevel) を使用して LogLevel をチェックすることで、その他のパフォーマンスを最適化することができます。 特定の LogLevel に対してログ記録が構成されていない場合、次の記述は真になります。

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

詳細情報:

関連項目