log4net, LoggingAB, NLogを比較してみた

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

まとめ
個人的には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の速度は互角。LoggingABは3倍遅い。

おしまい。