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

[アーティクル]
04/18/2024

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[] の割り当ては回避される。
値型のボックス化は回避される。

詳細情報:

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

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

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

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

関連項目

フィードバック

その他のリソース

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

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

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

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

関連項目

フィードバック

その他のリソース

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

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

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