24 KiB
| title | author | description | monikerRange | ms.author | ms.custom | ms.date | uid |
|---|---|---|---|---|---|---|---|
| High-performance logging with LoggerMessage in ASP.NET Core | rick-anderson | Learn how to use LoggerMessage to create cacheable delegates that require fewer object allocations for high-performance logging scenarios. | >= aspnetcore-2.1 | riande | mvc | 08/26/2019 | fundamentals/logging/loggermessage |
High-performance logging with LoggerMessage in ASP.NET Core
:::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, 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, intoobject. 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 (how to download)
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) 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 for placeholder names. For example, {Count}, {FirstName}.
Each log message is an xref:System.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):
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
1with the name of theIndexPageRequestedmethod. - Message template (named format string) to a string.
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 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:
IndexPageRequested is called on the logger in the OnGetAsync method in Pages/Index.cshtml.cs:
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 xref:System.Action field:
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:
The static extension method for adding a quote, QuoteAdded, receives the quote argument value and passes it to the xref:System.Action delegate:
In the Index page's page model (Pages/Index.cshtml.cs), QuoteAdded is called to log the message:
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 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):
Note how the exception is passed to the delegate in QuoteDeleteFailed:
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-catch statement and logged by calling the QuoteDeleteFailed method on the logger in the catch block (Pages/Index.cshtml.cs):
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:
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) creates a xref:System.Func%601 delegate for defining a log scope. 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 for placeholder names. For example, {Count}, {FirstName}.
Define a log scope 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:
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):
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):
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:
The scope wraps the logging extension calls in a using block:
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)
:::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, 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, intoobject. 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 (how to download)
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) 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 for placeholder names. For example, {Count}, {FirstName}.
Each log message is an xref:System.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):
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
1with the name of theIndexPageRequestedmethod. - Message template (named format string) to a string.
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 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:
IndexPageRequested is called on the logger in the OnGetAsync method in Pages/Index.cshtml.cs:
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 xref:System.Action field:
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:
The static extension method for adding a quote, QuoteAdded, receives the quote argument value and passes it to the xref:System.Action delegate:
In the Index page's page model (Pages/Index.cshtml.cs), QuoteAdded is called to log the message:
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 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):
Note how the exception is passed to the delegate in QuoteDeleteFailed:
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-catch statement and logged by calling the QuoteDeleteFailed method on the logger in the catch block (Pages/Index.cshtml.cs):
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 xref:System.Func%601 delegate for defining a log scope. 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 for placeholder names. For example, {Count}, {FirstName}.
Define a log scope 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:
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):
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):
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:
The scope wraps the logging extension calls in a using block:
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)
:::moniker-end