如何提升寫入 Log Performance

撰寫程式時,多少都需要寫 LOG 記錄,
一般使用時都不成問題,不過當需要大量寫入資料就會發現一點點的效能差異影響是很大的,
之前寫了一個 MQTT Broker(Server) ,平時自己用都沒問題,
但最近測試大量連線和封包傳送,就發現速度慢了一截,
LOG 的第三方元件我使用 NLOG,
平時有需要,就一筆一筆寫入 Log,
若需要大量寫入,我會修改 NLog 設定,以 Buffer 方式寫入
大概的設定如下所示

 
一般不使用 Buffer方式

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" autoReload="true" throwExceptions="true">
  <targets>
    <target Name="TraceTarget" xsi:type="File" layout="${level:uppercase=true:padding=-5} ${date:format=yyyy\-MM\-dd\ HH\:mm\:ss\.fffffff} - ${message}" fileName="${basedir}/Log/Trace/Trace.log" archiveFileName="${basedir}/Log/Trace/Trace${date:yyyyMMdd\_HH}.{#}.log" archiveAboveSize="5242880" archiveNumbering="Sequence" concurrentWrites="true" keepFileOpen="false" maxArchiveFiles="100" encoding="UTF-8" />
  </targets>
  <rules>
    <logger Name="Trace" minlevel="DEBUG" writeTo="TraceTarget" LogWvalue="DEBUG" />
  </rules>
</nlog>

使用 Buffer 方式

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" autoReload="true" throwExceptions="true">
  <targets>
    <target xsi:type="BufferingWrapper" Name="TraceBufferingWrapper" bufferSize="100">
      <target Name="TraceTarget" xsi:type="File" layout="${level:uppercase=true:padding=-5} ${date:format=yyyy\-MM\-dd\ HH\:mm\:ss\.fffffff} - ${message}" fileName="${basedir}/Log/Trace/Trace.log" archiveFileName="${basedir}/Log/Trace/Trace${date:yyyyMMdd\_HH}.{#}.log" archiveAboveSize="5242880" archiveNumbering="Sequence" concurrentWrites="true" keepFileOpen="false" maxArchiveFiles="100" encoding="UTF-8" />
    </target>
  </targets>
  <rules>
    <logger Name="Trace" minlevel="DEBUG" writeTo="TraceBufferingWrapper" LogWvalue="DEBUG" />
  </rules>
</nlog>

雖然這樣的寫法就能提升效能,不過程式中寫 Log 的次數頻繁,內部效能還需要再進一步修正,
利用 ConcurrentQueue 先將要寫的 Log 內容推到 Queue 中,每隔 500 ms 再將 Queue 中的內容取出,並寫入 Log

    private string _logSetFile = @".\LogSetting.xml";
    ConcurrentQueue<string> _logQ = new ConcurrentQueue<string>();
    System.Timers.Timer _timer = new System.Timers.Timer();

    public LogTest()
    {
        if (System.IO.File.Exists(_logSetFile) == false)
        {
            try
            { Logger.CreatDefaultLogSettingFile(_logSetFile); }
            catch (Exception ex)
            { MessageBox.Show(ex.ToString()); return; }
        }
        Logger.Initialze(_logSetFile);

        _timer.Elapsed += LogTimeElapsed;
        _timer.Interval = 500;

    }
    
    public void StartLogTestWithQ()
    {
        Logger.CreateInstance("LogTestWithQ");
        _timer.Start();
        _sw2.Start();
        for (int i = 1; i <= 10000; i++)
        {
            _logQ.Enqueue("第 " + i.ToString() + " 筆");
        }
        _sw2.Done();
        _logQ.Enqueue("測試完成花費時間  " + _sw2.ElapsedTime().ToString());
        MessageBox.Show("測試完成花費時間  " + _sw2.ElapsedTime().ToString());
    }
    public void StartLogTestWithoutQ()
    {
        Logger.CreateInstance("LogTestWithoutQ");
        _sw2.Start();
        for (int i = 1; i <= 10000; i++)
        {
            Logger.LogMessage("LogTestWithoutQ", "第 " + i.ToString() + " 筆", LogLevel.Debug);
        }
        _sw2.Done();
        Logger.LogMessage("LogTestWithoutQ", "測試完成花費時間  " + _sw2.ElapsedTime().ToString(), LogLevel.Debug);
        MessageBox.Show("測試完成花費時間  " + _sw2.ElapsedTime().ToString());
    }

    /// <summary>
    /// 利用時間計數,一次寫入 Log ,不要占用太多資源
    /// </summary>
    /// <param name="obj"></param>
    /// <param name="e"></param>
    private void LogTimeElapsed(object obj, System.Timers.ElapsedEventArgs e)
    {
        StringBuilder sb = new StringBuilder();
        while (_logQ.Count > 0)
        {
            string result = "";
            if (_logQ.TryDequeue(out result))
            {
                Logger.LogMessage("LogTestWithQ", result, LogLevel.Debug);
            }
        }

    }

經過測試果然需要 Log Queue 搭配 NLog Buffer 的方式速度才會快
測試寫入 10000 筆資料,結果如下

//LogTestWithQ none Buffer (Log File 寫入時間長,但程式執行時間短)
DEBUG 2021-07-16 10:52:22.2869563 - 第 1 筆
DEBUG 2021-07-16 10:52:28.7547517 - 測試完成花費時間  0.0014641

//LogTestWithoutQ none Buffer (速度最慢)
DEBUG 2021-07-16 10:52:11.8478062 - 第 1 筆
DEBUG 2021-07-16 10:52:16.2525868 - 測試完成花費時間  4.4130297


//LogTestWithQ use Buffer (***速度最快)
DEBUG 2021-07-16 11:01:58.9000957 - 第 1 筆
DEBUG 2021-07-16 11:01:58.9549269 - 測試完成花費時間  0.0018626

//LogTestWithoutQ use Buffer
DEBUG 2021-07-16 11:01:53.5231884 - 第 1 筆
DEBUG 2021-07-16 11:01:53.6112196 - 測試完成花費時間  0.102756