[intlink id=”558″],[intlink id=”555″],[intlink id=”548″]の続き。 log4net, LoggingAB, NLogを比較してみた。

名前	DLLサイズ	速度	評価
log4net 1.2.10	270,336 bytes	70us/行	ハマりどころなし。よくできている。
NLog 1.0	253,952 bytes	67us/行	バッファリング設定しないと遅い。きめ細かい設定ができるともいえる。
LoggingAB Enterprise Library 3.1	379,728 bytes	224us/行	遅い。かゆいところに手が届かない印象。
出力なし	0 bytes	51us/行	最速だがログ出力してない(笑)

まとめ 個人的にはNLogが好きなんだけど、実績とか考えるとlog4net使っとくのが無難だと思う。 LogginABはオススメできない。

log4netはたぶんユーザ数が最多。 log4j使ってた経験があるなら設定とかすぐわかる。 パフォーマンスも隙がない。

NLogは2006年からwebサイト更新されてないように見える。 十分枯れてると思うが、ちょっと不安。好意的に見れば、枯れててバージョンアップが不要なのかも？？

LoggingABは重過ぎる。自作のリスナーとか作れば改善するかもしれない。 他のEnterprise Library機能と組み合わせるときにはこれしか選択肢なし。 ログ出力機能だけがほしいのであればオーバスペック。 Microsoftやpatterns & practicesが好きなら担いで見るのもよい。 あと、設定が一番ゴチャゴチャしてる。 専用の設定エディターが付属するけど、使い心地が微妙でもどかしい。

速度比較は日付単位ローテーションファイルへの出力。

「なし」は以下の空実装でログ出力を代用したもの。

class LOG
{
	public static void Info(string aMessage)
	{
	}

	public static bool IsInfoEnabled
	{
		get { return true; }
	}
}

テスト条件

テストに使用したプログラムは、25番目のフィボナッチ数を求めるプログラム。

class Program
{
	public static void Main(string[] args)
	{
		int tStartTimeMillis = System.Environment.TickCount;
		using (new Tracer("Trace"))
		{
			LOG.Info("fib(25) = " + fib(25));
		}
		int tEndTimeMillis = System.Environment.TickCount;
		Console.WriteLine("time: " + (tEndTimeMillis - tStartTimeMillis) + "ms");
	}

	static long fib(long n)
	{
		using (new Tracer("Trace"))
		{
			if (n <= 1)
			{
				return 1;
			}
			return fib(n - 2) + fib(n - 1);
		}
	}
}

25番目のフィボナッチ数を再帰を使って計算すると、242786回の再帰呼び出しを起こす。 再帰のたびにTracerを使ってログ出力してみた。 LoggingABにはMicrosoft.Practices.EnterpriseLibrary.Logging.Tracerが実装されているのでそれを使った。 log4netとNLogにはTracerがないので以下の自作のものを使った。

class Tracer : IDisposable
{
#if LOG4NET
	private static readonly ILog LOG = LogManager.GetLogger(typeof(Tracer));
#else
	private static readonly Logger LOG = LogManager.GetCurrentClassLogger();
#endif
	private Stopwatch mStopwatch;
	private long mStartTicks;

	public Tracer(string aCategory)
	{
		if (LOG.IsInfoEnabled)
		{
			if (Trace.CorrelationManager.ActivityId.Equals(Guid.Empty))
			{
				Trace.CorrelationManager.ActivityId = Guid.NewGuid();
			}
			Trace.CorrelationManager.StartLogicalOperation(aCategory);
			mStopwatch = Stopwatch.StartNew();
			mStartTicks = Stopwatch.GetTimestamp();
			LOG.Info("Start " + aCategory + ": Activity '" + Trace.CorrelationManager.ActivityId + "' in method '" + GetExecutingMethodName() + "' at " + mStopwatch.ElapsedTicks + " ticks");
		}
	}

	public void Dispose()
	{
		if (LOG.IsInfoEnabled)
		{
			try
			{
				long tEndTicks = Stopwatch.GetTimestamp();
				long tElapsedMillis = mStopwatch.ElapsedMilliseconds;
				LOG.Info("End " + Trace.CorrelationManager.LogicalOperationStack.Peek() + ": Activity '" + Trace.CorrelationManager.ActivityId + "' in method '" + GetExecutingMethodName() + "' at " + tEndTicks + " ticks (elapsed time: " + tElapsedMillis + " ms)");
			}
			finally
			{
				Trace.CorrelationManager.StopLogicalOperation();
			}
		}
		GC.SuppressFinalize(this);
	}

	private string GetExecutingMethodName()
	{
		string tResult = "Unknown";
		StackTrace tStackTrace = new StackTrace(false);

		for (int i = 0; i < tStackTrace.FrameCount; i++)
		{
			MethodBase tMethod = tStackTrace.GetFrame(i).GetMethod();
			if (tMethod.DeclaringType != GetType())
			{
				tResult = string.Concat(tMethod.DeclaringType.FullName, ".", tMethod.Name);
				break;
			}
		}

		return tResult;
	}
}

ログの出力設定はできるだけあわせたんだけど・・・。 log4net

出力

2008-03-22 06:58:09,652 [1] INFO  - Start Trace: Activity '3fe83136-62f7-48a5-b57c-b643c506e753' in method 'Log4netTest.Program.fib' at 665 ticks
2008-03-22 06:58:09,652 [1] INFO  - End Trace: Activity '3fe83136-62f7-48a5-b57c-b643c506e753' in method 'Log4netTest.Program.fib' at 9356634867556 ticks (elapsed time: 0 ms)

NLog

出力

2008/03/22 07:02:44,181 [1] Info - Start Trace: Activity '9b409697-f680-48fb-a868-dbcae2eadd39' in method 'NLogTest.Program.fib' at 653 ticks
2008/03/22 07:02:44,181 [1] Info - End Trace: Activity '9b409697-f680-48fb-a868-dbcae2eadd39' in method 'NLogTest.Program.fib' at 9360565483535 ticks (elapsed time: 0 ms)

LoggingAB

出力

2008/03/21 22:06:10 [5752] Start - Start Trace: Activity 'ddea2bbb-de2e-42a0-a167-1461a71b7074' in method 'LoggingABTest.Program.fib' at 9363521594110 ticks
2008/03/21 22:06:10 [5752] Stop - End Trace: Activity 'ddea2bbb-de2e-42a0-a167-1461a71b7074' in method 'LoggingABTest.Program.fib' at 9363521611483 ticks (elapsed time: 0.001 seconds)

結果

	log4net	NLog +BufferingWrapper	NLog	LoggingAB	出力なし
1回目(ms)	34008	32604	612397	108842	24742
2回目(ms)	34023	32807	-	109076	24820
3回目(ms)	34024	33509	-	108826	24820
4回目(ms)	34008	32449	-	108686	24758
5回目(ms)	33961	32417	-	109060	24741
平均(ms)	34005	32757	612397	108898	24776
行数(行)	485574	485574	485574	485574	485574
(us/行)	70	67	1261	224	51
485574行あたりのファイルサイズ(bytes)	78,426,276	76,485,442	76,485,442	82,784,994	-
(bytes/ms)	2306	2335	125	760	-

log4netとNLogの速度は互角。LoggingABは3倍遅い。

おしまい。