Introdução

A interface padrão do .NET para registro em log (ILogger) pode registrar qualquer número e tipo de parâmetros nas mensagens de log. Por causa disso, os parâmetros são passados como object para a implementação de log, causando o boxing de tipos de valor.

Neste post, mostrarei como o .NET Core removeu a necessidade de boxing ao registrar em log, focando nos geradores de origem do .NET 6.

CA1848: Use os delegados LoggerMessage

Se você usa uma estratégia agressiva de análise estática de código, como expliquei neste post, provavelmente recebeu esta mensagem.

A documentação para a mensagem afirma:

Use LoggerMessage para corrigir violações desta regra.

LoggerMessage fornece as seguintes vantagens de desempenho sobre os métodos de extensão Logger:

• Os métodos de extensão Logger exigem “boxing” (conversão) de tipos de valor, como int, em objeto. O padrão > LoggerMessage evita o boxing usando campos Action estáticos e métodos de extensão com parâmetros fortemente > tipados.
• Os métodos de extensão Logger devem analisar o modelo de mensagem (string de formato nomeada) cada vez que uma > mensagem de log é gravada. LoggerMessage requer apenas a análise de um modelo uma vez quando a mensagem é definida.

Ele fala sobre dois problemas: boxing de tipos de valor e análise do modelo de mensagem cada vez que o método de log é chamado.

Olhando para os métodos de extensão para a interface ILogger, podemos ver por que o boxing ocorre. O parâmetro args é do tipo object, então ele pode aceitar qualquer número e qualquer tipo de argumentos (Generics não cobriria todas as permutações de params):

1
2
3
4

public static void LogInformation(this ILogger logger, string? message, params object?[] args)
{
    logger.Log(LogLevel.Information, message, args);
}

Indo um pouco mais longe, podemos ver que a mensagem é analisada cada vez que o método é chamado:

1
2
3
4
5
6
7

public static void Log(this ILogger logger, LogLevel logLevel, EventId eventId, Exception? exception, string? message, params object?[] args)
{
    ThrowHelper.ThrowIfNull(logger);

    //A classe FormattedLogValues chama o método Format da classe LogValuesFormatter.
    logger.Log(logLevel, eventId, new FormattedLogValues(message, args), exception, _messageFormatter);
}

Boxing e Unboxing

Boxing é o ato de converter um tipo de valor para o tipo object ou para uma interface. Unboxing é o processo inverso, convertendo um objeto ou interface para um tipo de valor. Ambas as operações são relativamente caras, mas o boxing é mais caro porque envolve alocar memória no heap.

Mihai Albert tem um ótimo post sobre boxing e seus impactos no desempenho em C#.

Solução anterior ao .NET 6: LoggerMessage.Define

Antes do .NET 6, podíamos definir delegados para mensagens de log e usá-los mais tarde.

Declare um delegado com o modelo de mensagem e os argumentos que ele aceita uma vez:

1
2
3
4
5

private readonly Action<ILogger, DateTime, Exception?> _logCustomerLogin = 
    LoggerMessage.Define<DateTime>(
        LogLevel.Information,
        new EventId(1, "CustomerLoggedIn"),
        "Cliente fez login em {time}");

Em seguida, chame o delegado ao registrar em log:

_logCustomerLogin(_logger, DateTime.Now, null);

Isso resolveu o problema de boxing e análise de mensagens a cada chamada, mas o .NET 6 introduziu uma solução mais limpa.

Mais informações sobre LoggerMessage.Define aqui.

Solução no .NET 6: Geradores de Origem

O .NET 6 introduziu o LoggerMessageAttribute. Quando usado, ele gera métodos de registro em log de alto desempenho em tempo de compilação. Podemos definir os métodos de logger com uma mensagem fixa e os parâmetros específicos para essa mensagem. Isso evita o problema de boxing e a análise da mensagem cada vez que o método é chamado.

Uma coisa que acho particularmente boa sobre este padrão é que as mensagens de log são centralizadas em uma classe. Isso evita problemas como repetir mensagens em muitas classes e possivelmente mensagens diferentes para o mesmo log.

Para usá-lo, aplique-o a um método partial em uma classe partial:

1
2
3
4
5

public static partial class LogMessages
{
    [LoggerMessage(Level = LogLevel.Information, Message = "Cliente fez login em {time}")]
    public static partial void LogCustomerLogin(this ILogger logger, DateTime time);
}

Em seguida, use este método de extensão personalizado para registrar em log:

_logger.LogCustomerLogin(DateTime.Now);

ℹ️ Podemos usar a palavra-chave this no atributo ILogger, como no exemplo acima, para usar o método gerado pela origem como um método de extensão das propriedades ILogger.

Mais informações aqui.

Benchmarks

Executei alguns benchmarks comparando o desempenho dos métodos de extensão padrão ILogger e os métodos de logger gerados pela origem, ambos com um número diferente de argumentos e com níveis de log habilitados e desabilitados.

A partir dos resultados, podemos ver:

• Para os métodos de extensão padrão, mesmo ao registrar um evento com um nível de log que está desabilitado (Trace), o boxing ocorre e a memória é alocada no heap, causando uma possível coleta de lixo. Podemos verificar manualmente se o nível do evento está habilitado antes de registrar em log, mas considero fazer isso toda vez um cheiro ruim;
• Com o método gerado pela origem, nenhum boxing ocorre e nenhuma memória é alocada no heap;
• Os métodos gerados pela origem são mais rápidos, mesmo quando nenhum argumento é passado para os métodos de extensão padrão.

As diferenças de velocidade são muito pequenas (nanossegundos para um log) e, provavelmente, não impactarão a maioria dos aplicativos, exceto aqueles que têm operações intensivas de log. Mesmo assim, acredito que usar os métodos de registro em log gerados pela origem vale a pena porque melhora a qualidade do código, definindo mensagens de log específicas em uma classe.

⚠️ Campos Error/StdDev/Median ocultos para melhor visualização. Resultados completos aqui.

❗ Os benchmarks não estão registrando em nenhum lugar. A ideia é fazer benchmark da lógica no método de registro em log, deixando as operações de E/S de fora.

Código fonte para os Benchmarks

https://github.com/dgenezini/LoggerBenchmarks

Referências e links

• https://learn.microsoft.com/en-us/dotnet/core/extensions/logger-message-generator
• https://learn.microsoft.com/en-us/dotnet/api/microsoft.extensions.logging.loggermessage?view=dotnet-plat-ext-7.0
• https://learn.microsoft.com/en-us/dotnet/core/extensions/high-performance-logging
• https://mihai-albert.com/2019/08/04/boxing-performance-in-c-sharp-the-basics/
• https://learn.microsoft.com/en-us/dotnet/csharp/programming-guide/types/boxing-and-unboxing