為了讓我們第一時間知道程序的運行狀態，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 的同學，希望你同我一樣，對了解事務的本質保持好奇心，持之以恆！