Asp.Net Core2.2 源碼閱讀系列——控制台日誌源碼解析
- 2019 年 10 月 3 日
- 筆記
為了讓我們第一時間知道程式的運行狀態，Asp.Net Core 添加了默認的日誌輸出服務。這看起來並沒有什麼問題，對於開發人員也相當友好，但如果不了解日誌輸出的細節，也有可能因為錯誤的日誌級別配置導致性能問題，筆者的同事在一次進行性能測試的時候被輸出日誌誤導，與其討論分析了測試源碼，排除業務程式碼因素，後來聯想到應該是由於默認的日誌輸出導致（默認的日誌級別 Microsoft 是 Inforamtion），隨後將日誌級別調高，性能立即飆升，問題解決。
雖然問題得到解決，但筆者腦中的對於到底為何日誌輸出會導致性能下降的疑問沒有解決，一切查資料的方式，都不及先看源碼來得直接，於是在github上拉取源碼，經過詳細的閱讀分析，終於了解了技術細節，找到了高並發下，控制台日誌輸出導致性能低下的真正原因。
1.首先要弄清楚默認日誌服務是如何添加的？
Asp.Net Core程式在啟動時，IWebHostBuilder CreateDefaultBuilder(args) 方法中會為我們註冊一些默認服務，這其中就包含默認的日誌輸出服務[GitHub源碼地址]：
public static void Main(string[] args) { CreateWebHostBuilder(args).Build().Run(); } public static IWebHostBuilder CreateWebHostBuilder(string[] args) => WebHost.CreateDefaultBuilder(args) .UseStartup<Startup>(); //部分源碼 public static IWebHostBuilder CreateDefaultBuilder(string[] args) { var builder = new WebHostBuilder(); ... builder.UseKestrel((builderContext, options) => { options.Configure(builderContext.Configuration.GetSection("Kestrel")); }) .ConfigureAppConfiguration((hostingContext, config) => { ... }) .ConfigureLogging((hostingContext, logging) => { logging.AddConfiguration(hostingContext.Configuration.GetSection("Logging")); logging.AddConsole(); //手動高亮 logging.AddDebug(); //手動高亮 logging.AddEventSourceLogger(); //手動高亮 }) .ConfigureServices((hostingContext, services) => { ... }) .UseIIS() .UseIISIntegration() .UseDefaultServiceProvider((context, options) => { options.ValidateScopes = context.HostingEnvironment.IsDevelopment(); }); return builder; }PS：如果還想了解默認添加的其他服務詳細細節，可以參看Hosting源碼地址
2. 日誌源碼
目前 Asp.Net Core 已經將擴展插件統統挪到 [aspnet/Extensions] 倉庫下，包含了所有 Asp.Net Core 所使用的擴展組件，如日誌，配置等，如需查找 Microsoft.Extensions.* 命名空間下的源碼，可以參考這個倉庫。
打開目錄 Extensions/src/Logging/ ，可以看到日誌相關的組件均在這個文件夾下，這裡簡單說下主要包含的Project：
- 日誌抽象層，主要負責Logger以及LoggerFactory介面定義和默認實現，為IOC提供擴展方法
- Microsoft.Extensions.Logging.Abstractions
- Microsoft.Extensions.Logging
- 日誌配置
- Microsoft.Extensions.Logging.Configuration
- 日誌具體實現
- Microsoft.Extensions.Logging.Console
- Microsoft.Extensions.Logging.Debug
- Microsoft.Extensions.Logging.EventLog
先來看下程式碼圖：
上圖可以看到，核心類主要有以下幾個：
- ConsoleLoggerProvider 實現了ILoggerProvider介面，主要負責創建ConsoleLogger
- ConsoleLoggerSettings ConsoleLogger日誌配置類
- ConsoleLogger 實現ILogger介面，日誌輸出最終的執行類
重要！篇幅原因，以下源碼均做了精簡，如有需要可以點擊文件名連接直接查看github源文件。
先來看 ConsoleLoggerProvider.cs 源碼:
public class ConsoleLoggerProvider : ILoggerProvider { private readonly ConcurrentDictionary<string, ConsoleLogger> _loggers = new ConcurrentDictionary<string, ConsoleLogger>();//手動高亮 private readonly Func<string, LogLevel, bool> _filter; private IConsoleLoggerSettings _settings; private readonly ConsoleLoggerProcessor _messageQueue = new ConsoleLoggerProcessor();//手動高亮 private static readonly Func<string, LogLevel, bool> falseFilter = (cat, level) => false; //通過IOptionMonitor<> 實現動態修改日誌參數功能，比如日誌級別 public ConsoleLoggerProvider(IOptionsMonitor<ConsoleLoggerOptions> options) { // Filter would be applied on LoggerFactory level _filter = trueFilter; _optionsReloadToken = options.OnChange(ReloadLoggerOptions); ReloadLoggerOptions(options.CurrentValue); } //3.0中將移除此構造函數 public ConsoleLoggerProvider(IConsoleLoggerSettings settings) { _settings = settings; if (_settings.ChangeToken != null) { _settings.ChangeToken.RegisterChangeCallback(OnConfigurationReload, null); } } //動態修改日誌級別 private void ReloadLoggerOptions(ConsoleLoggerOptions options) { foreach (var logger in _loggers.Values) { logger.ScopeProvider = scopeProvider; } } //通過此方法動態修改日誌級別 private void OnConfigurationReload(object state) { _settings = _settings.Reload(); foreach (var logger in _loggers.Values) { logger.Filter = GetFilter(logger.Name, _settings); } } //創建日誌組件，注意，每個日誌category name 創建一個日誌實例， //所以可以根據不同的name設置不通的日誌級別，達到細粒度控制 public ILogger CreateLogger(string name) { return _loggers.GetOrAdd(name, CreateLoggerImplementation); } private ConsoleLogger CreateLoggerImplementation(string name) { return new ConsoleLogger(name, GetFilter(name, _settings), null, _messageQueue) { }; } private Func<string, LogLevel, bool> GetFilter(string name, IConsoleLoggerSettings settings) { if (settings != null) { foreach (var prefix in GetKeyPrefixes(name)) { LogLevel level; if (settings.TryGetSwitch(prefix, out level)) { return (n, l) => l >= level; } } } return falseFilter; } //日誌級別匹配方式，比如name為 "A.B.C"，則依次匹配 "A.B.C","A.B", "A" private IEnumerable<string> GetKeyPrefixes(string name) { while (!string.IsNullOrEmpty(name)) { yield return name; var lastIndexOfDot = name.LastIndexOf('.'); if (lastIndexOfDot == -1) { yield return "Default"; break; } name = name.Substring(0, lastIndexOfDot); } } }可以看見，ConsoleLoggerProvider 持有一個執行緒安全的字典_loggers，用以保證每個category name（也就是業務程式碼中構造函數中的 ILogger<T> 中的 nameof(T)）有且僅有一個ILogger 實例，之所以這麼做，是為了可以更加細粒度控制每個logger的日誌輸出細節，比如log level。同時，可以通過 IOperationMonitor<> 實現動態日誌細節配置控制。
另外還有一個名為 _messageQueue 的實例在 ConsoleLogger 構造時傳進去，從名字看來似乎對日誌輸出做了排隊處理，我們稍後再看。
再來看 ConsoleLogger.cs 源碼:
public class ConsoleLogger : ILogger { private readonly ConsoleLoggerProcessor _queueProcessor; private Func<string, LogLevel, bool> _filter; [ThreadStatic]//手動高亮 private static StringBuilder _logBuilder; static ConsoleLogger() { var logLevelString = GetLogLevelString(LogLevel.Information); } internal ConsoleLogger(string name, Func<string, LogLevel, bool> filter, IExternalScopeProvider scopeProvider, ConsoleLoggerProcessor loggerProcessor) { Name = name; Filter = filter ?? ((category, logLevel) => true); _queueProcessor = loggerProcessor; } public string Name { get; } //日誌寫入介面實現 public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter) { if (!IsEnabled(logLevel)) return; var message = formatter(state, exception); if (!string.IsNullOrEmpty(message) || exception != null) { WriteMessage(logLevel, Name, eventId.Id, message, exception); } } // 日誌通過stringbuilder進行裝配 public virtual void WriteMessage(LogLevel logLevel, string logName, int eventId, string message, Exception exception) { var logBuilder = _logBuilder; _logBuilder = null; if (logBuilder == null) { logBuilder = new StringBuilder(); } var logLevelString = GetLogLevelString(logLevel); // category and event id logBuilder.Append(_loglevelPadding); logBuilder.Append(logName); logBuilder.Append("["); logBuilder.Append(eventId); logBuilder.AppendLine("]"); if (!string.IsNullOrEmpty(message)) { // message logBuilder.Append(_messagePadding); var len = logBuilder.Length; logBuilder.AppendLine(message); logBuilder.Replace(Environment.NewLine, _newLineWithMessagePadding, len, message.Length); } if (exception != null) { logBuilder.AppendLine(exception.ToString()); } var hasLevel = !string.IsNullOrEmpty(logLevelString); // Queue log message _queueProcessor.EnqueueMessage(new LogMessageEntry() //裝配完成日誌入隊 { Message = logBuilder.ToString(), MessageColor = DefaultConsoleColor, LevelString = hasLevel ? logLevelString : null, }); logBuilder.Clear(); if (logBuilder.Capacity > 1024) { logBuilder.Capacity = 1024; } _logBuilder = logBuilder; } public bool IsEnabled(LogLevel logLevel) { if (logLevel == LogLevel.None) { return false; } return Filter(Name, logLevel); } //日誌最終記錄欄位和LogLevel中的枚舉名稱通過此方法映射 private static string GetLogLevelString(LogLevel logLevel) { switch (logLevel) { case LogLevel.Trace: return "trce"; case LogLevel.Debug: return "dbug"; case LogLevel.Information: return "info"; case LogLevel.Warning: return "warn"; case LogLevel.Error: return "fail"; case LogLevel.Critical: return "crit"; default: throw new ArgumentOutOfRangeException(nameof(logLevel)); } } } 此類是對ILogger介面的簡單實現，可以看出，在調用Log
值得注意的是，筆者看到WriteMessage()方法中的 _logBuilder.Append() 日誌內容時，沒加任何鎖，立即懷疑這不是會有執行緒安全問題么？然後抬頭一看，_logBuilder的欄位定義上加了 [ThreadStatic] 標籤，相比於對這個方法加鎖，對這個欄位設置為執行緒靜態欄位才是完美的方案，不得不感嘆微軟程式設計師的嚴謹性！
最後看下 ConsoleLoggerProcessor.cs，尋找最終答案:
public class ConsoleLoggerProcessor : IDisposable { private const int _maxQueuedMessages = 1024; private readonly BlockingCollection<LogMessageEntry> _messageQueue = new BlockingCollection<LogMessageEntry>(_maxQueuedMessages); private readonly Thread _outputThread; public IConsole Console; public ConsoleLoggerProcessor() { // 開啟消費阻塞隊列執行緒 _outputThread = new Thread(ProcessLogQueue) { IsBackground = true, Name = "Console logger queue processing thread" }; _outputThread.Start(); } public virtual void EnqueueMessage(LogMessageEntry message) { if (!_messageQueue.IsAddingCompleted) { try { //入隊操作 _messageQueue.Add(message); return; } catch (InvalidOperationException) { } } } //消費隊列 private void ProcessLogQueue() { try { foreach (var message in _messageQueue.GetConsumingEnumerable()) { WriteMessage(message); } } catch { try { _messageQueue.CompleteAdding(); } catch { } } } } 以上程式碼解釋了為何在並發情況下，控制台日誌輸出會導致性能降低的原因：
該類中有一個BlockingCollection<> 阻塞隊列，最大長度1024，用於實現日誌輸出的生產消費模型，再看 EnqueueMessage()方法，如果阻塞隊列中已經達到1024條日誌，則所有生產者將被阻塞。也就是說：一旦日誌生產速度遠遠大於隊列消費速度，生產者將會集中等待隊列消費後才能競爭入隊後返回，引發了性能瓶頸
到此，終於弄清楚之前的性能測試為何會受日誌控制台輸出的影響，對底層程式碼的分析，會加深對此類問題的理解，不但對之後排查類似問題有幫助，也讓我們對生產消費模型場景有了更深的理解。
後記
筆者此次對日誌相關源碼還做了更多深入的閱讀，同時依照 Microsoft.Extesions.Logging 中的介面實現了自定義日誌組件，用於在生產中，從底層對很多資訊進行獲取和記錄，比如traceid，在這個翻閱的過程中，感受到通過閱讀源碼，可以更加直接的理解 Asp.Net Core 相關的設計思想，以及程式碼實現，對於理解整體框架有極大的幫助，筆者後續也會繼續閱讀其他相關源碼。對於目前在使用.Net Core 的同學，希望你同我一樣，對了解事務的本質保持好奇心，持之以恆！
