High-performance logging with LoggerMessage in ASP.NET Core

By Luke Latham

LoggerMessage features create cacheable delegates that require fewer object allocations and reduced computational overhead compared to logger extension methods, such as LogInformation, LogDebug, and LogError. For high-performance logging scenarios, use the LoggerMessage pattern.

LoggerMessage provides the following performance advantages over Logger extension methods:

  • Logger extension methods require "boxing" (converting) value types, such as int, into object. The LoggerMessage pattern avoids boxing by using static Action fields and extension methods with strongly-typed parameters.
  • Logger extension methods must parse the message template (named format string) every time a log message is written. LoggerMessage only requires parsing a template once when the message is defined.

View or download sample code (how to download)

The sample app demonstrates LoggerMessage features with a basic quote tracking system. The app adds and deletes quotes using an in-memory database. As these operations occur, log messages are generated using the LoggerMessage pattern.

LoggerMessage.Define

Define(LogLevel, EventId, String) creates an Action delegate for logging a message. Define overloads permit passing up to six type parameters to a named format string (template).

The string provided to the Define method is a template and not an interpolated string. Placeholders are filled in the order that the types are specified. Placeholder names in the template should be descriptive and consistent across templates. They serve as property names within structured log data. We recommend Pascal casing for placeholder names. For example, {Count}, {FirstName}.

Each log message is an Action held in a static field created by LoggerMessage.Define. For example, the sample app creates a field to describe a log message for a GET request for the Index page (Internal/LoggerExtensions.cs):

private static readonly Action<ILogger, Exception> _indexPageRequested;

For the Action, specify:

  • The log level.
  • A unique event identifier (EventId) with the name of the static extension method.
  • The message template (named format string).

A request for the Index page of the sample app sets the:

  • Log level to Information.
  • Event id to 1 with the name of the IndexPageRequested method.
  • Message template (named format string) to a string.
_indexPageRequested = LoggerMessage.Define(
    LogLevel.Information, 
    new EventId(1, nameof(IndexPageRequested)), 
    "GET request for Index page");

Structured logging stores may use the event name when it's supplied with the event id to enrich logging. For example, Serilog uses the event name.

The Action is invoked through a strongly-typed extension method. The IndexPageRequested method logs a message for an Index page GET request in the sample app:

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

IndexPageRequested is called on the logger in the OnGetAsync method in Pages/Index.cshtml.cs:

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

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

Inspect the app's console output:

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

To pass parameters to a log message, define up to six types when creating the static field. The sample app logs a string when adding a quote by defining a string type for the Action field:

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

The delegate's log message template receives its placeholder values from the types provided. The sample app defines a delegate for adding a quote where the quote parameter is a string:

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

The static extension method for adding a quote, QuoteAdded, receives the quote argument value and passes it to the Action delegate:

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

In the Index page's page model (Pages/Index.cshtml.cs), QuoteAdded is called to log the message:

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

    _logger.QuoteAdded(Quote.Text);

    return RedirectToPage();
}

Inspect the app's console output:

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

The sample app implements a trycatch pattern for quote deletion. An informational message is logged for a successful delete operation. An error message is logged for a delete operation when an exception is thrown. The log message for the unsuccessful delete operation includes the exception stack trace (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})");

Note how the exception is passed to the delegate in 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);
}

In the page model for the Index page, a successful quote deletion calls the QuoteDeleted method on the logger. When a quote isn't found for deletion, an ArgumentNullException is thrown. The exception is trapped by the trycatch statement and logged by calling the QuoteDeleteFailed method on the logger in the catch block (Pages/Index.cshtml.cs):

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

When a quote is successfully deleted, inspect the app's console output:

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)

When quote deletion fails, inspect the app's console output. Note that the exception is included in the log message:

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

DefineScope(String) creates a Func delegate for defining a log scope. DefineScope overloads permit passing up to three type parameters to a named format string (template).

As is the case with the Define method, the string provided to the DefineScope method is a template and not an interpolated string. Placeholders are filled in the order that the types are specified. Placeholder names in the template should be descriptive and consistent across templates. They serve as property names within structured log data. We recommend Pascal casing for placeholder names. For example, {Count}, {FirstName}.

Define a log scope to apply to a series of log messages using the DefineScope(String) method.

The sample app has a Clear All button for deleting all of the quotes in the database. The quotes are deleted by removing them one at a time. Each time a quote is deleted, the QuoteDeleted method is called on the logger. A log scope is added to these log messages.

Enable IncludeScopes in the console logger section of appsettings.json:

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

To create a log scope, add a field to hold a Func delegate for the scope. The sample app creates a field called _allQuotesDeletedScope (Internal/LoggerExtensions.cs):

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

Use DefineScope to create the delegate. Up to three types can be specified for use as template arguments when the delegate is invoked. The sample app uses a message template that includes the number of deleted quotes (an int type):

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

Provide a static extension method for the log message. Include any type parameters for named properties that appear in the message template. The sample app takes in a count of quotes to delete and returns _allQuotesDeletedScope:

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

The scope wraps the logging extension calls in a using block:

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

Inspect the log messages in the app's console output. The following result shows three quotes deleted with the log scope message included:

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)

Additional resources