Registro de alto rendimiento con LoggerMessage en ASP.NET Core

Artículo
08/17/2021
8 minutos para leer

Las características de LoggerMessage crean 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.

Vea o descargue el código de ejemplo (cómo descargarlo)

La aplicación de ejemplo muestra las características de LoggerMessage con un sistema de seguimiento de citas básico. La aplicación agrega y elimina citas mediante una base de datos en memoria. A medida que se producen estas operaciones, se generan mensajes de registro mediante el patrón LoggerMessage.

LoggerMessage.Define

Define(LogLevel, EventId, String) crea 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: {Count}, {FirstName}.

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 que describe un mensaje de registro para una solicitud GET para la página de índice (Internal/LoggerExtensions.cs):

private static readonly Action<ILogger, Exception> _indexPageRequested;

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

Una solicitud para la página de índice de la aplicación de ejemplo establece:

El nivel de registro en Information.
El identificador de evento en 1 con el nombre del método IndexPageRequested.
La plantilla de mensaje (cadena de formato con nombre) en una cadena.

_indexPageRequested = LoggerMessage.Define(
    LogLevel.Information, 
    new EventId(1, nameof(IndexPageRequested)), 
    "GET request for Index page");

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 IndexPageRequested registra un mensaje para una solicitud GET de página de índice en la aplicación de ejemplo:

public static void IndexPageRequested(this ILogger logger)
{
    _indexPageRequested(logger, null);
}

Se llama a IndexPageRequested en el registrador en el método OnGetAsync en Pages/Index.cshtml.cs:

public async Task OnGetAsync()
{
    _logger.IndexPageRequested();

    Quotes = await _db.Quotes.AsNoTracking().ToListAsync();
}

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

info: LoggerMessageSample.Pages.IndexModel[1]
      => RequestId:0HL90M6E7PHK4:00000001 RequestPath:/ => /Index
      GET request for Index page

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 una cadena cuando se agrega una cita. Para ello, define un tipo string para el campo Action:

private static readonly Action<ILogger, string, Exception> _quoteAdded;

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 una cita cuando el parámetro de la cita es string:

_quoteAdded = LoggerMessage.Define<string>(
    LogLevel.Information, 
    new EventId(2, nameof(QuoteAdded)), 
    "Quote added (Quote = '{Quote}')");

El método de extensión estático para agregar una cita, QuoteAdded, recibe el valor de argumento de la cita y lo pasa al delegado Action:

public static void QuoteAdded(this ILogger logger, string quote)
{
    _quoteAdded(logger, quote, null);
}

En el modelo de página para la página de índice (Pages/Index.cshtml.cs), se llama a QuoteAdded para registrar el mensaje:

public async Task<IActionResult> OnPostAddQuoteAsync()
{
    _db.Quotes.Add(Quote);
    await _db.SaveChangesAsync();

    _logger.QuoteAdded(Quote.Text);

    return RedirectToPage();
}

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

info: LoggerMessageSample.Pages.IndexModel[2]
      => RequestId:0HL90M6E7PHK5:0000000A RequestPath:/ => /Index
      Quote added (Quote = 'You can avoid reality, but you cannot avoid the 
          consequences of avoiding reality. - Ayn Rand')

La aplicación de ejemplo implementa un patrón try-catch para la eliminación de la cita. Se registra un mensaje informativo si se realiza correctamente una operación de eliminación. Se registra un mensaje de error para una operación de eliminación si se produce una excepción. El mensaje de registro de la operación de eliminación con error incluye el seguimiento de la pila de excepciones (Internal/LoggerExtensions.cs):

private static readonly Action<ILogger, string, int, Exception> _quoteDeleted;
private static readonly Action<ILogger, int, Exception> _quoteDeleteFailed;

_quoteDeleted = LoggerMessage.Define<string, int>(
    LogLevel.Information, 
    new EventId(4, nameof(QuoteDeleted)), 
    "Quote deleted (Quote = '{Quote}' Id = {Id})");

_quoteDeleteFailed = LoggerMessage.Define<int>(
    LogLevel.Error, 
    new EventId(5, nameof(QuoteDeleteFailed)), 
    "Quote delete failed (Id = {Id})");

Observe cómo se pasa la excepción al delegado en QuoteDeleteFailed:

public static void QuoteDeleted(this ILogger logger, string quote, int id)
{
    _quoteDeleted(logger, quote, id, null);
}

public static void QuoteDeleteFailed(this ILogger logger, int id, Exception ex)
{
    _quoteDeleteFailed(logger, id, ex);
}

En el modelo de página para la página de índice, una operación correcta de eliminación de cita llama al método QuoteDeleted en el registrador. Cuando no se encuentra una cita para su eliminación, se produce una excepción ArgumentNullException. La excepción se captura mediante la instrucción try-catch y se registra mediante una llamada al método QuoteDeleteFailed en el registrador en el bloque catch block (Pages/Index.cshtml.cs):

public async Task<IActionResult> OnPostDeleteQuoteAsync(int id)
{
    try
    {
        var quote = await _db.Quotes.FindAsync(id);
        _db.Quotes.Remove(quote);
        await _db.SaveChangesAsync();

        _logger.QuoteDeleted(quote.Text, id);
    }
    catch (NullReferenceException ex)
    {
        _logger.QuoteDeleteFailed(id, ex);
    }

    return RedirectToPage();
}

Cuando se elimine correctamente una cita, inspeccione la salida de la consola de la aplicación:

info: LoggerMessageSample.Pages.IndexModel[4]
      => RequestId:0HL90M6E7PHK5:00000016 RequestPath:/ => /Index
      Quote deleted (Quote = 'You can avoid reality, but you cannot avoid the 
          consequences of avoiding reality. - Ayn Rand' Id = 1)

Cuando se produzca un error en la eliminación de una cita, inspeccione la salida de la consola de la aplicación. Tenga en cuenta que la excepción se incluye en el mensaje del registro:

LoggerMessageSample.Pages.IndexModel: Error: Quote delete failed (Id = 999)

System.NullReferenceException: Object reference not set to an instance of an object.
   at lambda_method(Closure , ValueBuffer )
   at System.Linq.Enumerable.SelectEnumerableIterator`2.MoveNext()
   at Microsoft.EntityFrameworkCore.InMemory.Query.Internal.InMemoryShapedQueryCompilingExpressionVisitor.AsyncQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()
   at Microsoft.EntityFrameworkCore.Query.ShapedQueryCompilingExpressionVisitor.SingleOrDefaultAsync[TSource](IAsyncEnumerable`1 asyncEnumerable, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.ShapedQueryCompilingExpressionVisitor.SingleOrDefaultAsync[TSource](IAsyncEnumerable`1 asyncEnumerable, CancellationToken cancellationToken)
   at LoggerMessageSample.Pages.IndexModel.OnPostDeleteQuoteAsync(Int32 id) in c:\Users\guard\Documents\GitHub\Docs\aspnetcore\fundamentals\logging\loggermessage\samples\3.x\LoggerMessageSample\Pages\Index.cshtml.cs:line 77

LoggerMessage.DefineScope

DefineScope(String) crea un delegado Func<TResult> para definir un ámbito de registro. Las sobrecargas DefineScope permiten pasar hasta tres 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: {Count}, {FirstName}.

Defina un ámbito de registro para aplicarlo a una serie de mensajes de registro mediante el método DefineScope.

La aplicación de ejemplo tiene un botón Borrar todo para eliminar todas las citas de la base de datos. Para eliminar las citas, se van quitando de una en una. Cada vez que se elimina una cita, se llama al método QuoteDeleted en el registrador. Se agrega un ámbito de registro a estos mensajes de registro.

Habilite IncludeScopes en la sección del registrador de consola de appsettings.json :

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

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 _allQuotesDeletedScope (Internal/LoggerExtensions.cs):

private static Func<ILogger, int, IDisposable> _allQuotesDeletedScope;

Use DefineScope para crear el delegado. Pueden especificarse hasta tres tipos para usarlos como argumentos de plantilla cuando se invoca el delegado. La aplicación de ejemplo usa una plantilla de mensaje que incluye el número de citas eliminadas (un tipo int):

_allQuotesDeletedScope = 
    LoggerMessage.DefineScope<int>("All quotes deleted (Count = {Count})");

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 toma un valor de número count de citas que se van a eliminar y devuelve _allQuotesDeletedScope:

public static IDisposable AllQuotesDeletedScope(
    this ILogger logger, int count)
{
    return _allQuotesDeletedScope(logger, count);
}

El ámbito encapsula las llamadas a la extensión de registro en un bloque using:

public async Task<IActionResult> OnPostDeleteAllQuotesAsync()
{
    var quoteCount = await _db.Quotes.CountAsync();

    using (_logger.AllQuotesDeletedScope(quoteCount))
    {
        foreach (Quote quote in _db.Quotes)
        {
            _db.Quotes.Remove(quote);

            _logger.QuoteDeleted(quote.Text, quote.Id);
        }
        await _db.SaveChangesAsync();
    }

    return RedirectToPage();
}

Inspeccione los mensajes de registro en la salida de la consola de la aplicación. En el resultado siguiente se muestran tres citas eliminadas con el mensaje del ámbito de registro incluido:

info: LoggerMessageSample.Pages.IndexModel[4]
      => RequestId:0HL90M6E7PHK5:0000002E RequestPath:/ => /Index => 
          All quotes deleted (Count = 3)
      Quote deleted (Quote = 'Quote 1' Id = 2)
info: LoggerMessageSample.Pages.IndexModel[4]
      => RequestId:0HL90M6E7PHK5:0000002E RequestPath:/ => /Index => 
          All quotes deleted (Count = 3)
      Quote deleted (Quote = 'Quote 2' Id = 3)
info: LoggerMessageSample.Pages.IndexModel[4]
      => RequestId:0HL90M6E7PHK5:0000002E RequestPath:/ => /Index => 
          All quotes deleted (Count = 3)
      Quote deleted (Quote = 'Quote 3' Id = 4)

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.

Vea o descargue el código de ejemplo (cómo descargarlo)

LoggerMessage.Define

private static readonly Action<ILogger, Exception> _indexPageRequested;

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

Una solicitud para la página de índice de la aplicación de ejemplo establece:

El nivel de registro en Information.
El identificador de evento en 1 con el nombre del método IndexPageRequested.
La plantilla de mensaje (cadena de formato con nombre) en una cadena.

_indexPageRequested = LoggerMessage.Define(
    LogLevel.Information, 
    new EventId(1, nameof(IndexPageRequested)), 
    "GET request for Index page");

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.

public static void IndexPageRequested(this ILogger logger)
{
    _indexPageRequested(logger, null);
}

Se llama a IndexPageRequested en el registrador en el método OnGetAsync en Pages/Index.cshtml.cs:

public async Task OnGetAsync()
{
    _logger.IndexPageRequested();

    Quotes = await _db.Quotes.AsNoTracking().ToListAsync();
}

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

info: LoggerMessageSample.Pages.IndexModel[1]
      => RequestId:0HL90M6E7PHK4:00000001 RequestPath:/ => /Index
      GET request for Index page

private static readonly Action<ILogger, string, Exception> _quoteAdded;

_quoteAdded = LoggerMessage.Define<string>(
    LogLevel.Information, 
    new EventId(2, nameof(QuoteAdded)), 
    "Quote added (Quote = '{Quote}')");

El método de extensión estático para agregar una cita, QuoteAdded, recibe el valor de argumento de la cita y lo pasa al delegado Action:

public static void QuoteAdded(this ILogger logger, string quote)
{
    _quoteAdded(logger, quote, null);
}

En el modelo de página para la página de índice (Pages/Index.cshtml.cs), se llama a QuoteAdded para registrar el mensaje:

public async Task<IActionResult> OnPostAddQuoteAsync()
{
    _db.Quotes.Add(Quote);
    await _db.SaveChangesAsync();

    _logger.QuoteAdded(Quote.Text);

    return RedirectToPage();
}

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

info: LoggerMessageSample.Pages.IndexModel[2]
      => RequestId:0HL90M6E7PHK5:0000000A RequestPath:/ => /Index
      Quote added (Quote = 'You can avoid reality, but you cannot avoid the 
          consequences of avoiding reality. - Ayn Rand')

private static readonly Action<ILogger, string, int, Exception> _quoteDeleted;
private static readonly Action<ILogger, int, Exception> _quoteDeleteFailed;

_quoteDeleted = LoggerMessage.Define<string, int>(
    LogLevel.Information, 
    new EventId(4, nameof(QuoteDeleted)), 
    "Quote deleted (Quote = '{Quote}' Id = {Id})");

_quoteDeleteFailed = LoggerMessage.Define<int>(
    LogLevel.Error, 
    new EventId(5, nameof(QuoteDeleteFailed)), 
    "Quote delete failed (Id = {Id})");

Observe cómo se pasa la excepción al delegado en QuoteDeleteFailed:

public static void QuoteDeleted(this ILogger logger, string quote, int id)
{
    _quoteDeleted(logger, quote, id, null);
}

public static void QuoteDeleteFailed(this ILogger logger, int id, Exception ex)
{
    _quoteDeleteFailed(logger, id, ex);
}

public async Task<IActionResult> OnPostDeleteQuoteAsync(int id)
{
    var quote = await _db.Quotes.FindAsync(id);

    // DO NOT use this approach in production code!
    // You should check quote to see if it's null before removing 
    // it and saving changes to the database. A try-catch is used 
    // here for demonstration purposes of LoggerMessage features.
    try
    {
        _db.Quotes.Remove(quote);
        await _db.SaveChangesAsync();

        _logger.QuoteDeleted(quote.Text, id);
    }
    catch (ArgumentNullException ex)
    {
        _logger.QuoteDeleteFailed(id, ex);
    }

    return RedirectToPage();
}

Cuando se elimine correctamente una cita, inspeccione la salida de la consola de la aplicación:

info: LoggerMessageSample.Pages.IndexModel[4]
      => RequestId:0HL90M6E7PHK5:00000016 RequestPath:/ => /Index
      Quote deleted (Quote = 'You can avoid reality, but you cannot avoid the 
          consequences of avoiding reality. - Ayn Rand' Id = 1)

Cuando se produzca un error en la eliminación de una cita, inspeccione la salida de la consola de la aplicación. Tenga en cuenta que la excepción se incluye en el mensaje del registro:

fail: LoggerMessageSample.Pages.IndexModel[5]
      => RequestId:0HL90M6E7PHK5:00000010 RequestPath:/ => /Index
      Quote delete failed (Id = 999)
System.ArgumentNullException: Value cannot be null.
Parameter name: entity
   at Microsoft.EntityFrameworkCore.Utilities.Check.NotNull[T]
       (T value, String parameterName)
   at Microsoft.EntityFrameworkCore.DbContext.Remove[TEntity](TEntity entity)
   at Microsoft.EntityFrameworkCore.Internal.InternalDbSet`1.Remove(TEntity entity)
   at LoggerMessageSample.Pages.IndexModel.<OnPostDeleteQuoteAsync>d__14.MoveNext() 
      in <PATH>\sample\Pages\Index.cshtml.cs:line 87

LoggerMessage.DefineScope

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 consola de appsettings.json :

{
  "Logging": {
    "Console": {
      "IncludeScopes": true
    },
    "LogLevel": {
      "Default": "Warning"
    }
  },
  "AllowedHosts": "*"
}

private static Func<ILogger, int, IDisposable> _allQuotesDeletedScope;

_allQuotesDeletedScope = 
    LoggerMessage.DefineScope<int>("All quotes deleted (Count = {Count})");

public static IDisposable AllQuotesDeletedScope(
    this ILogger logger, int count)
{
    return _allQuotesDeletedScope(logger, count);
}

El ámbito encapsula las llamadas a la extensión de registro en un bloque using:

public async Task<IActionResult> OnPostDeleteAllQuotesAsync()
{
    var quoteCount = await _db.Quotes.CountAsync();

    using (_logger.AllQuotesDeletedScope(quoteCount))
    {
        foreach (Quote quote in _db.Quotes)
        {
            _db.Quotes.Remove(quote);

            _logger.QuoteDeleted(quote.Text, quote.Id);
        }
        await _db.SaveChangesAsync();
    }

    return RedirectToPage();
}

Inspeccione los mensajes de registro en la salida de la consola de la aplicación. En el resultado siguiente se muestran tres citas eliminadas con el mensaje del ámbito de registro incluido:

info: LoggerMessageSample.Pages.IndexModel[4]
      => RequestId:0HL90M6E7PHK5:0000002E RequestPath:/ => /Index => 
          All quotes deleted (Count = 3)
      Quote deleted (Quote = 'Quote 1' Id = 2)
info: LoggerMessageSample.Pages.IndexModel[4]
      => RequestId:0HL90M6E7PHK5:0000002E RequestPath:/ => /Index => 
          All quotes deleted (Count = 3)
      Quote deleted (Quote = 'Quote 2' Id = 3)
info: LoggerMessageSample.Pages.IndexModel[4]
      => RequestId:0HL90M6E7PHK5:0000002E RequestPath:/ => /Index => 
          All quotes deleted (Count = 3)
      Quote deleted (Quote = 'Quote 3' Id = 4)

Recursos adicionales

Registro

Registro de alto rendimiento con LoggerMessage en ASP.NET Core

Valore su experiencia

LoggerMessage.Define

LoggerMessage.DefineScope

LoggerMessage.Define

LoggerMessage.DefineScope

Recursos adicionales