Registro em log de alto desempenho no .NET

Artigo
04/11/2024

A classe LoggerMessage expõe a funcionalidade para criar delegados que podem ser armazenados em cache e exigem menos alocações de objeto e sobrecarga computacional reduzida em comparação com os métodos de extensão do agente, tais como LogInformation e LogDebug. Para cenários de registro em log de alto desempenho, use o padrão LoggerMessage.

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

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

Importante

Em vez de usar a classe LoggerMessage para criar logs de alto desempenho, é possível usar o atributo LoggerMessage no .NET 6 e versões posteriores. O LoggerMessageAttribute dá suporte ao log de geração de origem criado para fornecer uma solução de log altamente utilizável e de alto desempenho para aplicativos modernos do .NET. Para saber mais, confira Geração de origem de registro em log em tempo de compilação (Conceitos básicos do .NET).

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

Dica

Todo o código-fonte do exemplo de log está disponível no Navegador de Exemplos para download. Para obter mais informações, confira Procurar exemplos de código: log no .NET.

Definir uma mensagem do agente

Use Define(LogLevel, EventId, String) para criar um delegado Action a fim de registrar uma mensagem em log. Sobrecargas de Define permitem passar até seis parâmetros de tipo para uma cadeia de caracteres de formato nomeada (modelo).

A cadeia de caracteres fornecida para o método Define é 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 do espaço reservado no modelo devem ser descritivos e consistentes em todos os modelos. Eles servem como nomes de propriedade em dados de log estruturado. Recomendamos o uso da formatação Pascal Case para nomes de espaço reservado. Por exemplo, {Item}, {DateTime}.

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

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Para a Action, especifique:

O nível de log.
Um identificador de evento exclusivo (EventId) com o nome do método de extensão estático.
O modelo de mensagem (cadeia de caracteres de formato nomeada).

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

O nível de log como LogLevel.Critical.
A ID do evento como 13 com o nome do método FailedToProcessWorkItem.
Modelo de mensagem (cadeia de caracteres de formato nomeada) como uma cadeia de caracteres.

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

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

Repositórios de log estruturado podem usar o nome do evento quando recebem a ID do evento para enriquecer o log. Por exemplo, Serilog usa o nome do evento.

A Action é invocada por meio de um método de extensão fortemente tipado. O método PriorityItemProcessed registra uma mensagem sempre que um item de trabalho está sendo processado. FailedToProcessWorkItem é chamado se e quando ocorre 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 tipo WorkItem para o campo Action:

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 em que o parâmetro do 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ático para registrar em log que um item de trabalho está sendo processado, PriorityItemProcessed, recebe o valor do argumento do item de trabalho e o passa ao delegado Action:

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

No método ExecuteAsync do serviço de trabalho, PriorityItemProcessed é chamado para registrar 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 agente

O método DefineScope(string) cria um delegado Func<TResult> para definir um escopo de log. Sobrecargas de DefineScope permitem passar até seis parâmetros de tipo para uma cadeia de caracteres de formato nomeada (modelo).

Como é o caso com o método Define, a cadeia de caracteres fornecida ao método DefineScope é 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 do espaço reservado no modelo devem ser descritivos e consistentes em todos os modelos. Eles servem como nomes de propriedade em dados de log estruturado. Recomendamos o uso da formatação Pascal Case para nomes de espaço reservado. Por exemplo, {Item}, {DateTime}.

Defina um escopo de log a ser aplicado a uma série de mensagens de log usando o método DefineScope. Habilite IncludeScopes na seção de agente do console de 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 conter um delegado Func<TResult> para o escopo. O aplicativo de exemplo cria um campo chamado s_processingWorkScope (Internal/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 representante é invocado. O aplicativo de exemplo usa um modelo de mensagem que inclui a hora e a data em que o processamento foi iniciado:

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

Forneça um método de extensão estático para a mensagem de log. Inclua os parâmetros de tipo para propriedades nomeadas exibidos no modelo de mensagem. O aplicativo de exemplo usa um DateTime como carimbo de data/hora personalizado para registrar 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 using:

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 seguinte resultado mostra a ordenação prioritária de 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 no nível de log

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

ILogger.Log não é chamado.
Uma alocação de object[] representando os parâmetros é evitada.
A conversão boxing de tipo de valor é evitada.

Para mais informações:

Confira também

Registro em log no .NET

Compartilhar via

Registro em log de alto desempenho no .NET

Definir uma mensagem do agente

Definir o escopo da mensagem do agente

Otimizações protegidas no nível de log

Confira também

Recursos adicionais