Alto desempenho em registro de logs no .NET

A LoggerMessage classe expõe a funcionalidade para criar delegados armazenáveis em cache que exigem menos alocações de objetos e menor sobrecarga computacional em comparação com métodos de extensão do registrador, como LogInformation e LogDebug. Para cenários de log de alto desempenho, use o LoggerMessage padrão.

LoggerMessage fornece as seguintes vantagens de desempenho em relação aos métodos de extensão do logger:

• Os métodos de extensão do Logger exigem tipos de valor "boxing" (conversão), como int, em object. O LoggerMessage padrão evita o boxe usando campos estáticos Action e métodos de extensão com parâmetros fortemente tipados.
• Os métodos de extensão do logger devem analisar o modelo de mensagem (cadeia de caracteres de formato nomeada) sempre que uma mensagem de log é gravada. LoggerMessage só requer a análise de um modelo uma vez quando a mensagem é definida.

O aplicativo de exemplo demonstra LoggerMessage recursos com um serviço de trabalhador de processamento de fila de prioridade. O aplicativo processa itens de trabalho em ordem de prioridade. À medida que essas operações ocorrem, as mensagens de log são geradas usando o LoggerMessage padrão.

Definir uma mensagem do registador

Use Define(LogLevel, EventId, String) para criar um Action delegado para registrar uma mensagem. Define As sobrecargas permitem passar até seis parâmetros de tipo para uma string de formato nomeado (também conhecida como modelo).

A cadeia de caracteres fornecida ao Define método é um modelo e não uma cadeia de caracteres interpolada. Os espaços reservados são preenchidos na ordem em que os tipos são especificados. Os nomes de espaço reservado no modelo devem ser descritivos e consistentes entre todos os modelos. Eles servem como nomes de propriedade dentro de dados de log estruturados. Recomendamos usar PascalCasing para nomes de espaços reservados. Por exemplo, {Item}, {DateTime}.

Cada mensagem de log é mantida Action num campo estático criado por LoggerMessage.Define. Por exemplo, o aplicativo de exemplo cria um campo para descrever uma mensagem de log para o processamento de itens de trabalho:

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Para o Action, especificar:

• O nível de log.
• Um identificador de evento exclusivo (EventId) com o nome do método de extensão estática.
• O modelo de mensagem (chamado string de formato).

À medida que os itens de trabalho são retirados da fila para processamento, o aplicativo de serviço de trabalho define:

• Configure o nível de log para LogLevel.Critical.
• ID do evento para 13, com o nome do método FailedToProcessWorkItem.
• Converta o modelo de mensagem (cadeia de caracteres de formato nomeado) para uma cadeia de caracteres.

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

O LoggerMessage.Define método é usado para configurar e definir um Action delegado, que representa uma mensagem de log.

Os armazenamentos de log estruturados podem usar o nome do evento quando ele é fornecido com a ID do evento para enriquecer o log. Por exemplo, Serilog usa o nome do evento.

O Action é invocado através de um método de extensão fortemente tipado. O PriorityItemProcessed método registra uma mensagem toda vez que um item de trabalho é processado. FailedToProcessWorkItem é chamado se e quando ocorrer uma exceção:

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

Inspecione a saída do console do aplicativo:

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

Para passar parâmetros para uma mensagem de log, defina até seis tipos ao criar o campo estático. O aplicativo de exemplo registra os detalhes do item de trabalho ao processar itens definindo um WorkItem tipo para o Action campo:

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

O modelo de mensagem de log do delegado recebe seus valores de espaço reservado dos tipos fornecidos. O aplicativo de exemplo define um delegado para adicionar um item de trabalho onde o parâmetro item é um WorkItem:

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

O método de extensão estática para registar que um item de trabalho está em processamento, PriorityItemProcessed, recebe o valor do argumento do item de trabalho e passa-o para o delegado Action.

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

No método do serviço de trabalho ExecuteAsync, PriorityItemProcessed é chamado para registar a mensagem:

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

Inspecione a saída do console do aplicativo:

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

Definir o escopo da mensagem do logger

O método DefineScope(string) cria um Func<TResult> delegado para definir um escopo de log. DefineScope As sobrecargas permitem passar até seis parâmetros de tipo para uma string de formato nomeado (também conhecida como modelo).

Como é o caso com o Define método, a cadeia de caracteres fornecida ao DefineScope método é um modelo e não uma cadeia de caracteres interpolada. Os espaços reservados são preenchidos na ordem em que os tipos são especificados. Os nomes de espaço reservado no modelo devem ser descritivos e consistentes entre todos os modelos. Eles servem como nomes de propriedade dentro de dados de log estruturados. Recomendamos usar PascalCasing para nomes de espaços reservados. Por exemplo, {Item}, {DateTime}.

Defina um escopo de log para aplicar a uma série de mensagens de log usando o DefineScope método. Habilite IncludeScopes na seção do registrador de console do appsettings.json:

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

Para criar um escopo de log, adicione um campo para manter um Func<TResult> delegado para o escopo. O aplicativo de exemplo cria um campo chamado s_processingWorkScope (Interno/LoggerExtensions.cs):

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

Use DefineScope para criar o delegado. Até seis tipos podem ser especificados para uso como argumentos de modelo quando o delegado é invocado. O aplicativo de exemplo usa um modelo de mensagem que inclui a data de início do processamento:

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

Forneça um método de extensão estática para a mensagem de log. Inclua quaisquer parâmetros de tipo para propriedades nomeadas que aparecem no modelo de mensagem. O aplicativo de exemplo recebe um carimbo de data/hora personalizado DateTime para registo e retorna _processingWorkScope:

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

O escopo encapsula as chamadas de extensão de log em um bloco de uso :

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

Inspecione as mensagens de log na saída do console do aplicativo. O resultado a seguir mostra a ordem de prioridade das mensagens de log com a mensagem de escopo de log incluída:

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

Otimizações protegidas por nível de log

Outra otimização de desempenho pode ser feita verificando o LogLevel, com ILogger.IsEnabled(LogLevel) antes de uma invocação para o método correspondente Log* . Quando o registo em log não está configurado para o LogLevel especificado, as seguintes afirmações são verdadeiras:

• ILogger.Log não é chamado.
• Evita-se uma alocação de object[] que representa os parâmetros.
• O boxe de tipo de valor é evitado.

Para mais informações:

• Micro benchmarks no ambiente de execução do .NET
• Antecedentes e motivação para verificações no nível de log

Ver também

• Registo em .NET