.NET 中的高性能日志记录

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

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

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

重要

在 .NET 6 及更高版本中,可以使用 LoggerMessage 属性而不是 LoggerMessage 类来创建高性能日志。 LoggerMessageAttribute 提供源生成日志记录支持,旨在为新式 .NET 应用程序提供高度可用且高性能的日志记录解决方案。 有关详细信息,请参阅编译时日志记录源生成(.NET 基础知识)

示例应用展示了具有优先级队列处理辅助角色服务的 LoggerMessage 功能。 应用按优先级顺序处理工作项。 发生这些操作时,通过 LoggerMessage 模式生成日志消息。

提示

所有日志记录示例源代码都可以在示例浏览器中下载。 有关详细信息,请参阅浏览代码示例:.NET 中的日志记录

定义记录器消息

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

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

每条日志消息都是一个 Action,保存在由 Action 创建的静态字段中。 例如,示例应用创建一个字段来描述处理工作项的日志消息:

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

对于 Action,指定:

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

由于对工作项处理取消排队,辅助角色服务应用会进行下列设置:

  • 将日志级别设置为 LogLevel.Critical
  • 将事件 ID 设置为具有 FailedToProcessWorkItem 方法名称的 13
  • 将消息模板(命名的格式字符串)设置为字符串。
s_failedToProcessWorkItem = LoggerMessage.Define(
    LogLevel.Critical,
    new EventId(13, nameof(FailedToProcessWorkItem)),
    "Epic failure processing item!");

LoggerMessage.Define 方法用于配置和定义表示日志消息的 Action 委托。

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

通过强类型扩展方法调用 ActionPriorityItemProcessed 方法会在每次处理工作项时记录一条消息。 在(如果)发生异常时调用 FailedToProcessWorkItem

protected override async Task ExecuteAsync(
    CancellationToken stoppingToken)
{
    using (IDisposable? scope = logger.ProcessingWorkScope(DateTime.Now))
    {
        while (!stoppingToken.IsCancellationRequested)
        {
            try
            {
                WorkItem? nextItem = priorityQueue.ProcessNextHighestPriority();

                if (nextItem is not null)
                {
                    logger.PriorityItemProcessed(nextItem);
                }
            }
            catch (Exception ex)
            {
                logger.FailedToProcessWorkItem(ex);
            }

            await Task.Delay(1_000, stoppingToken);
        }
    }
}

检查应用的控制台输出:

crit: WorkerServiceOptions.Example.Worker[13]
      Epic failure processing item!
      System.Exception: Failed to verify communications.
         at WorkerServiceOptions.Example.Worker.ExecuteAsync(CancellationToken stoppingToken) in
         ..\Worker.cs:line 27

要将参数传递给日志消息,创建静态字段时最多定义六种类型。 在通过定义 Action 字段的 WorkItem 类型来处理项时,示例应用会记录工作项的详细信息:

private static readonly Action<ILogger, WorkItem, Exception> s_processingPriorityItem;

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

s_processingPriorityItem = LoggerMessage.Define<WorkItem>(
    LogLevel.Information,
    new EventId(1, nameof(PriorityItemProcessed)),
    "Processing priority item: {Item}");

用于记录正在处理工作项的静态扩展方法 PriorityItemProcessed 接收工作项参数值并将其传递给 Action 委托:

public static void PriorityItemProcessed(
    this ILogger logger, WorkItem workItem) =>
    s_processingPriorityItem(logger, workItem, default!);

在辅助角色服务的 ExecuteAsync 方法中,调用 PriorityItemProcessed 以记录消息:

protected override async Task ExecuteAsync(
    CancellationToken stoppingToken)
{
    using (IDisposable? scope = logger.ProcessingWorkScope(DateTime.Now))
    {
        while (!stoppingToken.IsCancellationRequested)
        {
            try
            {
                WorkItem? nextItem = priorityQueue.ProcessNextHighestPriority();

                if (nextItem is not null)
                {
                    logger.PriorityItemProcessed(nextItem);
                }
            }
            catch (Exception ex)
            {
                logger.FailedToProcessWorkItem(ex);
            }

            await Task.Delay(1_000, stoppingToken);
        }
    }
}

检查应用的控制台输出:

info: WorkerServiceOptions.Example.Worker[1]
      Processing priority item: Priority-Extreme (50db062a-9732-4418-936d-110549ad79e4): 'Verify communications'

指定记录器消息作用域

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

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

使用 DefineScope 方法定义一个日志作用域,以应用到一系列日志消息中。 在 appsettings.json 的控制台记录器部分启用 IncludeScopes

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

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

private static readonly Func<ILogger, DateTime, IDisposable?> s_processingWorkScope;

使用 DefineScope 来创建委托。 调用委托时最多可以指定 6 种类型作为模板参数使用。 示例应用使用包含处理开始的日期时间的消息模板:

s_processingWorkScope =
    LoggerMessage.DefineScope<DateTime>(
        "Processing scope, started at: {DateTime}");

为日志消息提供一种静态扩展方法。 包含已命名属性的任何类型参数(这些参数出现在消息模板中)。 示例应用接受自定义时间戳的 DateTime 以记录和返回 _processingWorkScope

public static IDisposable? ProcessingWorkScope(
    this ILogger logger, DateTime time) =>
    s_processingWorkScope(logger, time);

该作用域将日志记录扩展调用包装在 using 块中:

protected override async Task ExecuteAsync(
    CancellationToken stoppingToken)
{
    using (IDisposable? scope = logger.ProcessingWorkScope(DateTime.Now))
    {
        while (!stoppingToken.IsCancellationRequested)
        {
            try
            {
                WorkItem? nextItem = priorityQueue.ProcessNextHighestPriority();

                if (nextItem is not null)
                {
                    logger.PriorityItemProcessed(nextItem);
                }
            }
            catch (Exception ex)
            {
                logger.FailedToProcessWorkItem(ex);
            }

            await Task.Delay(1_000, stoppingToken);
        }
    }
}

检查应用控制台输出中的日志消息。 以下结果显示日志消息的优先级排序,其中包括日志作用域消息:

info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Extreme (7d153ef9-8894-4282-836a-8e5e38319fb3): 'Verify communications'
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: D:\source\repos\dotnet-docs\docs\core\extensions\snippets\logging\worker-service-options
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-High (dbad6558-60cd-4eb1-8531-231e90081f62): 'Validate collection'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Medium (1eabe213-dc64-4e3a-9920-f67fe1dfb0f6): 'Propagate selections'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Medium (1142688d-d4dc-4f78-95c5-04ec01cbfac7): 'Enter pooling [contention]'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Low (e85e0c4d-0840-476e-b8b0-22505c08e913): 'Health check network'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Deferred (07571363-d559-4e72-bc33-cd8398348786): 'Ping weather service'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Deferred (2bf74f2f-0198-4831-8138-03368e60bd6b): 'Set process state'
info: Microsoft.Hosting.Lifetime[0]
      Application is shutting down...

日志级防护优化

在调用相应的 Log* 方法之前,可通过使用 ILogger.IsEnabled(LogLevel) 检查 LogLevel 来进行另一种性能优化。 未为给定的 LogLevel 配置日志记录时,以下语句为 true:

  • ILogger.Log 未调用。
  • 避免分配表示参数的 object[]
  • 避免值类型装箱。

参考信息:

另请参阅