Delen via

Logboekregistratie met hoge prestaties in .NET

  • Artikel

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 extensiemethoden voor logboekregistratie:

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

Belangrijk

In plaats van de LoggerMessage-klasse te gebruiken om logboeken met hoge prestaties te maken, kunt u het kenmerk LoggerMessage gebruiken in .NET 6 en latere versies. De LoggerMessageAttribute biedt ondersteuning voor logboekregistratie van de brongeneratie die is ontworpen om een zeer bruikbare en zeer goed presterende logboekregistratieoplossing te bieden voor moderne .NET-toepassingen. Zie Compile-time logging source generation (.NET Fundamentals) voor meer informatie.

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

Tip

Alle voorbeeldbroncode voor logboekregistratie is beschikbaar in de voorbeeldenbrowser om te downloaden. Zie Bladeren in codevoorbeelden: Logboekregistratie in .NET voor meer informatie.

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 notatietekenreeks (sjabloon).

De tekenreeks die aan de Define methode wordt verstrekt, is een sjabloon en geen geïnterpoleerde tekenreeks. Tijdelijke aanduidingen worden ingevuld in de volgorde waarin de typen zijn opgegeven. 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 aan om tijdelijke aanduidingen te gebruiken voor namen van 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, geef het volgende op:

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

Omdat werkitems worden ontkend voor verwerking, stelt de werkservice-app het volgende in:

  • Logboekniveau naar LogLevel.Critical.
  • Gebeurtenis-id naar 13 met de naam van de FailedToProcessWorkItem methode.
  • Berichtsjabloon (benoemde notatietekenreeks) 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 logboekregistratiearchieven kunnen de naam van de gebeurtenis gebruiken wanneer deze wordt opgegeven met de gebeurtenis-id om 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 logboekregistratie dat een werkitem wordt verwerkt, PriorityItemProcessedontvangt de waarde van het werkitemar en geeft deze door aan de Action gemachtigde:

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

In de methode PriorityItemProcessed van ExecuteAsync de werkrolservice wordt het bericht aangeroepen:

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 notatietekenreeks (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. Tijdelijke aanduidingen worden ingevuld in de volgorde waarin de typen zijn opgegeven. 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 aan om tijdelijke aanduidingen te gebruiken voor namen van tijdelijke aanduidingen. Bijvoorbeeld, {Item}. {DateTime}

Definieer een logboekbereik dat moet worden toegepast op een reeks logboekberichten met behulp van de DefineScope methode. Inschakelen IncludeScopes in de sectie consolelogger van appsettings.json:

{
    "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 deze 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 neemt een DateTime aangepaste tijdstempel in om te registreren en retourneert _processingWorkScope:

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

Het bereik verpakt de aanroepen van de extensie voor logboekregistratie 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. Wanneer logboekregistratie niet is geconfigureerd voor de opgegeven LogLevel, zijn de volgende instructies waar:

  • ILogger.Log wordt niet gebeld.
  • Er wordt een toewijzing van object[] de parameters vermeden.
  • Het boksen van waardetypen wordt vermeden.

Bekijk voor meer informatie:

Zie ook