高性能日志记录

在 ASP.NET Core 中使用 LoggerMessage 的高性能日志记录

作者:Luke Latham

LoggerMessage 功能创建可缓存的委托,该功能比记录器扩展方法(例如 LogInformationLogDebug)需要的对象分配和计算开销少。 对于高性能日志记录方案,请使用 LoggerMessage 模式。

与记录器扩展方法相比,LoggerMessage 具有以下性能优势:

  • 记录器扩展方法需要将值类型(例如 int)“装箱”(转换)到 object 中。 LoggerMessage 模式使用带强类型参数的静态 Action 字段和扩展方法来避免装箱。
  • 记录器扩展方法每次写入日志消息时必须分析消息模板(命名的格式字符串)。 如果已定义消息,那么 LoggerMessage 只需分析一次模板即可。

查看或下载示例代码如何下载

此示例应用通过基本引号跟踪系统演示 LoggerMessage 功能。 此应用使用内存中数据库添加和删除引号。 发生这些操作时,通过 LoggerMessage 模式生成日志消息。

LoggerMessage.Define

Define(LogLevel、EventId、字符串)创建用于记录消息的 Action 委托。 Define 重载允许向命名的格式字符串(模板)传递最多六个类型参数。

提供给 Define 方法的字符串是一个模板,而不是内插字符串。 占位符按照指定类型的顺序填充。 模板中的占位符名称在各个模板中应当具备描述性和一致性。 它们在结构化的日志数据中充当属性名称。 对于占位符名称,建议使用帕斯卡拼写法 例如:{Count}{FirstName}

每条日志消息都是一个 Action,保存在由 LoggerMessage.Define 创建的静态字段中。 例如,示例应用创建一个字段来为索引页 (Internal/LoggerExtensions.cs ) 描述 GET 请求的日志消息:

private static readonly Action<ILogger, Exception> _indexPageRequested;

对于 Action,指定:

  • 日志级别。
  • 具有静态扩展方法名称的唯一事件标识符 (EventId)。
  • 消息模板(命名的格式字符串)。

对示例应用的索引页的请求设置:

  • 将日志级别设置为 Information
  • 将事件 ID 设置为具有 IndexPageRequested 方法名称的 1
  • 将消息模板(命名的格式字符串)设置为字符串。
_indexPageRequested = LoggerMessage.Define(
    LogLevel.Information, 
    new EventId(1, nameof(IndexPageRequested)), 
    "GET request for Index page");

结构化日志记录存储可以使用事件名称(当它获得事件 ID 时)来丰富日志记录。 例如,Serilog 使用该事件名称。

通过强类型扩展方法调用 Action IndexPageRequested 方法在示例应用中记录索引页 GET 请求的消息:

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

在 Pages/Index.cshtml.cs 的 OnGetAsync 方法中,在记录器上调用 IndexPageRequested

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

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

检查应用的控制台输出:

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

要将参数传递给日志消息,创建静态字段时最多定义六种类型。 通过为 Action 字段定义 string 类型来添加引号时,示例应用会记录一个字符串:

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

委托的日志消息模板从提供的类型接收其占位符值。 示例应用定义一个委托,用于在 quote 参数是 string 的位置添加引号:

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

用于添加引号的静态扩展方法 QuoteAdded 接收 quote 参数值并将其传递给 Action 委托:

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

在索引页的页面模型 (Pages/Index.cshtml.cs ) 中,调用 QuoteAdded 来记录消息:

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

    _logger.QuoteAdded(Quote.Text);

    return RedirectToPage();
}

检查应用的控制台输出:

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

本示例应用实现用于删除引号的 try–catch 模式。 为成功的删除操作记录提示性信息。 引发异常时,为删除操作记录错误消息。 针对未成功的删除操作,日志消息包括异常堆栈跟踪 (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})");

请注意异常如何传递到 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);
}

在索引页的页面模型中,成功删除引号时会在记录器上调用 QuoteDeleted 方法。 如果找不到要删除的引号,则会引发 ArgumentNullException 通过 try–catch 语句捕获异常,并在 catch 块 (Pages/Index.cshtml.cs) 中调用记录器上的 QuoteDeleteFailed 方法来记录异常 :

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

成功删除引号时,检查应用的控制台输出:

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)

引号删除失败时,检查应用的控制台输出。 请注意,异常包括在日志消息中:

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(字符串)创建一个用于定义日志作用域Func<TResult> 委托。 DefineScope 重载允许向命名的格式字符串(模板)传递最多三个类型参数。

Define 方法也一样,提供给 DefineScope 方法的字符串是一个模板,而不是内插字符串。 占位符按照指定类型的顺序填充。 模板中的占位符名称在各个模板中应当具备描述性和一致性。 它们在结构化的日志数据中充当属性名称。 对于占位符名称,建议使用帕斯卡拼写法 例如:{Count}{FirstName}

使用 DefineScope 方法定义一个日志作用域,以应用到一系列日志消息中。

示例应用含有一个“全部清除” 按钮,用于删除数据库中的所有引号。 通过一次删除一个引号来将其删除。 每当删除一个引号时,都会在记录器上调用 QuoteDeleted 方法。 在这些日志消息中会添加一个日志作用域。

在 appsettings.json 的控制台记录器部分启用 IncludeScopes

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

要创建日志作用域,请添加一个字段来保存该作用域的 Func<TResult> 委托。 示例应用创建一个名为 _allQuotesDeletedScope (Internal/LoggerExtensions.cs ) 的字段:

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

使用 DefineScope 来创建委托。 调用委托时最多可以指定三种类型作为模板参数使用。 示例应用使用包含删除的引号数量的消息模板(int 类型):

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

为日志消息提供一种静态扩展方法。 包含已命名属性的任何类型参数(这些参数出现在消息模板中)。 示例应用采用引号的 count,以删除并返回 _allQuotesDeletedScope

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

该作用域将日志记录扩展调用包装在 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();
}

检查应用控制台输出中的日志消息。 以下结果显示删除的三个引号,以及包含的日志作用域消息:

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 功能创建可缓存的委托,该功能比记录器扩展方法(例如 LogInformationLogDebug)需要的对象分配和计算开销少。 对于高性能日志记录方案,请使用 LoggerMessage 模式。

与记录器扩展方法相比,LoggerMessage 具有以下性能优势:

  • 记录器扩展方法需要将值类型(例如 int)“装箱”(转换)到 object 中。 LoggerMessage 模式使用带强类型参数的静态 Action 字段和扩展方法来避免装箱。
  • 记录器扩展方法每次写入日志消息时必须分析消息模板(命名的格式字符串)。 如果已定义消息,那么 LoggerMessage 只需分析一次模板即可。

查看或下载示例代码如何下载

此示例应用通过基本引号跟踪系统演示 LoggerMessage 功能。 此应用使用内存中数据库添加和删除引号。 发生这些操作时,通过 LoggerMessage 模式生成日志消息。

LoggerMessage.Define

Define(LogLevel、EventId、字符串)创建用于记录消息的 Action 委托。 Define 重载允许向命名的格式字符串(模板)传递最多六个类型参数。

提供给 Define 方法的字符串是一个模板,而不是内插字符串。 占位符按照指定类型的顺序填充。 模板中的占位符名称在各个模板中应当具备描述性和一致性。 它们在结构化的日志数据中充当属性名称。 对于占位符名称,建议使用帕斯卡拼写法 例如:{Count}{FirstName}

每条日志消息都是一个 Action,保存在由 LoggerMessage.Define 创建的静态字段中。 例如,示例应用创建一个字段来为索引页 (Internal/LoggerExtensions.cs ) 描述 GET 请求的日志消息:

private static readonly Action<ILogger, Exception> _indexPageRequested;

对于 Action,指定:

  • 日志级别。
  • 具有静态扩展方法名称的唯一事件标识符 (EventId)。
  • 消息模板(命名的格式字符串)。

对示例应用的索引页的请求设置:

  • 将日志级别设置为 Information
  • 将事件 ID 设置为具有 IndexPageRequested 方法名称的 1
  • 将消息模板(命名的格式字符串)设置为字符串。
_indexPageRequested = LoggerMessage.Define(
    LogLevel.Information, 
    new EventId(1, nameof(IndexPageRequested)), 
    "GET request for Index page");

结构化日志记录存储可以使用事件名称(当它获得事件 ID 时)来丰富日志记录。 例如,Serilog 使用该事件名称。

通过强类型扩展方法调用 Action IndexPageRequested 方法在示例应用中记录索引页 GET 请求的消息:

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

在 Pages/Index.cshtml.cs 的 OnGetAsync 方法中,在记录器上调用 IndexPageRequested

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

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

检查应用的控制台输出:

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

要将参数传递给日志消息,创建静态字段时最多定义六种类型。 通过为 Action 字段定义 string 类型来添加引号时,示例应用会记录一个字符串:

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

委托的日志消息模板从提供的类型接收其占位符值。 示例应用定义一个委托,用于在 quote 参数是 string 的位置添加引号:

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

用于添加引号的静态扩展方法 QuoteAdded 接收 quote 参数值并将其传递给 Action 委托:

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

在索引页的页面模型 (Pages/Index.cshtml.cs ) 中,调用 QuoteAdded 来记录消息:

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

    _logger.QuoteAdded(Quote.Text);

    return RedirectToPage();
}

检查应用的控制台输出:

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

本示例应用实现用于删除引号的 try–catch 模式。 为成功的删除操作记录提示性信息。 引发异常时,为删除操作记录错误消息。 针对未成功的删除操作,日志消息包括异常堆栈跟踪 (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})");

请注意异常如何传递到 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);
}

在索引页的页面模型中,成功删除引号时会在记录器上调用 QuoteDeleted 方法。 如果找不到要删除的引号,则会引发 ArgumentNullException 通过 try–catch 语句捕获异常,并在 catch 块 (Pages/Index.cshtml.cs) 中调用记录器上的 QuoteDeleteFailed 方法来记录异常 :

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

成功删除引号时,检查应用的控制台输出:

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)

引号删除失败时,检查应用的控制台输出。 请注意,异常包括在日志消息中:

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(字符串)创建一个用于定义日志作用域Func<TResult> 委托。 DefineScope 重载允许向命名的格式字符串(模板)传递最多三个类型参数。

Define 方法也一样,提供给 DefineScope 方法的字符串是一个模板,而不是内插字符串。 占位符按照指定类型的顺序填充。 模板中的占位符名称在各个模板中应当具备描述性和一致性。 它们在结构化的日志数据中充当属性名称。 对于占位符名称,建议使用帕斯卡拼写法 例如:{Count}{FirstName}

使用 DefineScope 方法定义一个日志作用域,以应用到一系列日志消息中。

示例应用含有一个“全部清除” 按钮,用于删除数据库中的所有引号。 通过一次删除一个引号来将其删除。 每当删除一个引号时,都会在记录器上调用 QuoteDeleted 方法。 在这些日志消息中会添加一个日志作用域。

在 appsettings.json 的控制台记录器部分启用 IncludeScopes

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

要创建日志作用域,请添加一个字段来保存该作用域的 Func<TResult> 委托。 示例应用创建一个名为 _allQuotesDeletedScope (Internal/LoggerExtensions.cs ) 的字段:

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

使用 DefineScope 来创建委托。 调用委托时最多可以指定三种类型作为模板参数使用。 示例应用使用包含删除的引号数量的消息模板(int 类型):

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

为日志消息提供一种静态扩展方法。 包含已命名属性的任何类型参数(这些参数出现在消息模板中)。 示例应用采用引号的 count,以删除并返回 _allQuotesDeletedScope

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

该作用域将日志记录扩展调用包装在 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();
}

检查应用控制台输出中的日志消息。 以下结果显示删除的三个引号,以及包含的日志作用域消息:

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)

其他资源