1. 程式人生 > >Asp.Net Core2.2 原始碼閱讀系列——控制檯日誌原始碼解析

Asp.Net Core2.2 原始碼閱讀系列——控制檯日誌原始碼解析

  為了讓我們第一時間知道程式的執行狀態,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:

  1. 日誌抽象層,主要負責Logger以及LoggerFactory介面定義和預設實現,為IOC提供擴充套件方法
  • Microsoft.Extensions.Logging.Abstractions
  • Microsoft.Extensions.Logging
  1. 日誌配置
  • Microsoft.Extensions.Logging.Configuration
  1. 日誌具體實現
  • Microsoft.Extensions.Logging.Console
  • Microsoft.Extensions.Logging.Debug
  • Microsoft.Extensions.Logging.EventLog

  先來看下程式碼圖:

   上圖可以看到,核心類主要有以下幾個:

  1. ConsoleLoggerProvider 實現了ILoggerProvider介面,主要負責建立ConsoleLogger
  2. ConsoleLoggerSettings ConsoleLogger日誌配置類
  3. 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()方法,使用stringbuilder 對日誌內容進行了拼接,然後果然丟進了_queueProcessor佇列,並沒有立即輸出。

  值得注意的是,筆者看到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 的同學,希望你同我一樣,對了解事務的本質保持好奇心,持之以恆