• .NET性能优化-使用SourceGenerator-Logger记录日志


    前言

    在现在许许多多的应用系统中,日志非常关键,它即是排查问题的强力工具,也是程序员居家旅行工作甩锅必备良品。
    在团队中编码中,我们都要求对于那些会变更数据的接口、调用第三方的接口记录请求和响应参数,另外在关键的代码路径记录后续可供诊断的日志信息。
    如果使用了微软官方的日志记录框架Microsoft.Extensions.Logging,我们通常会像下面代码一样记录日志。
    这是我们经常会遇到的日志记录场景,其中会记录一些外部传入的参数。带参数的日志会有频繁的字符串拼接必然会使用更多的内存对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);

    ///
    /// 会员
    ///
    /// 会员Id
    /// 会员名
    public record Member(string MemberId, string Name);

    ///
    /// 订单日志记录类
    /// 需要使用Source Generator 所以类型为partial
    ///
    public partial class OrderLogger
    {
    private readonly ILogger _logger;

    public OrderLogger(ILogger logger)
    {
        _logger = logger;
    }
    
    /// 
    /// 使用字符串插值记录
    /// 
    public void LogByStringInterpolation(Member member, DateTime now)=>
        _logger.LogInformation($"会员[{member}]在[{now:yyyy-MM-dd HH:mm:ss}]充值了一个小目标");
    
    /// 
    /// 使用参数化记录
    /// 
    public void LogByStructure(Member member, DateTime now) =>
        _logger.LogInformation("会员[{Member}]在[{Now:yyyy-MM-dd HH:mm:ss}]充值了一个小目标", member, now);
    
    /// 
    /// 使用源代码生成
    /// 
    [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);
    
    • 1
    • 2
    • 3
    • 4
    • 5
    • 6
    • 7
    • 8
    • 9
    • 10
    • 11
    • 12
    • 13
    • 14
    • 15
    • 16
    • 17
    • 18
    • 19
    • 20
    • 21
    • 22
    • 23
    • 24
    • 25

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

    性能对比

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

    public class EmptyLogger : ILogger
    {
    public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter)
    { }

    public bool IsEnabled(LogLevel logLevel) => true;  
    
    public IDisposable BeginScope(TState state) => default;  
    
    • 1
    • 2
    • 3

    }
    然后使用下面代码进行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);  
    
    • 1
    • 2
    • 3
    • 4
    • 5
    • 6
    • 7
    • 8

    }
    跑分结果如下所示,可以看到使用了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生成的代码是可以输出到文件中的,只需要在项目文件中的内加入这样的一个配置,设置值为True。

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

    打开文件夹以后,可以看到有一个*.g.cs结尾的文件,这就是由SG生成的文件。
    在这里插入图片描述

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

    //
    #nullable enable
    partial class OrderLogger
    {
    [global::System.CodeDom.Compiler.GeneratedCodeAttribute(“Microsoft.Extensions.Logging.Generators”, “6.0.5.2210”)]
    private static readonly global::System.Action __LogBySourceGeneratorCallback =
    global::Microsoft.Extensions.Logging.LoggerMessage.Define(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,假设我忘记了这个,写了如下的代码:

    ///
    /// 源代码生成 - 忘记写partial
    ///
    [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参数。

    ///
    /// 源代码生成
    ///
    [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方法有几个主要好处:

    允许保留日志记录结构,并启用消息模板所需的确切格式语法。
    允许为模板占位符提供替代名称,允许使用格式说明符。
    允许按原样传递所有原始数据,在对其进行处理之前,不需要进行任何复杂的存储(除了创建 string)。
    提供特定于日志记录的诊断,针对重复的事件 ID 发出警告。
    与手动使用 LoggerMessage.Define 相比,还有一些好处:

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

  • 相关阅读:
    每日一题|2022-11-23|1742. 盒子中小球的最大数量|Golang
    Linux系统内核作用
    Geogebra 教程之 04 Geogebra 小程序
    【MySQL新手到通关】第一章 数据库概述
    全志V853开发板开发进阶——GPADC
    Linux磁盘分区与挂载
    Redis缓存
    JSP 购物商城系统eclipse定制开发mysql数据库BS模式java编程servlet
    .NET周刊【6月第5期 2024-06-30】
    10 Redis之SB整合Redis+ 高并发问题 + 分布式锁
  • 原文地址:https://blog.csdn.net/weixin_43214644/article/details/126115167