關於提昇 NLog 寫入檔案效能

這是之前一直想做的測試筆記用來比較紀錄 NLog 參數設定對於寫入 log 的效能差異比較，起因是曾經在專案中遇到程式本身沒有問題，卻因為交易龐大產生大量 log 讓 nlog 頻繁讀寫檔案，加上使用傳統硬碟 disk io 速度受限，最後造成系統效能低落，形成嚴重效能瓶頸

剛好同事最近問到相關問題，就來紀錄一下相關比較數據吧

基本設定

1. 使用 console project

2. 安裝 NLog 及 NLog.config

   

3. 加入寫 log 程式

   • 定義 logger

     private static ILogger logger = LogManager.GetCurrentClassLogger();
     

   • 執行 log

     static void Main(string[] args)
     {
         int logcount = 1000000;
         for (int i = 0; i < 5; i++)
         {
             LogToFile(i,logcount);
         }
                 }
                 private static void LogToFile(int index,int logcount)
     {
                     Stopwatch sw = new Stopwatch();
         sw.Start();
         for (int i = 0; i < logcount; i++)
         {
             logger.Debug($"{index}_{i}_{DateTime.Now}");
         }
         sw.Stop();
         logger.Info($"{index}_log 筆數：{logcount};總耗時毫秒：{sw.ElapsedMilliseconds}");
         LogManager.Flush();
     }
     

預設設定

使用原始 NLog.config 所提供的預設設定(僅調整 log folder 跟 layout)

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
    autoReload="true"
    throwExceptions="false"
    internalLogLevel="Off" internalLogFile="c:\temp\nlog-internal.log">
    <targets>
        <target xsi:type="File" name="f" fileName="${basedir}/logs/origin/${shortdate}.${uppercase:${level}}.log"
                layout="${longdate} ${message}" />
    </targets>
    <rules>
        <logger name="*" minlevel="Debug" writeTo="f" />
    </rules>
</nlog>

使用 keepFileOpen

在 target 中加上 keepFileOpen="true" 讓 log file 保持開啟，可以節省開檔、關檔的成本

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Off" internalLogFile="c:\temp\nlog-internal.log">
    <targets>
        <target xsi:type="File" name="f" fileName="${basedir}/logs/keepFileOpen/${shortdate}.${uppercase:${level}}.log"
                layout="${longdate} ${message}" keepFileOpen="true"/>
    </targets>
    <rules>
        <logger name="*" minlevel="Debug" writeTo="f" />
    </rules>
</nlog>

)

使用 async

在 targets 設定使用 asynchronous，讓 nlog 另起 thread 來寫入 log

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Off" internalLogFile="c:\temp\nlog-internal.log">
    <targets async="true">
        <target xsi:type="File" name="f" fileName="${basedir}/logs/async/${shortdate}.${uppercase:${level}}.log"
                layout="${longdate} ${message}" />
    </targets>
    <rules>
        <logger name="*" minlevel="Debug" writeTo="f" />
    </rules>
</nlog>

使用 async + keepFileOpen

同時使用 async 及 keepFileOpen

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Off" internalLogFile="c:\temp\nlog-internal.log">
    <targets async="true">
        <target xsi:type="File" name="f" fileName="${basedir}/logs/asynckeepFileOpen/${shortdate}.${uppercase:${level}}.log"
                layout="${longdate} ${message}" keepFileOpen="true"/>
    </targets>
    <rules>
        <logger name="*" minlevel="Debug" writeTo="f" />
    </rules>
</nlog>

總和比較

心得

除了預設設定之外，在少量 log (1000筆) 的情境下，各個設定的耗時差距都很小，但隨著 log 量增加至 10 萬筆時就會發現 async 效能比 keepFileOpen 較快，此時同時使用 async + keepFileOpen 效能上反而沒有單用 async 快，直到筆數來到百萬筆時，同時使用 async + keepFileOpen 效能上就會超越單用 async，但效果並不是非常顯著

另外有個普遍現象是，第一筆 log 的時間都要較久，原因是第一筆 log 包含建立檔案的時間

最後有個需要特別留意的是開檔效能，使用預設設定需要重複開檔、讀檔、寫檔，因此隨著檔案變大，寫入 log 的時間也就愈來愈長，相同的問題在其他設定上則未發生

參考資訊

1. NLog Configuration file
2. Should NLog flush all queued messages in the AsyncTargetWrapper when Flush() is called?