Freigeben über

Hochleistungsprotokollierung in .NET

Die LoggerMessage Klasse stellt Funktionalität zum Erstellen zwischenspeicherbarer Delegaten zur Verfügung, die weniger Objektzuweisungen erfordern und den Rechenaufwand im Vergleich zu Logger-Erweiterungsmethoden, wie LogInformation und LogDebug, reduzieren. Verwenden Sie das LoggerMessage-Muster für Hochleistungsprotokollierungen.

LoggerMessage bietet die folgenden Leistungsvorteile gegenüber Logger-Erweiterungsmethoden:

  • Protokollierungserweiterungsmethoden erfordern das Konvertieren von Werttypen wie int in object (sogenanntes Boxing). Das LoggerMessage-Muster verhindert das Konvertieren mithilfe von statischen Action-Feldern und mithilfe von Erweiterungsmethoden mit stark typisierten Parametern.
  • Protokollierungserweiterungsmethoden müssen die Meldungsvorlagen (sogenannte Formatzeichenfolgen) jedes Mal analysieren, wenn eine Protokollmeldung geschrieben wird. LoggerMessage erfordert das Analysieren einer Vorlage nur einmal beim Festlegen der Meldung.

Von Bedeutung

Anstatt die LoggerMessage-Klasse zum Erstellen von Hochleistungsprotokollen zu verwenden, können Sie das LoggerMessage-Attribut in .NET 6 und höheren Versionen verwenden. Die LoggerMessageAttribute Unterstützung der Quellgenerierungsprotokollierung wurde bereitgestellt, um eine hochverwendbare und leistungsfähige Protokollierungslösung für moderne .NET-Anwendungen bereitzustellen. Weitere Informationen finden Sie unter Kompilierungszeitprotokollierungsquellengenerierung (.NET Fundamentals).

Die Beispiel-App veranschaulicht LoggerMessage-Features mit einem Workerdienst zur priorisierten Warteschlangenverarbeitung. Die App verarbeitet Arbeitsaufgaben in der Prioritätsreihenfolge. Wenn diese Vorgänge auftreten, werden Protokollmeldungen mithilfe des LoggerMessage Musters generiert.

Tipp

Der gesamte Quellcode des Protokollierungsbeispiels steht im Beispielbrowser zum Download zur Verfügung. Weitere Informationen finden Sie unter Durchsuchen von Codebeispielen: Protokollierung in .NET.

Definieren einer Protokolliernachricht

Verwenden Sie Define(LogLevel, EventId, String), um einen Action Delegaten zum Protokollieren einer Nachricht zu erstellen. Define Überladungen ermöglichen das Übergeben von bis zu sechs Typparametern an eine benannte Formatzeichenfolge (Vorlage).

Die für die Define Methode bereitgestellte Zeichenfolge ist eine Vorlage und keine interpolierte Zeichenfolge. Platzhalter werden in der Reihenfolge ausgefüllt, in der die Typen angegeben sind. Platzhalternamen in der Vorlage sollten beschreibend und einheitlich in allen Vorlagen sein. Sie dienen als Eigenschaftsnamen in strukturierten Protokolldaten. Es wird empfohlen, für Platzhalternamen die Pascal-Schreibweise zu verwenden. Platzhalter in einer derartigen Schreibweise sind z.B. {Item} und {DateTime}.

Jede Protokollnachricht wird Action in einem statischen Feld gespeichert, das von LoggerMessage.Define erstellt wurde. Beispielsweise erstellt die Beispiel-App ein Feld, um eine Protokollmeldung für die Verarbeitung von Arbeitsaufgaben zu beschreiben:

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Geben Sie für den Action Folgendes an:

  • Die Protokollebene.
  • Ein eindeutiger Ereignisbezeichner (EventId) mit dem Namen der statischen Erweiterungsmethode.
  • Die Vorlage für Nachrichten (Formatzeichenfolge mit Namen).

Während Arbeitselemente zur Verarbeitung aus der Warteschlange entfernt werden, legt die Workerdienst-App Folgendes fest:

  • Die Protokollierungsebene ist LogLevel.Critical.
  • Die Ereignis-ID ist 13 mit dem Namen der FailedToProcessWorkItem-Methode.
  • Die Meldungsvorlage (eine benannte Formatzeichenfolge) ist eine Zeichenfolge.
s_failedToProcessWorkItem = LoggerMessage.Define(
    LogLevel.Critical,
    new EventId(13, nameof(FailedToProcessWorkItem)),
    "Epic failure processing item!");

Die LoggerMessage.Define Methode wird verwendet, um einen Action Delegaten zu konfigurieren und zu definieren, der eine Protokollmeldung darstellt.

Strukturierte Protokollierungsspeicher können den Ereignisnamen verwenden, wenn er zusammen mit der Ereignis-ID bereitgestellt wird, um die Protokollierung zu bereichern. Beispielsweise verwendet Serilog den Ereignisnamen.

Das Action-Objekt wird mit einer stark typisierten Erweiterungsmethode aufgerufen. Die PriorityItemProcessed Methode protokolliert eine Nachricht jedes Mal, wenn eine Arbeitsaufgabe verarbeitet wird. FailedToProcessWorkItem wird aufgerufen, wenn und wann eine Ausnahme auftritt:

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

Überprüfen Sie die Konsolenausgabe der App:

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

Um Parameter an eine Protokollmeldung zu übergeben, definieren Sie beim Erstellen des statischen Felds bis zu sechs Typen. In der Beispiel-App werden die Arbeitsaufgabendetails protokolliert, wenn Elemente verarbeitet werden, indem ein WorkItem Typ für das Action Feld definiert wird:

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

Die Vorlage für Protokollnachrichten des Delegaten empfängt ihre Platzhalterwerte von den bereitgestellten Typen. Die Beispiel-App definiert einen Delegierten zum Hinzufügen einer Arbeitsaufgabe, bei der der Parameter des Elements ein WorkItem ist:

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

Die statische Erweiterungsmethode für die Protokollierung, dass ein Arbeitselement verarbeitet wird, PriorityItemProcessed empfängt den Wert des Arbeitselementarguments und übergibt ihn an den Action Delegaten:

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

In derExecuteAsync-Methode des Workerdiensts wird PriorityItemProcessed aufgerufen, um die Meldung zu protokollieren:

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

Überprüfen Sie die Konsolenausgabe der App:

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

Definieren des Logger-Nachrichtenbereichs

Die DefineScope(string)- Methode erstellt einen Func<TResult> Delegaten zum Definieren eines Protokollbereichs. DefineScope Überladungen ermöglichen das Übergeben von bis zu sechs Typparametern an eine benannte Formatzeichenfolge (Vorlage).

Wie bei der Define Methode ist die für die DefineScope Methode bereitgestellte Zeichenfolge eine Vorlage und keine interpolierte Zeichenfolge. Platzhalter werden in der Reihenfolge ausgefüllt, in der die Typen angegeben sind. Platzhalternamen in der Vorlage sollten beschreibend und einheitlich in allen Vorlagen sein. Sie dienen als Eigenschaftsnamen in strukturierten Protokolldaten. Es wird empfohlen, für Platzhalternamen die Pascal-Schreibweise zu verwenden. Platzhalter in einer derartigen Schreibweise sind z.B. {Item} und {DateTime}.

Definieren Sie einen Protokollbereich , der auf eine Reihe von Protokollmeldungen mithilfe der DefineScope Methode angewendet werden soll. Aktivieren Sie IncludeScopes im Abschnitt "Konsole-Logger" von appsettings.json:

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

Fügen Sie zum Erstellen eines Protokollbereichs ein Feld hinzu, dass einen Func<TResult>-Delegaten für den Bereich enthält. Die Beispiel-App erstellt ein Feld namens s_processingWorkScope (Intern/LoggerExtensions.cs):

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

Verwenden Sie DefineScope, um den Delegaten zu erstellen. Sie können bis zu sechs Typen als Vorlagenargumente festlegen, die verwendet werden können, wenn der Delegat aufgerufen wird. Die Beispiel-App verwendet eine Nachrichtenvorlage, die die Datumszeit enthält, zu der die Verarbeitung gestartet wurde:

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

Stellen Sie eine statische Erweiterungsmethode für die Protokollnachricht bereit. Fügen Sie alle Typparameter für benannte Eigenschaften ein, die in der Nachrichtenvorlage angezeigt werden. Die Beispiel-App akzeptiert einen DateTime-Wert für einen benutzerdefinierten Zeitstempel, der protokolliert werden soll, und gibt _processingWorkScope zurück:

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

Der Bereich umschließt die Protokollerweiterungsaufrufe in einem using-Block:

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

Überprüfen Sie die Protokollmeldungen in der Konsolenausgabe der App. Das folgende Ergebnis zeigt die Prioritätsordnung von Protokollnachrichten mit der eingeschlossenen Protokollbereichsnachricht:

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...

Geschützte Optimierungen auf Protokollebene

Eine zusätzliche Leistungsoptimierung kann durch Überprüfen von LogLevel mit ILogger.IsEnabled(LogLevel) vor einem Aufruf der entsprechenden Log*-Methode erfolgen. Wenn Protokollierung nicht für das angegebene LogLevel-Element konfiguriert ist, gelten die folgenden Aussagen:

  • ILogger.Log wird nicht aufgerufen.
  • Eine Zuordnung von object[], die die Parameter darstellt, wird vermieden.
  • Boxing von Werttypen wird vermieden.

Weitere Informationen:

Siehe auch