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, emobject. 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
13com o nome do métodoFailedToProcessWorkItem. - 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:
- Micro parâmetro de comparação no runtime do .NET
- Plano de fundo e motivação para verificações no nível do log
Confira também
Comentários
Em breve: Ao longo de 2024, eliminaremos os problemas do GitHub como o mecanismo de comentários para conteúdo e o substituiremos por um novo sistema de comentários. Para obter mais informações, consulte https://aka.ms/ContentUserFeedback.
Enviar e exibir comentários de