Logboekregistratie met hoge prestaties in .NET

De LoggerMessage klasse biedt functionaliteit voor het maken van in cache opgeslagen gedelegeerden waarvoor minder objecttoewijzingen en minder rekenoverhead nodig zijn in vergelijking met methoden voor logboekuitbreiding, zoals LogInformation en LogDebug. Gebruik het LoggerMessage patroon voor scenario's voor logboekregistratie met hoge prestaties.

LoggerMessage biedt de volgende prestatievoordelen ten opzichte van logboekextensiemethoden:

• Voor extensiemethoden voor logboekregistratie zijn waardetypen voor boksen (converteren) vereist, zoals int, in object. Het LoggerMessage patroon voorkomt boksen met behulp van statische Action velden en extensiemethoden met sterk getypte parameters.
• Extensiemethoden voor logboekregistratie moeten de berichtsjabloon (benoemde notatietekenreeks) parseren telkens wanneer een logboekbericht wordt geschreven. LoggerMessage parseren van een sjabloon is slechts eenmaal vereist wanneer het bericht is gedefinieerd.

De applicatie demonstreert LoggerMessage functies met een verwerkingsservice voor prioriteitswachtrijen. De app verwerkt werkitems in volgorde van prioriteit. Wanneer deze bewerkingen plaatsvinden, worden logboekberichten gegenereerd met behulp van het LoggerMessage patroon.

Een logboekregistratiebericht definiëren

Gebruik Define(LogLevel, EventId, String) om een Action gemachtigde te maken voor het vastleggen van een bericht. Define overbelastingen maken het mogelijk om maximaal zes typeparameters door te geven aan een benoemde formattekenreeks (sjabloon).

De tekenreeks die aan de Define methode wordt verstrekt, is een sjabloon en geen geïnterpoleerde tekenreeks. Plaatsaanduidingen worden ingevuld in de opgegeven volgorde van de typen. Namen van tijdelijke aanduidingen in de sjabloon moeten beschrijvend en consistent zijn voor alle sjablonen. Ze fungeren als eigenschapsnamen binnen gestructureerde logboekgegevens. We raden Pascal casing aan voor tijdelijke aanduidingen. Bijvoorbeeld, {Item}. {DateTime}

Elk logboekbericht is een Action vastgehouden in een statisch veld dat is gemaakt door LoggerMessage.Define. De voorbeeld-app maakt bijvoorbeeld een veld om een logboekbericht te beschrijven voor de verwerking van werkitems:

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Geef voor de Action het volgende op:

• Het logboekniveau.
• Een unieke gebeurtenis-id (EventId) met de naam van de statische extensiemethode.
• De berichtsjabloon (tekenreeks met benoemde notatie).

Terwijl werkitems uit de wachtrij worden gehaald voor verwerking, stelt de werkservice-app het volgende in:

• Logniveau naar LogLevel.Critical.
• Gebeurtenis-id naar 13 met de naam van de FailedToProcessWorkItem methode.
• Berichtsjabloon (formaatreeks met naam) naar een tekenreeks.

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

De LoggerMessage.Define methode wordt gebruikt voor het configureren en definiëren van een Action gemachtigde, die een logboekbericht vertegenwoordigt.

Gestructureerde logboekarchieven kunnen de gebeurtenisnaam gebruiken wanneer deze samen met de gebeurtenis-id wordt opgegeven om de logboekregistratie te verrijken. Serilog gebruikt bijvoorbeeld de gebeurtenisnaam.

De Action wordt aangeroepen via een sterk getypte extensiemethode. Met de PriorityItemProcessed methode wordt een bericht geregistreerd telkens wanneer een werkitem wordt verwerkt. FailedToProcessWorkItem wordt aangeroepen als en wanneer er een uitzondering optreedt:

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

Controleer de console-uitvoer van de 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

Als u parameters wilt doorgeven aan een logboekbericht, definieert u maximaal zes typen bij het maken van het statische veld. De voorbeeld-app registreert de details van het werkitem bij het verwerken van items door een WorkItem type voor het Action veld te definiëren:

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

De sjabloon voor logboekberichten van de gemachtigde ontvangt de tijdelijke aanduidingen van de opgegeven typen. De voorbeeld-app definieert een gemachtigde voor het toevoegen van een werkitem waarbij de itemparameter een WorkItem:

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

De statische extensiemethode voor het loggen waarbij een werkitem wordt verwerkt, PriorityItemProcessed ontvangt de waarde van het werkitem en geeft deze door aan de Action delegate.

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

In de werkrolservice methode ExecuteAsync wordt PriorityItemProcessed aangeroepen om het bericht te loggen.

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

Controleer de console-uitvoer van de app:

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

Logboekberichtbereik definiëren

Met de methode DefineScope(string) wordt een Func<TResult> gemachtigde gemaakt voor het definiëren van een logboekbereik. DefineScope overbelastingen maken het mogelijk om maximaal zes typeparameters door te geven aan een benoemde formattekenreeks (sjabloon).

Net als bij de Define methode is de tekenreeks die aan de DefineScope methode wordt geleverd een sjabloon en niet een geïnterpoleerde tekenreeks. Plaatsaanduidingen worden ingevuld in de opgegeven volgorde van de typen. Namen van tijdelijke aanduidingen in de sjabloon moeten beschrijvend en consistent zijn voor alle sjablonen. Ze fungeren als eigenschapsnamen binnen gestructureerde logboekgegevens. We raden Pascal casing aan voor tijdelijke aanduidingen. Bijvoorbeeld, {Item}. {DateTime}

Definieer een logboekbereik dat moet worden toegepast op een reeks logboekberichten met behulp van de DefineScope methode. Schakel IncludeScopes in de console-logger-sectie van appsettings.json in:

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

Als u een logboekbereik wilt maken, voegt u een veld toe om een Func<TResult> gemachtigde voor het bereik te bewaren. De voorbeeld-app maakt een veld met de naam s_processingWorkScope (Intern/LoggerExtensions.cs):

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

Gebruik DefineScope om de gemachtigde te maken. Er kunnen maximaal zes typen worden opgegeven voor gebruik als sjabloonargumenten wanneer de gemachtigde wordt aangeroepen. De voorbeeld-app maakt gebruik van een berichtsjabloon die de datum/tijd bevat waarin de verwerking is gestart:

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

Geef een statische extensiemethode op voor het logboekbericht. Neem eventuele typeparameters op voor benoemde eigenschappen die worden weergegeven in de berichtsjabloon. De voorbeeld-app accepteert een DateTime als aangepaste tijdstempel om te registreren en retourneert _processingWorkScope:

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

Het bereik omwikkelt de aanroepen van de logboekextensie in een using-blok.

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

Controleer de logboekberichten in de console-uitvoer van de app. Het volgende resultaat toont prioriteitsvolgorde van logboekberichten, waarbij het logboekbereikbericht is opgenomen:

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

Beveiligde optimalisaties op logboekniveau

Een andere optimalisatie van prestaties kan worden uitgevoerd door de LogLevel, met ILogger.IsEnabled(LogLevel) vóór een aanroep naar de bijbehorende Log* methode te controleren. Als loggen niet is geconfigureerd voor de opgegeven LogLevel, zijn de volgende uitspraken waar:

• ILogger.Log wordt niet aangeroepen.
• Er wordt een toewijzing van object[], die voor de parameters is bedoeld, vermeden.
• Het boksen van waardetypen wordt vermeden.

Voor meer informatie:

• Microbenchmarks in de .NET-runtime
• Achtergrond en motivatie voor controles op logboekniveau

Zie ook

• Logboekregistratie in .NET