Asp.Net Core2.2 源碼閱讀系列——控制台日誌源碼解析

来源:https://www.cnblogs.com/xboo/archive/2019/09/23/11574091.html
-Advertisement-
Play Games

  為了讓我們第一時間知道程式的運行狀態，Asp.Net Core 添加了預設的日誌輸出服務。這看起來並沒有什麼問題，對於開發人員也相當友好，但如果不瞭解日誌輸出的細節，也有可能因為錯誤的日誌級別配置導致性能問題，筆者的同事在一次進行性能測試的時候被輸出日誌誤導，與其討論分析了測 ...


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


您的分享是我們最大的動力!

-Advertisement-
Play Games
更多相關文章
  • Python 容器使用的 5 個技巧和 2 個誤區
    “容器”這兩個字很少被 Python 技術文章提起。一看到“容器”，大家想到的多是那頭藍色小鯨魚：Docker，但這篇文章和它沒有任何關係。本文里的容器，是 Python 中的一個抽象概念，是對專門用來裝其他對象的數據類型的統稱。 在 Python 中，有四類最常見的內建容器類型： 列表（list） ...
  • validator 自動化校驗
    溫馨提示 請收藏再看。此文篇幅太長，你短時間看不完；此文乾貨太多，錯過太可惜。 示例代碼可以關註 （公眾號）回覆 獲取。 收穫 1. 講解詳細：能讓你掌握使用 及類似校驗工具的各種使用姿勢 2. 內容全面：可以當做知識字典來查詢 what 註意：hibernate validator 與 持久層框架 ...
  • 手寫Spring MVC
    閑及無聊 又打開了CSDN開始看一看有什麼先進的可以學習的相關帖子，這時看到了一位大神寫的簡歷裝X必備，手寫Spring MVC。 我想這個東西還是有一點意思的 就拜讀了一下大佬的博客 通讀了一遍相關代碼 感覺和我想象中spring的運作流程基本相同 但是我腦海中基本上只有一個非常簡單的基本概念 而 ...
  • 二維碼生成器，基於python,segno庫
    多好，多簡單，多好 ...
  • 貪心演算法之——黑白點的匹配（兩種實現方法）
    一、題目 設平面上分佈著n個白點和n個黑點，每個點用一對坐標（x, y）表示。一個黑點b=（xb,yb）支配一個白點w=(xw, yw)當且僅當xb>=xw和yb>=yw。 若黑點b支配白點w，則黑點b和白點w可匹配（可形成一個匹配對）。 在一個黑點最多只能與一個白點匹配，一個白點最多只能與一個黑點 ...
  • .NET MVC5簡介（四）Filter和AuthorizeAttribute許可權驗證
    在webform中，驗證的流程大致如下圖： 在AOP中： 在Filter中： AuthorizeAttribute許可權驗證 登錄後有許可權控制，有的頁面是需要用戶登錄才能訪問的，需要在訪問頁面增加一個驗證，也不能每個action都一遍。 1、寫一個CustomAuthorAttribute，繼承自Au ...
  • .NET MVC5簡介（三）Result
    Ajax請求數據響應格式，一個醒目組必須是同意的，前端才知道怎麼應付，還有很多其他情況，比如異常了，有ExceptionFilter，按照固定格式返回，比如沒有許可權，Authorization，按照固定格式返回。 Http請求的本質： 請求--應答式，響應可以那麼豐富？不同的類型其實方式一樣的，只不 ...
  • .NET MVC5簡介（二）
    MVCApplication Application_Statr--RegisterRoutes--給RouteCollection添加規則，請求進到網站 X 請求地址被路由按照順序匹配，遇到一個溫和的就結束，就到對應的控制器和action。 在程式中使用log4net，首先nuget引入程式集 L ...
一周排行
    -Advertisement-
    Play Games
  • Dapr Outbox 執行流程
    Dapr Outbox 是1.12中的功能。 本文只介紹Dapr Outbox 執行流程，Dapr Outbox基本用法請閱讀官方文檔 。本文中appID=order-processor，topic=orders 本文前提知識：熟悉Dapr狀態管理、Dapr發佈訂閱和Outbox 模式。 Outbo ...
  • Advanced .Net Debugging 7：托管堆與垃圾收集
    引言 在前幾章我們深度講解了單元測試和集成測試的基礎知識，這一章我們來講解一下代碼覆蓋率,代碼覆蓋率是單元測試運行的度量值,覆蓋率通常以百分比表示，用於衡量代碼被測試覆蓋的程度，幫助開發人員評估測試用例的質量和代碼的健壯性。常見的覆蓋率包括語句覆蓋率（Line Coverage）、分支覆蓋率（Bra ...
  • C#S7.NET實現西門子PLCDB塊數據採集的完整步驟
    前言 本文介紹瞭如何使用S7.NET庫實現對西門子PLC DB塊數據的讀寫，記錄了使用電腦模擬，模擬PLC，自至完成測試的詳細流程，並重點介紹了在這個過程中的易錯點，供參考。 用到的軟體： 1.Windows環境下鏈路層網路訪問的行業標準工具（WinPcap_4_1_3.exe）下載鏈接：http ...
  • WPF控制項：密碼框綁定MVVM
    從依賴倒置原則（Dependency Inversion Principle, DIP）到控制反轉（Inversion of Control, IoC）再到依賴註入（Dependency Injection, DI）的演進過程，我們可以理解為一種逐步抽象和解耦的設計思想。這種思想在C#等面向對象的編 ...
  • Python中的私有屬性與私有方法
    關於Python中的私有屬性和私有方法 Python對於類的成員沒有嚴格的訪問控制限制，這與其他面相對對象語言有區別。關於私有屬性和私有方法，有如下要點： 1、通常我們約定，兩個下劃線開頭的屬性是私有的（private）。其他為公共的（public）； 2、類內部可以訪問私有屬性（方法）； 3、類外 ...
  • C++ 訪問說明符詳解：封裝數據，控制訪問，提升安全性
    C++ 訪問說明符 訪問說明符是 C++ 中控制類成員（屬性和方法）可訪問性的關鍵字。它們用於封裝類數據並保護其免受意外修改或濫用。 三種訪問說明符： public：允許從類外部的任何地方訪問成員。 private：僅允許在類內部訪問成員。 protected：允許在類內部及其派生類中訪問成員。 示 ...
  • static_cast與dynamic_cast到底是什麼？
    寫這個隨筆說一下C++的static_cast和dynamic_cast用在子類與父類的指針轉換時的一些事宜。首先，【static_cast，dynamic_cast】【父類指針，子類指針】，兩兩一組，共有4種組合：用 static_cast 父類轉子類、用 static_cast 子類轉父類、使用 ...
  • C語言數據結構：雙向鏈表的增刪操作
    /******************************************************************************************************** * * * 設計雙向鏈表的介面 * * * * Copyright (c) 2023-2 ...
  • @ComponentScan註解的實現，Spring掃描包的過程
    相信接觸過spring做開發的小伙伴們一定使用過@ComponentScan註解 @ComponentScan("com.wangm.lifecycle") public class AppConfig { } @ComponentScan指定basePackage，將包下的類按照一定規則註冊成Be ...
  • opensips開啟python支持
    操作系統 ：CentOS 7.6_x64 opensips版本： 2.4.9 python版本：2.7.5 python作為腳本語言，使用起來很方便，查了下opensips的文檔，支持使用python腳本寫邏輯代碼。今天整理下CentOS7環境下opensips2.4.9的python模塊筆記及使用 ...
所有分類