[.NET][log4net]解決FileAppender+MinimalLock效能問題(一)(Buffering)

2016-09-27

7744
0
Log應用
2016-09-28

為了避免多個Process對同一個log檔案寫入而引發檔案鎖定或者相互覆蓋而出現log內容遺失問題，在log4net config中，我們會設定FileAppender+MinimalLock屬性，但啟動minimalLock屬性後，如果程式有大量的log需求，效能就會受到影響。

實驗的步驟:

實作目前的情境(minimalLock啟動及關閉的兩種狀況)。
接著改用BufferingForwardingAppender，觀察比較3種結果。

log4net引用

在指定的VisualStudio專案按右鍵 > 打開VisualStudio NuGet封裝管理員 > 輸入log4net搜尋，然後點選右邊的安裝

接著在專案目錄中新增一個組態檔案log4net.config

log4net.config輸入以下內容

<?xml version="1.0" encoding="utf-8" ?>
<log4net>

  <root>
    <level value="All"/>
    <appender-ref ref="RollingFile" />
  </root>
  
  <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
    <file type="log4net.Util.PatternString" value="Log/Log-%date{yyyyMMdd}/Debug.log" />
    <lockingModel type="log4net.Appender.FileAppender+MinimalLock" /> 
    <appendToFile value="true"/>
    <rollingStyle value="Composite"/>
    <maxSizeRollBackups value="-1"/>
    <maximumFileSize value="50MB"/>
    <staticLogFileName value="true"/>
    <datePattern value="yyyy-MM-dd"/>
    <countDirection value="1"/>
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date{ISO8601} [%2thread] - %message%newline%exception"/>
    </layout>
  </appender>

在安裝log4net的專案中新增一隻測試程式，程式碼內容:

private static readonly ILog Logger = LogManager.GetLogger(typeof(testLog4net));
[TestMethod]
public void TestMethod1()
{
    XmlConfigurator.Configure(new FileInfo(string.Format(@"{0}\{1}",
        Directory.GetParent(Directory.GetParent(Environment.CurrentDirectory).FullName),
        "log4net.config")));
    Stopwatch sw = new Stopwatch();
    sw.Start();
    for (int i = 0; i < 1000; i++)
    {
        Logger.Debug(string.Format("this is no{0} log", i + 1));
    }
    sw.Stop();
    Console.WriteLine("總耗時(ElapsedMilliseconds) = " + sw.ElapsedMilliseconds);
}

執行結果: 1,000筆25秒

log檔案內容:

關閉minimalLock屬性再測試:

測試結果: 1,000筆14毫秒

果然有時間單位的差距，但如果一定要啟用minimalLock，試試看BufferingForwardingAppender

BufferingForwardingAppender

引用BufferingForwardingAppender不用改程式，只要改Config，讓log先寫到buffer，到達blocksize或是process結束時再寫出到log檔案。

我們這邊先設定BufferSize = 512

<?xml version="1.0" encoding="utf-8" ?>
<log4net>

  <root>
    <level value="All"/>
    <!--<appender-ref ref="RollingFile" />-->
    <appender-ref ref="BufferingForwarder" /> 
  </root>

 <appender name="BufferingForwarder" type="log4net.Appender.BufferingForwardingAppender">
    <bufferSize value="512" />
    <lossy value="false" />
    <Fix value="8" />
    <appender-ref ref="RollingFile" />
  </appender>
  
  <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
    <file type="log4net.Util.PatternString" value="Log/Log-%date{yyyyMMdd}/Debug.log" />
    <lockingModel type="log4net.Appender.FileAppender+MinimalLock" /> 
    <appendToFile value="true"/>
    <rollingStyle value="Composite"/>
    <maxSizeRollBackups value="-1"/>
    <maximumFileSize value="50MB"/>
    <staticLogFileName value="true"/>
    <datePattern value="yyyy-MM-dd"/>
    <countDirection value="1"/>
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date{ISO8601} [%2thread] - %message%newline%exception"/>
    </layout>
  </appender>

</log4net>

測試結果: 1,000筆123毫秒