Hochleistungsprotokollierung in .NET

Artikel
04/11/2024

Die Klasse LoggerMessage macht Funktionen zum Erstellen von Delegaten verfügbar, die zwischengespeichert werden können und die im Vergleich zu Methoden zur Protokollierungserweiterung (wie z. B. LogInformation und LogDebug) weniger Objektzuweisungen benötigen und den Rechenaufwand reduzieren. Verwenden Sie das LoggerMessage-Muster für Hochleistungsprotokollierungen.

LoggerMessage hat im Vergleich zu Protokollierungserweiterungsmethoden die folgenden Vorzüge:

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.

Wichtig

Anstatt die LoggerMessage-Klasse zum Erstellen von Hochleistungsprotokollen zu verwenden, können Sie das LoggerMessage-Attribut in .NET 6 und höher verwenden. Die Unterstützung der Protokollierung der Quellgenerierung durch das LoggerMessageAttribute soll eine hochverwertbare und äußerst leistungsfähige Protokollierungslösung für moderne .NET-Anwendungen bieten. Weitere Informationen finden Sie unter Protokollierung der Quellgenerierung zur Kompilierzeit (.NET-Grundlagen).

Die Beispiel-App veranschaulicht LoggerMessage-Features mit einem Workerdienst zur priorisierten Warteschlangenverarbeitung. Die App verarbeitet Arbeitselemente in der Reihenfolge ihrer Priorität. Während dieser Vorgänge werden Protokollmeldungen mit dem LoggerMessage-Muster erstellt.

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 Protokollmeldung

Verwenden Sie Define(LogLevel, EventId, String) zum Erstellen eines Action-Delegaten zum Protokollieren einer Meldung. Define überlädt die Zulassung und übergibt bis zu sechs Typparameter an eine benannte Formatzeichenfolge (Vorlage).

Die für die Methode Define bereitgestellte Zeichenfolge ist eine Vorlage und keine interpolierte Zeichenfolge. Platzhalter werden in der Reihenfolge der angegebenen Typen ersetzt. Die Platzhalternamen in den Vorlagen sollten eindeutig und in allen Vorlagen einheitlich sein. Sie fungieren als Eigenschaftennamen 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 Protokollmeldung ist ein Action-Objekt, das in einem von LoggerMessage.Define erstellten statischen Feld enthalten ist. Beispiel: Die Beispiel-App erstellt ein Feld, das eine Protokollmeldung für die Verarbeitung von Arbeitselementen beschreibt:

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Geben Sie für das Action-Objekt Folgendes an:

die Protokollierungsebene
Einen eindeutigen Ereignis-Bezeichner (EventId) mit dem Namen der statischen Erweiterungsmethode
die Meldungsvorlage (eine benannte Formatzeichenfolge)

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 Protokollspeicher verwenden möglicherweise den Ereignisnamen, wenn dieser mit der Ereignis-ID bereitgestellt wird. Dadurch wird die Protokollierung ergänzt. Serilog verwendet z.B. den Ereignisnamen.

Das Action-Objekt wird mit einer stark typisierten Erweiterungsmethode aufgerufen. Die Methode PriorityItemProcessed protokolliert jedes Mal eine Meldung, wenn ein Arbeitselement verarbeitet wird. FailedToProcessWorkItem wird aufgerufen, wenn 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);
        }
    }
}

Sehen Sie sich folgende Konsolenausgabe der App an:

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

Definieren Sie bis zu sechs Typen, wenn Sie das statische Feld erstellen, um Parameter an eine Protokollmeldung zu übergeben. Die Beispiel-App protokolliert die Arbeitselementdetails bei der Verarbeitung von Elementen durch Definieren eines WorkItem-Typs für das Feld Action:

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

Die Protokollmeldungsvorlage des Delegaten erhält ihre Platzhalterwerte von den bereitgestellten Typen. Die Beispiel-App definiert einen Delegaten zum Hinzufügen eines Arbeitselements. Hierbei ist der Elementparameter ein WorkItem-Objekt:

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

Die statische Erweiterungsmethode zur Protokollierung der Verarbeitung eines Arbeitselements (PriorityItemProcessed) empfängt den Wert des Arguments für das Arbeitselement und übergibt ihn an den Delegaten Action:

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

Sehen Sie sich folgende Konsolenausgabe der App an:

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

Definieren des Bereichs für Protokollmeldungen

Die Methode DefineScope(string) erstellt einen Delegaten Func<TResult> zum Definieren eines Protokollbereichs. DefineScope überlädt die Zulassung und übergibt bis zu sechs Typparameter an eine benannte Formatzeichenfolge (Vorlage).

Wie bei der Methode Define ist die Zeichenfolge,die für die Methode DefineScope bereitgestellt wurde, eine Vorlage und keine interpolierte Zeichenfolge. Platzhalter werden in der Reihenfolge der angegebenen Typen ersetzt. Die Platzhalternamen in den Vorlagen sollten eindeutig und in allen Vorlagen einheitlich sein. Sie fungieren als Eigenschaftennamen 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, um mehrere Protokollmeldungen mit der DefineScope-Methode anzuwenden. Aktivieren Sie IncludeScopes in der Datei appsettings.json im Abschnitt „Konsolenprotokollierung“:

{
    "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 mit dem Namen s_processingWorkScope (Internal/LoggerExtensions.cs):

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

Verwenden Sie DefineScope zum Erstellen eines Delegaten. 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 Meldungsvorlage, die das Datum und die Uhrzeit 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 Protokollmeldung bereit. Beziehen Sie Typparameter für benannte Eigenschaften mit ein, die in der Meldungsvorlage vorhanden sind. 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);
        }
    }
}

Sehen Sie sich die Protokollmeldungen in der Konsolenausgabe der App an. Das folgende Ergebnis zeigt die priorisierte Anordnung von Protokollmeldungen zusammen mit der Protokollbereichsmeldung an:

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

Überwachte 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 finden Sie unter:

Siehe auch

Protokollierung in .NET

Freigeben über

Hochleistungsprotokollierung in .NET

Definieren einer Protokollmeldung

Definieren des Bereichs für Protokollmeldungen

Überwachte Optimierungen auf Protokollebene

Siehe auch

Zusätzliche Ressourcen