Registro de alto rendimiento en .NET

La LoggerMessage clase expone la funcionalidad para crear delegados almacenables en caché que requieren menos asignaciones de objetos y una sobrecarga computacional reducida en comparación con los métodos de extensión de registrador, como LogInformation y LogDebug. Para escenarios de registro de alto rendimiento, use el patrón LoggerMessage.

LoggerMessage proporciona las siguientes ventajas de rendimiento sobre los métodos de extensión del registrador:

• Los métodos de extensión del registrador requieren la conversión boxing de tipos de valor, como int, en object. El patrón LoggerMessage impide la conversión boxing mediante métodos de extensión y campos Action estáticos con parámetros fuertemente tipados.
• Los métodos de extensión del registrador deben analizar la plantilla de mensaje (cadena de formato con nombre) cada vez que se escribe un mensaje de registro. LoggerMessage solo necesita analizar una vez una plantilla cuando se define el mensaje.

En la aplicación de ejemplo se muestran características LoggerMessage con un servicio de trabajo de procesamiento de cola prioritario. La aplicación procesa los elementos de trabajo en orden de prioridad. A medida que se producen estas operaciones, los mensajes de registro se generan mediante el LoggerMessage patrón .

Definición de un mensaje de registrador

Use Define(LogLevel, EventId, String) para crear un Action delegado para registrar un mensaje. Las sobrecargas Define permiten pasar hasta seis parámetros de tipo a una cadena de formato con nombre (plantilla).

La cadena proporcionada al Define método es una plantilla y no una cadena interpolada. Los marcadores de posición se rellenan en el orden en que se especifican los tipos. Los nombres de marcador de posición en la plantilla deben ser descriptivos y coherentes a lo largo de las plantillas. Sirven como nombres de propiedad dentro de los datos de registro estructurados. Se recomienda el uso de la grafía Pascal para los nombres de los marcadores de posición. Por ejemplo, {Item}, {DateTime}.

Cada mensaje de registro es un delegado Action que se mantiene en un campo estático creado por LoggerMessage.Define. Por ejemplo, la aplicación de ejemplo crea un campo para describir un mensaje de registro para el procesamiento de elementos de trabajo:

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Para Action, especifique:

• El nivel de registro.
• Identificador de evento único (EventId) con el nombre del método de extensión estática.
• La plantilla de mensaje (cadena de formato con nombre).

A medida que los elementos de trabajo se quitan de la cola para el procesamiento, la aplicación de servicio de trabajo establece lo siguiente:

• El nivel de registro en LogLevel.Critical.
• El identificador de evento en 13 con el nombre del método FailedToProcessWorkItem.
• La plantilla de mensaje (cadena de formato con nombre) en una cadena.

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

El LoggerMessage.Define método se usa para configurar y definir un Action delegado, que representa un mensaje de registro.

Los almacenes de registro estructurado pueden usar el nombre de evento cuando se suministra con el identificador de evento para enriquecer el registro. Por ejemplo, Serilog usa el nombre del evento.

El delegado Action se invoca mediante un método de extensión fuertemente tipado. El PriorityItemProcessed método registra un mensaje cada vez que se procesa un elemento de trabajo. FailedToProcessWorkItem se llama si y cuando ocurre una excepción.

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);
        }
    }
}

Inspeccione la salida de la consola de la aplicación:

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 pasar parámetros a un mensaje de registro, defina hasta seis tipos al crear el campo estático. La aplicación de ejemplo registra los detalles del elemento de trabajo al procesar elementos definiendo un WorkItem tipo para el Action campo:

private static readonly Action<ILogger, WorkItem, Exception> s_processingPriorityItem;

La plantilla de mensaje de registro del delegado recibe sus valores de marcador de posición a partir de los tipos proporcionados. La aplicación de ejemplo define un delegado para agregar un elemento de trabajo donde el parámetro item es un WorkItem:

s_processingPriorityItem = LoggerMessage.Define<WorkItem>(
    LogLevel.Information,
    new EventId(1, nameof(PriorityItemProcessed)),
    "Processing priority item: {Item}");

El método de extensión estática para registrar que se está procesando un elemento de trabajo, PriorityItemProcessed, recibe el valor del argumento del elemento de trabajo y lo pasa al Action delegado:

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

En el método ExecuteAsync del servicio de trabajo, se llama a PriorityItemProcessed para registrar el mensaje:

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);
        }
    }
}

Inspeccione la salida de la consola de la aplicación:

info: WorkerServiceOptions.Example.Worker[1]
      Processing priority item: Priority-Extreme (50db062a-9732-4418-936d-110549ad79e4): 'Verify communications'

Definición del ámbito del mensaje del registrador

El método DefineScope(string) crea un Func<TResult> delegado para definir un ámbito de registro. Las sobrecargas DefineScope permiten pasar hasta seis parámetros de tipo a una cadena de formato con nombre (plantilla).

Como sucede con el Define método , la cadena proporcionada al DefineScope método es una plantilla y no una cadena interpolada. Los marcadores de posición se rellenan en el orden en que se especifican los tipos. Los nombres de marcador de posición en la plantilla deben ser descriptivos y coherentes a lo largo de las plantillas. Sirven como nombres de propiedad dentro de los datos de registro estructurados. Se recomienda el uso de la grafía Pascal para los nombres de los marcadores de posición. Por ejemplo, {Item}, {DateTime}.

Defina un ámbito de registro para aplicar a una serie de mensajes de registro usando el método DefineScope. Habilite IncludeScopes en la sección del registrador de la consola de appsettings.json:

{
    "Logging": {
        "Console": {
            "IncludeScopes": true
        },
        "LogLevel": {
            "Default": "Information",
            "Microsoft": "Warning",
            "Microsoft.Hosting.Lifetime": "Information"
        }
    }
}

Para crear un ámbito de registro, agregue un campo para que contenga un delegado Func<TResult> para el ámbito. La aplicación de ejemplo crea un campo denominado s_processingWorkScope (Interno/LoggerExtensions.cs):

private static readonly Func<ILogger, DateTime, IDisposable?> s_processingWorkScope;

Use DefineScope para crear el delegado. Se pueden especificar hasta seis tipos para usarlos como argumentos de plantilla cuando se invoca el delegado. La aplicación de ejemplo usa una plantilla de mensaje que incluye la fecha y hora en la que se inició el procesamiento:

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

Proporcione un método de extensión estática para el mensaje de registro. Incluya los parámetros de tipo para las propiedades con nombre que aparecen en la plantilla de mensaje. La aplicación de ejemplo adopta DateTime para una marca de tiempo personalizada para el registro y devuelve _processingWorkScope:

public static IDisposable? ProcessingWorkScope(
    this ILogger logger, DateTime time) =>
    s_processingWorkScope(logger, time);

El ámbito encapsula las llamadas a la extensión de registro en un bloque 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);
        }
    }
}

Inspeccione los mensajes de registro en la salida de la consola de la aplicación. El resultado siguiente muestra el orden de prioridad de los mensajes de registro con el mensaje de ámbito de registro incluido:

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...

Optimizaciones de nivel de registro con protección

Otra optimización del rendimiento se puede realizar comprobando LogLevel y ILogger.IsEnabled(LogLevel) antes de invocar al método correspondiente Log*. Cuando el registro no está configurado para el valor LogLevel proporcionado, las afirmaciones siguientes son ciertas:

• No se llama a ILogger.Log.
• Se evita una asignación de object[] que representa los parámetros.
• Se evita la conversión boxing de tipo de valor.

Para obtener más información:

• Micro benchmarks en el entorno de ejecución de .NET
• Antecedentes y motivación para las comprobaciones de nivel de registro

Consulte también

• Registro en .NET