Cómo escribir un logger de alto rendimiento para .Net Core

Han pasado ya unos días desde la última entrada en la que hablamos sobre como escribir código de alto rendimiento en .Net Core. Aunque en la entrada intenté meter todo lo posible, al final quedó bastante larga. Es por eso por lo que pensé que en vez de hablar por encima sobre como escribir un logger de alto rendimiento, era mejor dedicarle una entrada en exclusiva. ¡Vamos con ello!

¿Por qué debería escribir un logger de alto rendimiento?

Aun a riesgo de parecer pesado y repetir lo mismo que en la entrada anterior, el código de alto rendimiento es menos legible y más difícil de mantener que un código normal. Antes de decidir hacer modificaciones para conseguir un alto rendimiento, es importante medir. Con los datos de las mediciones en la mano, hay que evaluar si vale la pena cambiar el código para conseguir mejor rendimiento. (Sin medir, ni siquiera se puede afirmar de donde viene el problema…)

Si tienes dudas sobre cómo hacer esto, para aquí y lee Escribiendo código de alto rendimiento en .Net Core.

La interfaz ILogger está totalmente integrada en .Net Core tanto a nivel de web como de servicio, y es la piedra angular sobre la que se sustenta todo el sistema de logging. Esta tan bien integrado que no usarlo requiere que nos preguntemos si no estaremos reinventando la rueda….

Vale, tenemos mediciones de tiempo y podemos afirmar que hay que optimizar el logger para conseguir alto rendimiento. Tenemos totalmente integrado nuestro sistema con ILogger. ¿Dónde está el problema entonces?

Si hacemos una medición con un código como por ejemplo este:

[MemoryDiagnoser]
public class ILoggerParameters
{
    private readonly ILogger _logger;
    public ILoggerParameters()
    {
        IServiceCollection serviceCollection = new ServiceCollection();

        serviceCollection.AddLogging();

        var loggerFactory = serviceCollection.BuildServiceProvider().GetService<ILoggerFactory>();

        _logger = loggerFactory.CreateLogger("TEST");
    }

    [Benchmark(Baseline = true)]
    public void LoggerWith0Parameters()
    {
        _logger.LogInformation("Mensaje de log sin parámetros");
    }

    [Benchmark]
    public void LoggerWith1Parameters()
    {
        _logger.LogInformation("Mensaje de log con un parámetro {Parametro1}", "Valor1");
    }

    [Benchmark]
    public void LoggerWith2Parameters()
    {
        _logger.LogInformation("Mensaje de log con dos parámetros ({Parametro1},{Parametro2})", "Valor1", "Valor2");
    }
}

Podemos comprobar que los resultados apuntan a que el número de parámetros influye en el rendimiento del log.

De hecho, hay un punto interesante, y es que incluso hay un consumo de memoria al utilizar parámetros pero… Si los parámetros son string y son por referencia, ¿porque hay consumo? ¿Es esto suficiente para justificar un logger de alto rendimiento?

¿Qué hay bajo el capo de ILogger?

En los datos anteriores hemos comprobado que cuando se utiliza ILogger con parámetros, el consumo de memoria aumenta pese a que sean datos por referencia.

Esto a simple vista puede parecer raro, pero tiene todo el sentido si entramos a detalle de como esta implementado ILogger, vamos a poder comprobar que a fin de simplificar la generalización se hacen ciertas conversiones que añaden coste computacional al proceso, como por ejemplo convertir los parámetros en un «params». Esto obliga a crear un array que hay que reservar. Encima de todo eso, «params» es de tipo object[], por lo que además tenemos un boxing por el camino.

Se conoce como boxing el proceso de hacer una conversión de cualquier tipo a object. El unboxing hace referencia al proceso contrario, convertir object a cualquier otro tipo.

De hecho, basta con mirar la firma de uno de los métodos de ILogger como puede ser LogInformation (aunque sea un método de extensión, el método Log recibe los mismos args).

public static void LogInformation(this ILogger logger, string message, params object[] args)

En él, ya se puede comprobar que se está haciendo un boxing desde el tipo de dato que le pasemos como argumento hacia object y se esta convirtiendo en un array.

En el caso de trabajar con valores por referencia, el boxing y unboxing no es un problema ya que todos los datos ya están en el heap (cómo bien indica Daniel Redondo en los comentarios). En cambio si estamos haciendo boxing de un objeto por valor, la cosa es diferente tanto en tiempo como en memoria. Un código como este:

[Benchmark(Baseline = true)]
public int Boxing() => Boxing(Message);
[Benchmark]
public int NoBoxing() => NoBoxing(Message);
private int Boxing(object message) => (int)message;
private int NoBoxing(int message) => message;

Genera un resultado tan interesante como este:

¿Cómo se puede conseguir un logger de alto rendimiento?

Por suerte, .Net core 3 ofrece un mecanismo para crear un logger de alto rendimiento a través de LoggerMessage.Define. ¿Y cómo funciona LoggerMessage.Define para mejorar el rendimiento?

Este mecanismo va a crear una plantilla que se compilará y servirá para un mensaje concreto. Esto es un trabajo extra (como todo cuando se optimiza), pero permite que las llamadas ejecuten esa plantilla en vez de interpolar strings. Además, al ser esa plantilla un ‘Action’ no es preciso realizar un boxing ya que los tipos son estrictos.

Adicionalmente a lo anterior, este Action debería ser estático de modo que no sea necesario recrearlo cuando la clase que contiene el logger se inicialice de nuevo.

Para ello, podríamos crear una clase abstracta que almacene todas esas plantillas (delegados) de nuestro logger de alto rendimiento:

public static class OptimizedLogger
{
    public static void LogInformation(ILogger logger) => _informationSinParametros(logger, null);
    public static void LogInformation(ILogger logger, string parametro1) => _information1Parametro(logger, parametro1, null);
    public static void LogInformation(ILogger logger, string parametro1, string parametro2) => _information2Parametros(logger, parametro1, parametro2, null);


    private static readonly Action<ILogger, Exception> _informationSinParametros = LoggerMessage.Define(
        LogLevel.Information,
        Events.Evento1,
        "Mensaje de log sin parámetros");

    private static readonly Action<ILogger, string, Exception> _information1Parametro = LoggerMessage.Define<string>(
        LogLevel.Information,
        Events.Evento1,
        "Mensaje de log con 1 parámetro: {Parametro1}");

    private static readonly Action<ILogger, string, string, Exception> _information2Parametros = LoggerMessage.Define<string, string>(
        LogLevel.Information,
        Events.Evento1,
        "Mensaje de log con 2 parámetros: {Parametro1} y {Parametro2}");
}

Haciendo un resumen del código, estamos creando 3 delegados tipados con LoggerMessage para cada uno de los 3 escenarios. Hemos conseguido añadir parámetros utilizando la sobrecarga genérica de LoggerMessage.Define y ahora tenemos 3 delegados que reciben un ILogger, una excepción y entre o y 2 strings.

¿Hemos conseguido algo con esto? ¿No estamos utilizando el mismo ILogger que tenía mal rendimiento? Pues sí y no. Sí estamos utilizando el mismo ILogger, pero no estamos llamando a su método Log, sino que estamos utilizando el delegado que hemos definido previamente de modo que ahora las llamadas son fuertemente tipadas.

Vamos a comprobar si realmente hemos mejorado con un código que compare los dos loggers en el caso de tener 2 parámetros como podría ser este:

[MemoryDiagnoser]
public class ILoggerVsOptimized2Params
{
    private readonly ILogger _logger;
    private const string Parametro1 = "Parametro1";
    private const string Parametro2 = "Parametro2";

    public ILoggerVsOptimized2Params()
    {
        IServiceCollection serviceCollection = new ServiceCollection();
        serviceCollection.AddLogging();
        var loggerFactory = serviceCollection.BuildServiceProvider().GetService<ILoggerFactory>();
        _logger = loggerFactory.CreateLogger("TEST");
    }

    [Benchmark(Baseline = true)]
    public void Logger2Parametros()
    {
        _logger.LogInformation("Mensaje de log con 2 parámetros: {Parametro1} y {Parametro2}", Parametro1, Parametro2);
    }

    [Benchmark]
    public void OptimizedLogger2Parametros()
    {
        OptimizedLogger.LogInformation(_logger, Parametro1, Parametro2);
    }
}

Si nos fijamos en los resultados podemos comprobar que este cambio mejora el rendimiento tardando un 93% menos y sin consumir nada de memoria.

Conclusiones

Hacer un logger de alto rendimiento tiene un impacto a la hora de desarrollar el proyecto. Al igual que todas las optimizaciones es necesario que exista una razón cuantificable antes de hacer un desarrollo pensado para la máquina en vez de para las personas.

El hecho de tener que definir un delegado fuertemente tipado para cada mensaje que se vaya a loguear genera una sobrecarga de trabajo muy grande en un proyecto donde hay cientos de mensajes distintos. Es por eso que una opción muy interesante es valorar que logger tienen que ser de alto rendimiento (por ejemplo, en un middleware de cabecera de ASP) y que loggers pueden utilizar la implementación estándar.

Con esas consideraciones en la mano, evidentemente hacer los cambios tiene un beneficio importante en el coste de ejecución de la aplicación.

He dejado un repositorio en GitHub para que puedas descargarte el código y probarlo, tocarlo y cambiarlo para poder ver los resultados en tu propio equipo (que es como más se aprende).