以下のケースで実験。
- 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にある。