Registro em log de alto desempenho no .NET

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.

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 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 de registro

Use Define(LogLevel, EventId, String) para criar um Action delegado para 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 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 do espaço reservado no modelo devem ser descritivos e consistentes em todos os modelos. Eles servem como nomes de propriedade dentro de dados de log estruturados. Recomendamos o uso da formatação Pascal Case para nomes de espaço reservado. Por exemplo, {Item}, {DateTime}.

Cada mensagem de log é armazenada Action em um 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, 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 nomeado).

À 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.
• ID do evento para 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 LoggerMessage.Define método é usado para configurar e definir um Action delegado, 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 PriorityItemProcessed método registra uma mensagem sempre que um item de trabalho é 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 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 em que o parâmetro de 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 logger

O método DefineScope(string) cria um Func<TResult> delegado 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 do Define método, a cadeia de caracteres fornecida para o 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 do espaço reservado no modelo devem ser descritivos e consistentes em todos os modelos. Eles servem como nomes de propriedade dentro de dados de log estruturados. 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 DefineScope método. 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 (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 e hora 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 todos os parâmetros de tipo para propriedades nomeadas que aparecem 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 pode ser feita verificando o LogLevel, com ILogger.IsEnabled(LogLevel) antes de uma invocação do 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.
• Evita-se uma alocação de object[] que represente os parâmetros.
• A conversão boxing de tipo de valor é evitada.

Para obter mais informações:

• Micro parâmetro de comparação no runtime do .NET
• Plano de fundo e motivação para verificações no nível do log

Consulte também

• Registro em log no .NET