Registro de alto rendimiento en .NET

Artículo
04/11/2024

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

LoggerMessage proporciona las siguientes ventajas de rendimiento frente a 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.

Importante

En lugar de usar la clase LoggerMessage para crear registros de alto rendimiento, puede usar el atributo LoggerMessage en .NET 6 y versiones posteriores. LoggerMessageAttribute proporciona la compatibilidad con el registro de generación de origen diseñada para ofrecer una solución de registro altamente utilizable y de alto rendimiento para las aplicaciones .NET modernas. Para más información, consulte Generación de origen de registro en tiempo de compilación (principios básicos de .NET).

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 por orden de prioridad. A medida que se producen estas operaciones, se generan mensajes de registro mediante el patrón LoggerMessage.

Sugerencia

Todo el código fuente del ejemplo de registro está disponible en el Explorador de ejemplos para su descarga. Para obtener más información, consulte Examinación de ejemplos de código: registro en .NET.

Definición de un mensaje del registrador

Use Define(LogLevel, EventId, String) para crear un delegado Action 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 método Define 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 los marcadores de posición en la plantilla deben ser descriptivos y coherentes entre las plantillas. Sirven como nombres de propiedad en los datos estructurados del registro. 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 procesar los elementos de trabajo:

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Especifique lo siguiente para el delegado Action:

El nivel de registro.
Un identificador de evento único (EventId) con el nombre del método de extensión estático.
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 método LoggerMessage.Define se usa para configurar y definir un delegado Action, 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 de evento.

El delegado Action se invoca mediante un método de extensión fuertemente tipado. El método PriorityItemProcessed registra un mensaje cada vez que se procesa un elemento de trabajo. A FailedToProcessWorkItem se llama cuando produce 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 los elementos definiendo un tipo WorkItem para el campo Action:

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 cuando el parámetro del elemento es WorkItem:

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

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

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 delegado Func<TResult> 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).

Al igual que sucede con el método Define, la cadena proporcionada al método DefineScope 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 los marcadores de posición en la plantilla deben ser descriptivos y coherentes entre las plantillas. Sirven como nombres de propiedad en los datos estructurados del registro. 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 aplicarlo a una serie de mensajes de registro mediante 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 (Internal/LoggerExtensions.cs):

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

Use DefineScope para crear el delegado. Pueden especificarse 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 que se inició el procesamiento:

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

Proporcione un método de extensión estático para el mensaje de registro. Incluya todos los parámetros de tipo para propiedades con nombre que aparezcan 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

Se puede realizar otra optimización de rendimiento mediante la comprobación de LogLevel, con ILogger.IsEnabled(LogLevel) antes de una invocación al método Log* correspondiente. 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:

Vea también

Registro en .NET

Compartir a través de

Registro de alto rendimiento en .NET

Definición de un mensaje del registrador

Definición del ámbito del mensaje del registrador

Optimizaciones de nivel de registro con protección

Vea también

Recursos adicionales