在 multi-thread 的環境當中使用 log4net
為什麼會有這種題目呢?
最主要是在 plurk 上面看到 91 大的討論 http://www.plurk.com/p/1xq9j5
有人提到了不要在 multi-thread 的環境中使用 log4net .
哇! 我一看當然是大吃一斤…一臉屎樣, 如果不能用在 multi-thread 當中, 我寫的系統問題可就大了!
所以有必要好好探討一番.
從 log4net 的 RollingFileAppender 說明可以看到, RollingFileAppender 這個 class 並不是 Thread-Safety 的.
可是我用了 log4net 那麼久, 從來就沒發生過問題呢! 所以決定要好好探究.
在探究這個問題之前, 可以先參考別人對於這個問題的心得:
http://www.l4ndash.com/Log4NetMailArchive/tabid/70/forumid/1/postid/17279/view/topic/Default.aspx
是的, 實際上在寫 log 的時候, 並不是呼叫 RollingFileAppender 的 method 去寫 log, 而是透過 ILog 的 method 去寫的, 所以根據別人的心得, 我們應該是可以在 multi-thread 當中, 直接呼叫 log.Info(“message”)
那麼, 我還是實際寫段小程式來看看歪國人說的是真是假…
首先, 先要撰寫 log4net 用的 config file, 對於 windows applications, 我習慣將 log 獨立寫在 logconfig.xml 當中, 而不是跟 exe.config 混在一起, 因為獨立成一個 config.xml 的好處是, 可以在程式不中斷執行的情形下, 藉由改變 config.xml 檔案來啟動或停止 log 輸出, 或是更改 log 輸出的格式.
logconfig.xml 的內容如下, 我設定了三個 logger , 分別對應到三個 RollingFileAppender
<configuration>
<configSections>
<!-- 為了 log4net 下面這行是需要的 -->
<section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
</configSections>
<!-- log4net 的主要設定 -->
<log4net xmlns="urn:log4net">
<appender name="RollingLogFileAppender_GlobalLog" type="log4net.Appender.RollingFileAppender" >
<param name="File" value="Log\globallog" />
<encoding value="utf-8" />
<param name="AppendToFile" value="true" />
<param name="MaxSizeRollBackups" value="10" />
<param name="MaximumFileSize" value="10MB" />
<param name="RollingStyle" value="Composite" />
<param name="DatePattern" value="yyyyMMdd\.\t\x\t" />
<param name="StaticLogFileName" value="false" />
<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
<layout type="log4net.Layout.PatternLayout">
<param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n" />
</layout>
</appender>
<appender name="RollingLogFileAppender_Thread1Log" type="log4net.Appender.RollingFileAppender" >
<param name="File" value="Log\thread1log" />
<encoding value="utf-8" />
<param name="AppendToFile" value="true" />
<param name="MaxSizeRollBackups" value="10" />
<param name="MaximumFileSize" value="10MB" />
<param name="RollingStyle" value="Composite" />
<param name="DatePattern" value="yyyyMMdd\.\t\x\t" />
<param name="StaticLogFileName" value="false" />
<layout type="log4net.Layout.PatternLayout">
<param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n" />
</layout>
</appender>
<appender name="RollingLogFileAppender_Thread2Log" type="log4net.Appender.RollingFileAppender" >
<param name="File" value="Log\thread2log" />
<encoding value="utf-8" />
<param name="AppendToFile" value="true" />
<param name="MaxSizeRollBackups" value="10" />
<param name="MaximumFileSize" value="10MB" />
<param name="RollingStyle" value="Composite" />
<param name="DatePattern" value="yyyyMMdd\.\t\x\t" />
<param name="StaticLogFileName" value="false" />
<layout type="log4net.Layout.PatternLayout">
<param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n" />
</layout>
</appender>
<appender name="RollingLogFileAppender_Thread3Log" type="log4net.Appender.RollingFileAppender" >
<param name="File" value="Log\thread3log" />
<encoding value="utf-8" />
<param name="AppendToFile" value="true" />
<param name="MaxSizeRollBackups" value="10" />
<param name="MaximumFileSize" value="10MB" />
<param name="RollingStyle" value="Composite" />
<param name="DatePattern" value="yyyyMMdd\.\t\x\t" />
<param name="StaticLogFileName" value="false" />
<layout type="log4net.Layout.PatternLayout">
<param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n" />
</layout>
</appender>
<root>
<level value="WARN" />
<!-- <appender-ref ref="RollingLogFileAppender" /> -->
</root>
<logger name="globallogger">
<level value="DEBUG"/>
<appender-ref ref="RollingLogFileAppender_GlobalLog" />
</logger>
<logger name="threadlogger1">
<level value="DEBUG"/>
<appender-ref ref="RollingLogFileAppender_Thread1Log" />
</logger>
<logger name="threadlogger2">
<level value="DEBUG"/>
<appender-ref ref="RollingLogFileAppender_Thread2Log" />
</logger>
<logger name="threadlogger3">
<level value="DEBUG"/>
<appender-ref ref="RollingLogFileAppender_Thread3Log" />
</logger>
</log4net>
</configuration>
然後測試的程式碼如下, 是個小程式,
我先測多個 thread 對同一個 logger 輸出, 將結果寫在 globallogger 當中,
再測試每個 thread 生出一個 logger, 然後輸出結果在 threadlogger1 當中,
然後測試每個 thread 每個迴圈通通生一個 logger, 將輸出結果寫在 threadlogger2 當中,
最後, 一邊在 thread 寫 log, 另一邊在 thread 讀 log , 將輸出結果寫在 threadlogger3 當中.
目標是希望能夠找出是否會讓 log4net 產生很多 log 檔案, 或是漏寫 log, 或是有任何 error 發生,
using System.Collections.Generic;
using System.Linq;
using System.Text;
using log4net;
using System.Threading;
using System.IO;
namespace multiThreadLog4net
{
class Program
{
static ILog globallogger = LogManager.GetLogger("globallogger");
static string tlog1name = "threadlogger1";
static string tlog2name = "threadlogger2";
static string tlog3name = "threadlogger3";
static void Main(string[] args)
{
log4net.Config.XmlConfigurator.ConfigureAndWatch(new FileInfo(Path.Combine(AppDomain.CurrentDomain.BaseDirectory, "logconfig.xml")));
Console.WriteLine("test global");
TestMultithreadToCallGlobalLogger(100, 1000);
Console.WriteLine("test thread1");
TestMultiThread1(100, 1000);
Console.WriteLine("test thread2");
TestMultiThread2(100, 1000);
Console.WriteLine("test thread3");
TestMultiThread3(100, 30);
}
static void TestMultithreadToCallGlobalLogger(int threadcount, int outputcount)
{
globallogger.Info("Start");
List<Thread> threads = new List<Thread>();
for (int i = 0; i < threadcount; i++)
{
threads.Add(new Thread(() =>
{
for (int j = 0; j < outputcount; j++)
{
globallogger.Info(j.ToString());
}
}));
}
threads.ForEach(t => t.Start());
threads.ForEach(t => t.Join());
globallogger.Info("Over");
}
static void TestMultiThread1(int threadcount, int outputcount) {
ILog l1 = LogManager.GetLogger(tlog1name);
l1.Info("Start");
List<Thread> threads = new List<Thread>();
for (int i = 0; i < threadcount; i++)
{
threads.Add(new Thread(() =>
{
ILog tl1 = LogManager.GetLogger(tlog1name);
for (int j = 0; j < outputcount; j++)
{
tl1.Info(j.ToString());
}
}));
}
threads.ForEach(t => t.Start());
threads.ForEach(t => t.Join());
l1.Info("Done");
}
static void TestMultiThread2(int threadcount, int outputcount)
{
ILog l2 = LogManager.GetLogger(tlog2name);
l2.Info("Start");
List<Thread> threads = new List<Thread>();
for (int i = 0; i < threadcount; i++)
{
threads.Add(new Thread(() =>
{
for (int j = 0; j < outputcount; j++)
{
ILog tl2 = LogManager.GetLogger(tlog2name);
tl2.Info(j.ToString());
}
}));
}
threads.ForEach(t => t.Start());
threads.ForEach(t => t.Join());
l2.Info("Done");
}
static void TestMultiThread3(int threadcount, int outputcount)
{
ILog l3 = LogManager.GetLogger(tlog3name);
l3.Info("Start");
List<Thread> threads = new List<Thread>();
for (int i = 0; i < threadcount; i++)
{
threads.Add(new Thread(() =>
{
for (int j = 0; j < outputcount; j++)
{
l3.Info(j.ToString());
Thread.Sleep(100);
}
}));
}
// scan file thread.
threads.Add(new Thread(() =>
{
for (int j = 0; j < outputcount; j++)
{
// scan files.
string dir = Path.Combine(AppDomain.CurrentDomain.BaseDirectory, "log");
DirectoryInfo di = new DirectoryInfo(dir);
foreach (var fi in di.GetFiles())
{
// open each fi , and read 1 byte then close.
try
{
using (FileStream fs = new FileStream(fi.FullName, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
{
// seek to last, read 1 byte to write out.
fs.Seek(-1, SeekOrigin.End);
l3.Info(String.Format("read {0} 1 bytes:{1:X}", fi.FullName, fs.ReadByte()));
}
}
catch (Exception ex)
{
l3.Error("fail open " + fi.FullName, ex);
}
}
Thread.Sleep(100);
}
}));
threads.ForEach(t => t.Start());
threads.ForEach(t => t.Join());
l3.Info("Done");
}
}
}執行結果:
是的, 只有完整的四個檔案, 我弄不出多個檔案啊~~~
而且這些檔案內容都沒有錯誤, 都是完整的一行一行, 舉例如下:
2009-09-17 17:40:25,306 [7644] INFO globallogger - Start
2009-09-17 17:40:25,328 [7076] INFO globallogger - 0
2009-09-17 17:40:25,329 [7076] INFO globallogger - 1
2009-09-17 17:40:25,329 [7076] INFO globallogger - 2
2009-09-17 17:40:25,330 [7076] INFO globallogger - 3
2009-09-17 17:40:25,330 [7076] INFO globallogger - 4
2009-09-17 17:40:25,331 [7076] INFO globallogger - 5
2009-09-17 17:40:25,331 [7076] INFO globallogger - 6
2009-09-17 17:40:25,332 [7076] INFO globallogger - 7
2009-09-17 17:40:25,332 [7076] INFO globallogger - 8
2009-09-17 17:40:25,332 [7076] INFO globallogger - 9
2009-09-17 17:40:25,333 [6784] INFO globallogger - 0
2009-09-17 17:40:25,334 [6784] INFO globallogger - 1
2009-09-17 17:40:25,335 [6784] INFO globallogger - 2
2009-09-17 17:40:25,335 [6784] INFO globallogger - 3
2009-09-17 17:40:25,336 [6784] INFO globallogger - 4
2009-09-17 17:40:25,336 [6784] INFO globallogger - 5
2009-09-17 17:40:25,336 [6784] INFO globallogger - 6
2009-09-17 17:40:25,337 [6784] INFO globallogger - 7
2009-09-17 17:40:25,337 [6784] INFO globallogger - 8
2009-09-17 17:40:25,338 [6784] INFO globallogger - 9
2009-09-17 17:40:25,338 [6784] INFO globallogger - 10
2009-09-17 17:40:25,333 [7580] INFO globallogger - 0
2009-09-17 17:40:25,338 [6784] INFO globallogger - 11
2009-09-17 17:40:25,339 [6784] INFO globallogger - 12
2009-09-17 17:40:25,340 [6784] INFO globallogger – 13
其中中括弧內的就是 thread id, 所以可以看出 thread 交雜寫出 log, 但每行資料都是完整的.
不過, 我還是不放心, 所以我直接去 Trace 看看 log4net 的原始碼, log4net 已經很久沒更新了,
目前大家應該用的就是最新版: http://logging.apache.org/log4net/download.html log4net 1.2.10 , 2006/3/30 release 的版本.
利用原始碼單步執行, 我們可以直接欣賞高手寫的程式, 順便看看有何問題.
首先單步執行到寫 log 的那一行:
按下 F11, 恩, 果然不是 RollingFileAppender 的 method, 而是 LogImpl 這個 class 的 Info
一路追下去, 原來寫 log 是產生一個 logevent, 然後丟給每個 appender, 終於我看到 locker 了:
不過上面這個 ReaderWriterLock 似乎不是針對寫 log, 而是針對 multi-thread 時 addAppender, removeAppender 所設計的,
所以繼續追下去:
是的, 原來在寫 log 的時候, 是透過 RollingFileAppender 的基礎型別 AppenderSkeleton 的 DoAppend 函式去寫的,
而該函式利用 lock(this) 避免了 multi-thread 造成寫 log 錯誤 (lock(this) 的上方說明的很詳細)
最後才呼叫了 RollingFileAppender 的 Append , 但此時已經在 lock(this) 當中,
所以 RollingFileAppender 雖然不支援 multi-thread,
而且他的基礎型別 AppenderSkeleton 也不支援 multi-thread ,
但是 AppenderSkeleton 的 DoAppend 支援! (透過 lock this)
所以驗證那個外國人說的是對的 “log4net is thread safe as it says in the FAQ.”
