.NET性能優化-使用SourceGenerator-Logger記錄日誌

2022 年 8 月 1 日
筆記
.NET, Logging, 性能優化

前言

在現在許許多多的應用系統中，日誌非常關鍵，它即是排查問題的強力工具，也是程式設計師居家旅行工作甩鍋必備良品。
在團隊中編碼中，我們都要求對於那些會變更數據的介面、調用第三方的介面記錄請求和響應參數，另外在關鍵的程式碼路徑記錄後續可供診斷的日誌資訊。
如果使用了微軟官方的日誌記錄框架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是如何生成程式碼的不在本文的討論範圍，大家有興趣的可以查看下方的源碼鏈接。
//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方法有幾個主要好處：

允許保留日誌記錄結構，並啟用消息模板所需的確切格式語法。
允許為模板佔位符提供替代名稱，允許使用格式說明符。
允許按原樣傳遞所有原始數據，在對其進行處理之前，不需要進行任何複雜的存儲（除了創建 string）。
提供特定於日誌記錄的診斷，針對重複的事件 ID 發出警告。

與手動使用 LoggerMessage.Define 相比，還有一些好處：

語法更短、更簡單：使用聲明性屬性，而不是對樣本進行編碼。
引導式開發人員體驗：生成器會發出警告，幫助開發人員做正確的事。
支援任意數量的日誌記錄參數。 LoggerMessage.Define 最多支援六個。
支援動態日誌級別。單獨使用 LoggerMessage.Define 不可能做到這一點。

參考文獻及附錄

本項目源碼地址：//github.com/InCerryGit/BlogCodes
Logger文檔：//docs.microsoft.com/zh-cn/dotnet/core/extensions/logger-message-generator
SourceGenerator MSDOC文檔：//docs.microsoft.com/zh-cn/dotnet/csharp/roslyn-sdk/source-generators-overview
SourceGenerator 入門手冊： //github.com/dotnet/roslyn/blob/main/docs/features/source-generators.cookbook.md

Tags: .NET Logging 性能優化