0
点赞
收藏
分享

微信扫一扫

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


/// <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,它的所需要的内存分配要少的许多。


// <auto-generated/>

#nullable enable

partial 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是如何生成代码的不在本文的讨论范围,大家有兴趣的可以查看下方的源码链接。

举报

相关推荐

0 条评论