Loggning med höga prestanda i .NET

Artikel
04/11/2024

Klassen LoggerMessage exponerar funktioner för att skapa cachebara ombud som kräver färre objektallokeringar och lägre beräkningskostnader jämfört med inloggningstilläggsmetoder som LogInformation och LogDebug. Använd mönstret för LoggerMessage loggning med höga prestanda.

LoggerMessage ger följande prestandafördelar jämfört med inloggningstilläggsmetoder:

Inloggningstilläggsmetoder kräver "boxning" (konvertera) värdetyper, till exempel int, till object. Mönstret LoggerMessage undviker boxning med hjälp av statiska Action fält och tilläggsmetoder med starkt skrivna parametrar.
Inloggningstilläggsmetoder måste parsa meddelandemallen (namngiven formatsträng) varje gång ett loggmeddelande skrivs. LoggerMessage kräver bara parsning av en mall en gång när meddelandet har definierats.

Viktigt!

I stället för att använda klassen LoggerMessage för att skapa högpresterande loggar kan du använda attributet LoggerMessage i .NET 6 och senare versioner. Ger LoggerMessageAttribute stöd för källgenereringsloggning som är utformat för att leverera en mycket användbar och mycket högpresterande loggningslösning för moderna .NET-program. Mer information finns i Kompilera tidsloggningskällans generering (.NET Fundamentals).

Exempelappen visar LoggerMessage funktioner med en arbetstjänst för prioritetsköbearbetning. Appen bearbetar arbetsobjekt i prioritetsordning. När dessa åtgärder utförs genereras loggmeddelanden med hjälp av LoggerMessage mönstret.

Dricks

All källkod för loggningsexemplet är tillgänglig i Exempelwebbläsaren för nedladdning. Mer information finns i Bläddra bland kodexempel: Loggning i .NET.

Definiera ett loggningsmeddelande

Använd Define(LogLevel, EventId, String) för att skapa ett Action ombud för att logga ett meddelande. Define överlagringar tillåter att upp till sex typparametrar skickas till en namngiven formatsträng (mall).

Strängen som tillhandahålls Define till metoden är en mall och inte en interpolerad sträng. Platshållarna fylls i i den ordning som typerna anges. Platshållarnamn i mallen ska vara beskrivande och konsekventa mellan mallar. De fungerar som egenskapsnamn i strukturerade loggdata. Vi rekommenderar Pascal-hölje för platshållarnamn. Till exempel {Item}, {DateTime}.

Varje loggmeddelande lagras Action i ett statiskt fält som skapats av LoggerMessage.Define. Exempelappen skapar till exempel ett fält för att beskriva ett loggmeddelande för bearbetning av arbetsobjekt:

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

För anger Actiondu:

Loggnivån.
En unik händelseidentifierare (EventId) med namnet på metoden för statiskt tillägg.
Meddelandemallen (med namnet formatsträng).

När arbetsobjekten tas bort för bearbetning anger arbetstjänstappen följande:

Loggnivå till LogLevel.Critical.
Händelse-ID till 13 med namnet på FailedToProcessWorkItem metoden.
Meddelandemall (namngiven formatsträng) till en sträng.

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

Metoden LoggerMessage.Define används för att konfigurera och definiera ett Action ombud som representerar ett loggmeddelande.

Strukturerade loggningslager kan använda händelsenamnet när det levereras med händelse-ID:t för att utöka loggningen. Serilog använder till exempel händelsenamnet.

Action Anropas via en starkt typad tilläggsmetod. Metoden PriorityItemProcessed loggar ett meddelande varje gång ett arbetsobjekt bearbetas. FailedToProcessWorkItem anropas om och när ett undantag inträffar:

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

Granska appens konsolutdata:

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

Om du vill skicka parametrar till ett loggmeddelande definierar du upp till sex typer när du skapar det statiska fältet. Exempelappen loggar arbetsobjektsinformationen när objekt bearbetas genom att WorkItem en typ för fältet definieras Action :

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

Ombudets loggmeddelandemall tar emot platshållarvärdena från de angivna typerna. Exempelappen definierar ett ombud för att lägga till ett arbetsobjekt där objektparametern är :WorkItem

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

Den statiska tilläggsmetoden för loggning av att ett arbetsobjekt bearbetas, PriorityItemProcessed, tar emot argumentvärdet för arbetsobjektet och skickar det till ombudet Action :

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

I arbetstjänstens metod PriorityItemProcessed anropas ExecuteAsync för att logga meddelandet:

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

Granska appens konsolutdata:

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

Definiera meddelandeomfång för loggare

Metoden DefineScope(string) skapar ett Func<TResult> ombud för att definiera ett loggomfång. DefineScope överlagringar tillåter att upp till sex typparametrar skickas till en namngiven formatsträng (mall).

Precis som med Define metoden är strängen som tillhandahålls DefineScope till metoden en mall och inte en interpolerad sträng. Platshållarna fylls i i den ordning som typerna anges. Platshållarnamn i mallen ska vara beskrivande och konsekventa mellan mallar. De fungerar som egenskapsnamn i strukturerade loggdata. Vi rekommenderar Pascal-hölje för platshållarnamn. Till exempel {Item}, {DateTime}.

Definiera ett loggomfång som ska tillämpas på en serie loggmeddelanden med hjälp av DefineScope metoden . Aktivera IncludeScopes i avsnittet konsolloggning i appsettings.json:

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

Om du vill skapa ett loggomfång lägger du till ett fält som innehåller ett Func<TResult> ombud för omfånget. Exempelappen skapar ett fält med namnet s_processingWorkScope (Intern/LoggerExtensions.cs):

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

Använd DefineScope för att skapa ombudet. Upp till sex typer kan anges för användning som mallargument när ombudet anropas. Exempelappen använder en meddelandemall som innehåller datumtiden då bearbetningen startades:

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

Ange en statisk tilläggsmetod för loggmeddelandet. Inkludera alla typparametrar för namngivna egenskaper som visas i meddelandemallen. Exempelappen tar in en DateTime för en anpassad tidsstämpel för att logga och returnerar _processingWorkScope:

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

Omfånget omsluter loggningstilläggsanropen i ett användningsblock :

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

Granska loggmeddelandena i appens konsolutdata. Följande resultat visar prioritetsordning för loggmeddelanden med loggomfattningsmeddelandet inkluderat:

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

Skyddade optimeringar på loggnivå

En annan prestandaoptimering kan göras genom att kontrollera LogLevel, med ILogger.IsEnabled(LogLevel) före ett anrop till motsvarande Log* metod. När loggning inte har konfigurerats för angiven LogLevelär följande instruktioner sanna:

ILogger.Log anropas inte.
En allokering av object[] att representera parametrarna undviks.
Boxning av värdetyp undviks.

Mer information:

Se även

Loggning i .NET

Dela via

Loggning med höga prestanda i .NET

Definiera ett loggningsmeddelande

Definiera meddelandeomfång för loggare

Skyddade optimeringar på loggnivå

Se även

Ytterligare resurser