.NET 中的高性能日志记录

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}

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

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

对于Action,请指定:

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

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

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

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

结构化日志存储可以在提供事件 ID 时,使用事件名称来丰富日志。 例如, Serilog 使用事件名称。

通过强类型扩展方法调用 Action。 每次处理工作项时,该方法 PriorityItemProcessed 都会记录消息。 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

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

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

委托的日志消息模板从提供的类型接收其占位符值。 示例应用定义一个委托,用于添加一个工作项,其中项参数为 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 该方法应用于一系列日志消息。 在 IncludeScopes的控制台记录器部分中启用

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

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

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

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

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...

日志级防护优化

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

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

更多信息,请参阅:

另请参阅