log4jとlogbackのパフォーマンス比較

以下のケースで実験。

logback単体
log4j単体
SLF4J + log4j
SLF4J + logback

条件は以下。

CPU:Core 2 Duo T8100 2.1GHz
Memory:2G
PC:藤原のDellラップトップ
Eclipse Ganymedeから実行
1回のテストで100万行出力。これを3回連続で実施。
ログ出力のフォーマットは同じ（文字数もそろえた）
ログ出力開始から終了までの秒数を測定

ソースコードは以下のような感じ。Loggerを差し替えて実施している。

public class LogBackPerformanceSample {
final static Logger logger = LoggerFactory
.getLogger(LogBackPerformanceSample.class);
public static void main(String[] args) {
long start = System.currentTimeMillis();
int cnt = 1000;
for (int i = 0; i < cnt; i++) {
for (int j = 0; j < cnt; j++) {
logger.debug("fujihara.");
}
}
long end = System.currentTimeMillis();
logger.debug(String.valueOf((end -start) / 1000));
}
}

log4j単体の結果

一番速い。

// 1回目
2008-11-16 15:03:19,524 DEBUG com.daipresents.logging.log4j12.Log4j12PerformanceSample - fujihara.
2008-11-16 15:03:19,524 DEBUG com.daipresents.logging.log4j12.Log4j12PerformanceSample - 87
// 2回目
2008-11-16 15:05:00,776 DEBUG com.daipresents.logging.log4j12.Log4j12PerformanceSample - fujihara.
2008-11-16 15:05:00,776 DEBUG com.daipresents.logging.log4j12.Log4j12PerformanceSample - 90
// 3回目
2008-11-16 15:06:46,844 DEBUG com.daipresents.logging.log4j12.Log4j12PerformanceSample - fujihara.
2008-11-16 15:06:46,845 DEBUG com.daipresents.logging.log4j12.Log4j12PerformanceSample - 91

Ave89.3秒。

SLF4J + log4jの結果

一番遅い。

//1回目
2008-11-16 15:13:54,438 DEBUG com.daipresents.logging.log4j12.Log4jSLPerformanceSample - fujihara.
2008-11-16 15:13:54,438 DEBUG com.daipresents.logging.log4j12.Log4jSLPerformanceSample - 100
// 2回目
2008-11-16 15:15:34,489 DEBUG com.daipresents.logging.log4j12.Log4jSLPerformanceSample - fujihara.
2008-11-16 15:15:34,489 DEBUG com.daipresents.logging.log4j12.Log4jSLPerformanceSample - 88
// 3回目
2008-11-16 15:18:04,503 DEBUG com.daipresents.logging.log4j12.Log4jSLPerformanceSample - fujihara.
2008-11-16 15:18:04,504 DEBUG com.daipresents.logging.log4j12.Log4jSLPerformanceSample - 96

Ave94.6秒。

SLF4J + logbackの結果

多少遅いが気にならない程度な気がする。logbackだけ単体で呼び出すとlog4jより早いかもなー。

// 1回目
2008-11-16 14:55:39,662 DEBUG com.daipresents.logging.logback.LogBackPerformanceSample - fujihara.
2008-11-16 14:55:39,663 DEBUG com.daipresents.logging.logback.LogBackPerformanceSample - 93
// 2回目
2008-11-16 14:58:34,712 DEBUG com.daipresents.logging.logback.LogBackPerformanceSample - fujihara.
2008-11-16 14:58:34,713 DEBUG com.daipresents.logging.logback.LogBackPerformanceSample - 86
// 3回目
2008-11-16 15:00:29,494 DEBUG com.daipresents.logging.logback.LogBackPerformanceSample - fujihara.
2008-11-16 15:00:29,494 DEBUG com.daipresents.logging.logback.LogBackPerformanceSample - 94

Ave91秒。

logback単体の結果

logback単体でできんもんか調べてみたけど、以下のようなやり方でlogbackのロガー指定でとってみた。

LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();
Logger logger = lc.getLogger(LogBackOnlyPerformSample.class);

SLF4J + logbackの結果と同じLoggerが使われるんだろうけど、スピードが若干違った。

// 1回目
2008-11-24 15:46:11,179 DEBUG com.daipresents.logging.logback.LogBackOnlyPerformSample - fujihara.
2008-11-24 15:46:11,179 DEBUG com.daipresents.logging.logback.LogBackOnlyPerformSample - 86
// 2回目
2008-11-24 15:47:59,810 DEBUG com.daipresents.logging.logback.LogBackOnlyPerformSample - fujihara.
2008-11-24 15:47:59,810 DEBUG com.daipresents.logging.logback.LogBackOnlyPerformSample - 88
// 3回目
2008-11-24 15:49:36,529 DEBUG com.daipresents.logging.logback.LogBackOnlyPerformSample - fujihara.
2008-11-24 15:49:36,529 DEBUG com.daipresents.logging.logback.LogBackOnlyPerformSample - 78

Ave84秒。

結果まとめ

logback単体 Ave84秒。
log4j単体 Ave89.3秒。
SLF4J + logback Ave91秒。
SLF4J + log4j Ave94.6秒。

logbackは優秀。

発展しつつあるJavaのロギング by InfoQにもあるように、

例えば、ログステートメントを記録するかどうかを確定するような、クリティカルな操作はかなり改善されました。この操作に、LOGBackではおよそ3ナノ秒かかるのに対して、Log4jでは30ナノ秒かかります。LOGBackはロガーの生成も高速です。Log4jの23マイクロ秒に対して、13マイクロ秒です。さらにすごいのは、既存のロガーを取ってくるのに、Log4jは2234ナノ秒なのに対して、94ナノ秒で23倍も高速なのです。 JUL(java.util.logging)における改善も決してわずかなものではありません。LOGBackはEclipseプラグインやJMX MBeanとも統合されている。

と語るだけあり、開発が止まりかけているlog4jよりも改善されているように見える。
今回のソースはGoogle Code – daipresentsのLogBackSampleとLog4jSampleにある。