Java：おぼえがき：So-net blog

	ブログをはじめるログイン

log4jの行番号出力は遅いのか＠java　[Java]

log4jでログ出力するときに、ファイル名や行番号も合わせて出力する場合は、レイアウト指定で%Fや％Lを指定すればよいのだけれど、マニュアルを見ると以下のように書いてある。

WARNING Generating caller location information is extremely slow.

ものすごく遅いから気を付けろと。
ソースを見るとわかるんだけど、内部的にはStackTraceを使っているので、そのコストがかかるわけですが、実際にはどれくらい遅いのか測ってみました。

計測環境です。

CPU：Intel(R) Core(TM) i7-2600K CPU @ 3.40GHZ
MEMORY：12.0GB
OS：Windows8 Pro(64ビット)
HDD：SSD(Crucial Real SSD C300)

ソースはこんな感じで。

public class Log4jTest {
  private static Logger logger = Logger.getLogger(Log4jTest.class);
  
  public static void main(String[] args) {
    int num = 0;
    long t1 = 0L;
    long t2 = 0L;

    t1 = System.nanoTime();
    logger.info("hoge");
    t2 = System.nanoTime();

    System.out.println((t2-t1) + " [nsec]");
    logger.info((t2-t1) + " [nsec]");
  }
}

log4j.propertiesはこんな感じ。

log4j.rootLogger=INFO, root log4j.appender.root=org.apache.log4j.RollingFileAppender log4j.appender.root.File=./file.log log4j.appender.root.Append=true log4j.appender.root.MaxFileSize=10MB log4j.appender.root.MaxBackupIndex=20 log4j.appender.root.layout=org.apache.log4j.PatternLayout #log4j.appender.root.layout.ConversionPattern=%-5p %F(%L) - %m%n log4j.appender.root.layout.ConversionPattern=%-5p - %m%n

ログのレイアウトをファイル名+行番号をつけるかつけないかで比べてみました。
実際の運用では、ファイルに出力することが多いと思いますので、ログはファイルに吐くようにしています。
結果は、それぞれ10回ずつ実行して平均をとってみました。

ファイル名+行番号をつけないとき

ファイル名+行番号をつけたとき

結果としては、ファイル名+行番号を出力するだけで、しないときと比べて3～4倍の時間がかかってしまうようで、遅いといえば明らかに遅いです。
まあ、実際問題として遅いとみるか早いとみるかは、実装するアプリケーションの特性によって変わってくるので、何とも言えませんが。
あくまで、僕個人の環境で計測した値なので、参考まで。

2013-06-16 00:56 nice!(0) コメント(0) トラックバック(0)
共通テーマ：パソコン・インターネット