dotnet性能优化-使用SourceGenerator-Logger记录日志-技术圈

前言

在现在许许多多的应用系统中，日志非常关键，它即是排查问题的强力工具，也是程序员居家旅行工作甩锅必备良品。在团队中编码中，我们都要求对于那些会变更数据的接口、调用第三方的接口记录请求和响应参数，另外在关键的代码路径记录后续可供诊断的日志信息。如果使用了微软官方的日志记录框架Microsoft.Extensions.Logging^[1]，我们通常会像下面代码一样记录日志。这是我们经常会遇到的日志记录场景，其中会记录一些外部传入的参数。带参数的日志会有频繁的字符串拼接必然会使用更多的内存对GC造成更大的压力。当系统处理的请求越来越多的时候，日志记录就很可能会成为瓶颈。

// 创建日志记录类，分别使用不同的方式来记录日志var logger = LoggerFactory.Create(l => l.AddConsole()).CreateLogger(typeof(OrderLogger));var orderLogger = new OrderLogger(logger);var member = new Member("8888","Justin Yu");orderLogger.LogByStringInterpolation(member, DateTime.Now);orderLogger.LogByStructure(member, DateTime.Now);OrderLogger.LogBySourceGenerator(logger, member, DateTime.Now);
/// <summary>  /// 会员  /// </summary>  /// <param name="MemberId">会员Id</param>  /// <param name="Name">会员名</param>  public record Member(string MemberId, string Name);
/// <summary>/// 订单日志记录类/// 需要使用Source Generator 所以类型为partial/// </summary>public partial class OrderLogger{    private readonly ILogger _logger;
    public OrderLogger(ILogger logger)    {        _logger = logger;    }
    /// <summary>    /// 使用字符串插值记录    /// </summary>    public void LogByStringInterpolation(Member member, DateTime now)=>        _logger.LogInformation($"会员[{member}]在[{now:yyyy-MM-dd HH:mm:ss}]充值了一个小目标");
    /// <summary>    /// 使用参数化记录    /// </summary>    public void LogByStructure(Member member, DateTime now) =>        _logger.LogInformation("会员[{Member}]在[{Now:yyyy-MM-dd HH:mm:ss}]充值了一个小目标", member, now);
    /// <summary>    /// 使用源代码生成    /// </summary>    [LoggerMessage(        EventId = 0,        Level = LogLevel.Information,         Message = "会员[{member}]在[{Now:yyyy-MM-dd HH:mm:ss}]充值了一个小目标")]    public static partial void LogBySourceGenerator(ILogger logger, Member member, DateTime now);}

然后运行一下代码看看日志记录的结果，它们都能正常的输出我们想要的日志，那么究竟性能上有什么差别呢？让我们看看第二节的内容。

性能对比

我们这里实际上是测试这三种方式参数化日志记录的性能，为了避免日志输出到外部Console、File可能影响我们的测试结果，我们自己编写一个什么都不做的ILogger实现。

public class EmptyLogger : ILogger  {      public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)      { }  
    public bool IsEnabled(LogLevel logLevel) => true;  
    public IDisposable BeginScope<TState>(TState state) => default;  }

然后使用下面代码进行Benchmark。

[HtmlExporter][MemoryDiagnoser]  [Orderer(SummaryOrderPolicy.FastestToSlowest)]public class Benchmark  {      private static readonly ILogger Logger = new EmptyLogger();    private readonly OrderLogger _orderLogger = new(Logger);    private readonly Member _user = new("8888","Justin Yu");      private readonly DateTime _now = DateTime.UtcNow;  
    [Benchmark]      public void LogByStringInterpolation() => _orderLogger.LogByStringInterpolation(_user, _now);  
    [Benchmark]      public void LogByStructure() => _orderLogger.LogByStructure(_user, _now);  
    [Benchmark]      public void LogBySourceGenerator() => OrderLogger.LogBySourceGenerator(_logger, _user, _now);  }

跑分结果如下所示，可以看到使用了SourceGenerator的日志记录方式遥遥领先；另外也不要小看那么几十纳秒和Byte的差别，在高并发的系统中就是积少成多会带来不错的性能提升。

那么为什么使用SourceGenerator会有这样的效果？我们来看看SourceGenerator到底生成了什么。

关于SourceGenerator

SourceGenerator（下文使用SG替代）并不是什么新的东西，在.NET5时就已经支持，不过由于在那时还是比较新的技术，没有太多的应用场景。引用微软文档上的图片，SourceGenerator就是在编译时通过Roslyn来分析源代码然后生成新源代码参与编译，更详细的信息可以在文末找到链接。

它主要是为了在编译时生成代码，减少开发者写一些重复代码所花费的时间，另外也有着比反射和运行时生成代码(Emit)更高的性能和更低的使用门槛。另外一个方面就是为了Native AOT，比如Dapper、EF等为代表严重依赖运行时代码生成的ORM框架，在Native AOT中其实是不可用的，引入SourceGenerator以后就可以在编译期生成代码，为Native AOT加上这些框架的支持。目前在.NET框架中已经有Logging、System.Text.Json、Regex等组件已经支持SourceGenerator，都有着较大的性能提成。

SG为Logger生成了什么？

SG生成的代码是可以输出到文件中的，只需要在项目文件中的<PropertyGroup>内加入这样的一个配置，设置值为True。

<EmitCompilerGeneratedFiles>true</EmitCompilerGeneratedFiles>

然后我们就可以在下面的目录中找到SG为我们生成的代码。路径在项目文件同级目录，根据Debug模式和Release模式如下所示：

打开文件夹以后，可以看到有一个*.g.cs结尾的文件，这就是由SG生成的文件。

使用IDE打开这个文件，就可以看到为我们生成的代码是什么样的(如下所示)。可以看到SG为我们填充了LogBySourceGenerator的主体部分，实现高性能的秘密之一就是使用了LoggerMessage.Define^[2]，它的所需要的内存分配要少的许多。

// <auto-generated/>#nullable enablepartial class OrderLogger {    [global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "6.0.5.2210")]    private static readonly global::System.Action<global::Microsoft.Extensions.Logging.ILogger, global::Member, global::System.DateTime, global::System.Exception?> __LogBySourceGeneratorCallback =        global::Microsoft.Extensions.Logging.LoggerMessage.Define<global::Member, global::System.DateTime>(global::Microsoft.Extensions.Logging.LogLevel.Information, new global::Microsoft.Extensions.Logging.EventId(0, nameof(LogBySourceGenerator)), "会员[{member}]在[{Now:yyyy-MM-dd HH:mm:ss}]充值了一个小目标", new global::Microsoft.Extensions.Logging.LogDefineOptions() { SkipEnabledCheck = true });     [global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "6.0.5.2210")]    public static partial void LogBySourceGenerator(global::Microsoft.Extensions.Logging.ILogger logger, global::Member member, global::System.DateTime now)    {        if (logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Information))        {            __LogBySourceGeneratorCallback(logger, member, now, null);        }    }}

而填充的规则是由上面代码中的特性决定的，如下摘抄出来的代码。

[LoggerMessage(    EventId = 0,    Level = LogLevel.Information,     Message = "会员[{member}]在[{Now:yyyy-MM-dd HH:mm:ss}]充值了一个小目标")]public static partial void LogBySourceGenerator(ILogger logger, Member member, DateTime now);

至于SG是如何生成代码的不在本文的讨论范围，大家有兴趣的可以查看下方的源码链接。https://github.com/dotnet/runtime/tree/main/src/libraries/Microsoft.Extensions.Logging.Abstractions/gen

编译时警告

这是SG另外一个很不错的功能，我们在软件开发过程中经常会犯一些错误，导致不能正常的使用框架的功能或者产生一些BUG。比如：按照Logger的约定来说，为了方便SG生成代码，我们需要将类和方法名变为partial，假设我忘记了这个，写了如下的代码：

/// <summary>  /// 源代码生成 - 忘记写partial  /// </summary>  [LoggerMessage(      EventId = 0,      Level = LogLevel.Information,   Message = "会员[{member}]在[{Now:yyyy-MM-dd HH:mm:ss}]充值了一个小目标")]  public static void LogBySourceGenerator(ILogger logger, Member member, DateTime now);

就会有下面这样的错误，提醒你必须加partial关键字。

再如，在参数化的模版里面有merber和now两个参数，我们编写代码的时候像下方一样少传了now参数。

/// <summary>  /// 源代码生成  /// </summary>  [LoggerMessage(      EventId = 0,      Level = LogLevel.Information,   Message = "会员[{member}]在[{Now:yyyy-MM-dd HH:mm:ss}]充值了一个小目标")]  public static partial void LogBySourceGenerator(ILogger logger, Member member);

那么SG构建时便可以提醒你，模版中的Now没有听对应的参数。

这功能会非常有用，能节省很多问题排查的时间。

总结

随着 C# Source Generator的出现，编写高性能的日志记录API变得更加容易。使用Source Generator方法有几个主要好处：

•允许保留日志记录结构，并启用消息模板^[3]所需的确切格式语法。•允许为模板占位符提供替代名称，允许使用格式说明符。•允许按原样传递所有原始数据，在对其进行处理之前，不需要进行任何复杂的存储（除了创建 string）。•提供特定于日志记录的诊断，针对重复的事件 ID 发出警告。

与手动使用 LoggerMessage.Define^[4] 相比，还有一些好处：

•语法更短、更简单：使用声明性属性，而不是对样本进行编码。•引导式开发人员体验：生成器会发出警告，帮助开发人员做正确的事。•支持任意数量的日志记录参数。 LoggerMessage.Define 最多支持六个。•支持动态日志级别。单独使用 LoggerMessage.Define 不可能做到这一点。

参考文献及附录

本项目源码地址：https://github.com/InCerryGit/BlogCodes Logger文档：https://docs.microsoft.com/zh-cn/dotnet/core/extensions/logger-message-generator SourceGenerator MSDOC文档：https://docs.microsoft.com/zh-cn/dotnet/csharp/roslyn-sdk/source-generators-overview SourceGenerator 入门手册：https://github.com/dotnet/roslyn/blob/main/docs/features/source-generators.cookbook.md

References

[1] Microsoft.Extensions.Logging: https://docs.microsoft.com/zh-cn/dotnet/api/microsoft.extensions.logging?view=dotnet-plat-ext-6.0
[2] LoggerMessage.Define: https://docs.microsoft.com/zh-cn/dotnet/api/microsoft.extensions.logging.loggermessage
[3] 消息模板: https://messagetemplates.org/
[4] LoggerMessage.Define: https://docs.microsoft.com/zh-cn/dotnet/api/microsoft.extensions.logging.loggermessage.define

推荐阅读：

API 工程化分享

我的微软 MVP 之路

【译】ASP.NET Core 6 中的性能改进

【译】.NET 7 预览版 1 中的 ASP.NET Core 更新

【译】C# 11 特性的早期预览

点击下方卡片关注DotNet NB

一起交流学习