Skip to content

Commit

Permalink
LoggerMessage updates for 3.0 (#14021)
Browse files Browse the repository at this point in the history
  • Loading branch information
guardrex committed Aug 26, 2019
1 parent 443289f commit a68e43d
Show file tree
Hide file tree
Showing 19 changed files with 692 additions and 12 deletions.
174 changes: 172 additions & 2 deletions aspnetcore/fundamentals/logging/loggermessage.md
Original file line number Diff line number Diff line change
Expand Up @@ -5,21 +5,189 @@ description: Learn how to use LoggerMessage to create cacheable delegates that r
monikerRange: '>= aspnetcore-2.1'
ms.author: riande
ms.custom: mvc
ms.date: 04/24/2019
ms.date: 08/26/2019
uid: fundamentals/logging/loggermessage
---
# High-performance logging with LoggerMessage in ASP.NET Core

By [Luke Latham](https://github.com/guardrex)

::: moniker range=">= aspnetcore-3.0"

<xref:Microsoft.Extensions.Logging.LoggerMessage> features create cacheable delegates that require fewer object allocations and reduced computational overhead compared to [logger extension methods](xref:Microsoft.Extensions.Logging.LoggerExtensions), such as <xref:Microsoft.Extensions.Logging.LoggerExtensions.LogInformation*> and <xref:Microsoft.Extensions.Logging.LoggerExtensions.LogDebug*>. For high-performance logging scenarios, use the <xref:Microsoft.Extensions.Logging.LoggerMessage> pattern.

<xref:Microsoft.Extensions.Logging.LoggerMessage> provides the following performance advantages over Logger extension methods:

* Logger extension methods require "boxing" (converting) value types, such as `int`, into `object`. The <xref:Microsoft.Extensions.Logging.LoggerMessage> pattern avoids boxing by using static <xref:System.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. <xref:Microsoft.Extensions.Logging.LoggerMessage> only requires parsing a template once when the message is defined.

[View or download sample code](https://github.com/aspnet/AspNetCore.Docs/tree/master/aspnetcore/fundamentals/logging/loggermessage/samples/2.x/LoggerMessageSample) ([how to download](xref:index#how-to-download-a-sample))
[View or download sample code](https://github.com/aspnet/AspNetCore.Docs/tree/master/aspnetcore/fundamentals/logging/loggermessage/samples/) ([how to download](xref:index#how-to-download-a-sample))

The sample app demonstrates <xref:Microsoft.Extensions.Logging.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 <xref:Microsoft.Extensions.Logging.LoggerMessage> pattern.

## LoggerMessage.Define

[Define(LogLevel, EventId, String)](xref:Microsoft.Extensions.Logging.LoggerMessage.Define*) creates an <xref:System.Action> delegate for logging a message. <xref:Microsoft.Extensions.Logging.LoggerMessage.Define*> overloads permit passing up to six type parameters to a named format string (template).

The string provided to the <xref:Microsoft.Extensions.Logging.LoggerMessage.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](/dotnet/standard/design-guidelines/capitalization-conventions) for placeholder names. For example, `{Count}`, `{FirstName}`.

Each log message is an <xref:System.Action> held in a static field created by [LoggerMessage.Define](xref:Microsoft.Extensions.Logging.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*):

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Internal/LoggerExtensions.cs?name=snippet1)]

For the <xref:System.Action>, specify:

* The log level.
* A unique event identifier (<xref:Microsoft.Extensions.Logging.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.

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Internal/LoggerExtensions.cs?name=snippet5)]

Structured logging stores may use the event name when it's supplied with the event id to enrich logging. For example, [Serilog](https://github.com/serilog/serilog-extensions-logging) uses the event name.

The <xref:System.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:

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Internal/LoggerExtensions.cs?name=snippet9)]

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

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Pages/Index.cshtml.cs?name=snippet2&highlight=3)]

Inspect the app's console output:

```console
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 <xref:System.Action> field:

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Internal/LoggerExtensions.cs?name=snippet2)]

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`:

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Internal/LoggerExtensions.cs?name=snippet6)]

The static extension method for adding a quote, `QuoteAdded`, receives the quote argument value and passes it to the <xref:System.Action> delegate:

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Internal/LoggerExtensions.cs?name=snippet10)]

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

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Pages/Index.cshtml.cs?name=snippet3&highlight=6)]

Inspect the app's console output:

```console
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 [try&ndash;catch](/dotnet/csharp/language-reference/keywords/try-catch) 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*):

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Internal/LoggerExtensions.cs?name=snippet3)]

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Internal/LoggerExtensions.cs?name=snippet7)]

Note how the exception is passed to the delegate in `QuoteDeleteFailed`:

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Internal/LoggerExtensions.cs?name=snippet11)]

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 <xref:System.ArgumentNullException> is thrown. The exception is trapped by the [try&ndash;catch](/dotnet/csharp/language-reference/keywords/try-catch) statement and logged by calling the `QuoteDeleteFailed` method on the logger in the [catch](/dotnet/csharp/language-reference/keywords/try-catch) block (*Pages/Index.cshtml.cs*):

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Pages/Index.cshtml.cs?name=snippet5&highlight=9,13)]

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

```console
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:

```console
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)](xref:Microsoft.Extensions.Logging.LoggerMessage.DefineScope*) creates a <xref:System.Func%601> delegate for defining a [log scope](xref:fundamentals/logging/index#log-scopes). <xref:Microsoft.Extensions.Logging.LoggerMessage.DefineScope*> overloads permit passing up to three type parameters to a named format string (template).

As is the case with the <xref:Microsoft.Extensions.Logging.LoggerMessage.Define*> method, the string provided to the <xref:Microsoft.Extensions.Logging.LoggerMessage.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](/dotnet/standard/design-guidelines/capitalization-conventions) for placeholder names. For example, `{Count}`, `{FirstName}`.

Define a [log scope](xref:fundamentals/logging/index#log-scopes) to apply to a series of log messages using the <xref:Microsoft.Extensions.Logging.LoggerMessage.DefineScope*> 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*:

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/appsettings.json?highlight=3-5)]

To create a log scope, add a field to hold a <xref:System.Func%601> delegate for the scope. The sample app creates a field called `_allQuotesDeletedScope` (*Internal/LoggerExtensions.cs*):

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Internal/LoggerExtensions.cs?name=snippet4)]

Use <xref:Microsoft.Extensions.Logging.LoggerMessage.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):

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Internal/LoggerExtensions.cs?name=snippet8)]

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`:

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Internal/LoggerExtensions.cs?name=snippet12)]

The scope wraps the logging extension calls in a [using](/dotnet/csharp/language-reference/keywords/using-statement) block:

[!code-csharp[](loggermessage/samples/3.x/LoggerMessageSample/Pages/Index.cshtml.cs?name=snippet4&highlight=5-6,14)]

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

```console
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)
```

::: moniker-end

::: moniker range="< aspnetcore-3.0"

<xref:Microsoft.Extensions.Logging.LoggerMessage> features create cacheable delegates that require fewer object allocations and reduced computational overhead compared to [logger extension methods](xref:Microsoft.Extensions.Logging.LoggerExtensions), such as <xref:Microsoft.Extensions.Logging.LoggerExtensions.LogInformation*> and <xref:Microsoft.Extensions.Logging.LoggerExtensions.LogDebug*>. For high-performance logging scenarios, use the <xref:Microsoft.Extensions.Logging.LoggerMessage> pattern.

<xref:Microsoft.Extensions.Logging.LoggerMessage> provides the following performance advantages over Logger extension methods:

* Logger extension methods require "boxing" (converting) value types, such as `int`, into `object`. The <xref:Microsoft.Extensions.Logging.LoggerMessage> pattern avoids boxing by using static <xref:System.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. <xref:Microsoft.Extensions.Logging.LoggerMessage> only requires parsing a template once when the message is defined.

[View or download sample code](https://github.com/aspnet/AspNetCore.Docs/tree/master/aspnetcore/fundamentals/logging/loggermessage/samples/) ([how to download](xref:index#how-to-download-a-sample))

The sample app demonstrates <xref:Microsoft.Extensions.Logging.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 <xref:Microsoft.Extensions.Logging.LoggerMessage> pattern.

Expand Down Expand Up @@ -176,6 +344,8 @@ info: LoggerMessageSample.Pages.IndexModel[4]
Quote deleted (Quote = 'Quote 3' Id = 4)
```

::: moniker-end

## Additional resources

* [Logging](xref:fundamentals/logging/index)
Original file line number Diff line number Diff line change
Expand Up @@ -109,16 +109,15 @@ Quote deleted (Quote = 'Quote 3' Id = 3)</code></pre>
</li>
<li>
Select the <b>Delete (Id = 999)</b> button and examine the console log for the message, which includes the <code>ArgumentNullException</code>.
<pre><code>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
&lt;PATH&gt;\sample\Pages\Index.cshtml.cs:line 87</code></pre>
<pre><code>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</code></pre>
</li>
</ol>
<button type="submit" class="btn btn-danger" style="margin-bottom:2px" asp-page-handler="DeleteQuote" asp-route-id="999">Delete (Id = 999)</button>
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,14 @@
using Microsoft.EntityFrameworkCore;

namespace LoggerMessageSample.Data
{
public class AppDbContext : DbContext
{
public AppDbContext(DbContextOptions options)
: base(options)
{
}

public DbSet<Quote> Quotes { get; set; }
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,8 @@
namespace LoggerMessageSample.Data
{
public class Quote
{
public int Id { get; set; }
public string Text { get; set; }
}
}

0 comments on commit a68e43d

Please sign in to comment.