2010年11月26日 12:45

appengine上のcommons-loggingパフォーマンスチェック

appengineではログ出力にjava.util.logging.Loggerを推奨しています。しかしcommons-loggingに慣れているとLoggerのロギングレベルが違和感ありまくりんぐ。

 

参考:ざっくりとした対応図

java.util.logging: FINEST < FINER < FINE  < CONFIG < INFO < WARNING < SEVERE = SEVERE
commons-logging  : TRACE  = TRACE < DEBUG < INFO  = INFO < WARN    < ERROR  < FATAL

自分の開発ではcommons-loggingで

org.apache.commons.logging.Log=org.apache.commons.logging.impl.Jdk14Logger

てな感じでやってるのですが、Slim3だと直接Loggerを呼んでるし実際はどっちがいいのだろうかと思い、いろいろパフォーマンスを調べてみました。

 

サンプル1:java.util.logging.Loggerを直接インスタンス生成(公式推奨)
import java.util.logging.Level;
import java.util.logging.Logger;

import org.junit.Test;

public class Sample1Test {
    private static final Logger log = Logger.getLogger(Sample1Test.class.getName());

    private static final int MAX_COUNT = 1000000;

    @Test
    public void test1(){
        for(int i = 0; i < MAX_COUNT; i++){
            log.log(Level.FINE, "test");
        }
    }

    @Test
    public void test2(){
        for(int i = 0; i < MAX_COUNT; i++){
            Logger log = Logger.getLogger(Sample1Test.class.getName());
            log.log(Level.FINE, "test");
        }
    }

}
サンプル2:commons-loggingのLogを設定ファイル経由でインスタンス生成
import org.junit.Test;

import com.google.appengine.repackaged.org.apache.commons.logging.Log;
import com.google.appengine.repackaged.org.apache.commons.logging.LogFactory;

public class Sample2Test {
    private static final Log log = LogFactory.getLog(Sample2Test.class.getName());

    private static final int MAX_COUNT = 1000000;

    @Test
    public void test1(){
        for(int i = 0; i < MAX_COUNT; i++){
            log.debug("test");
        }
    }

    @Test
    public void test2(){
        for(int i = 0; i < MAX_COUNT; i++){
            Log log = LogFactory.getLog(Sample2Test.class.getName());
            log.debug("test");
        }
    }

}
サンプル3:commons-loggingのLogを直接インスタンス生成
import org.junit.Test;

import com.google.appengine.repackaged.org.apache.commons.logging.Log;
import com.google.appengine.repackaged.org.apache.commons.logging.impl.Jdk14Logger;

public class Sample3Test {
    private static final Log log = new Jdk14Logger(Sample3Test.class.getName());

    private static final int MAX_COUNT = 1000000;

    @Test
    public void test1(){
        for(int i = 0; i < MAX_COUNT; i++){
            log.debug("test");
        }
    }

    @Test
    public void test2(){
        for(int i = 0; i < MAX_COUNT; i++){
            Log log = new Jdk14Logger(Sample3Test.class.getName());
            log.debug("test");
        }
    }

}

プロダクション環境で動かしてみた結果
sc0003.png
サンプル1は公式推奨だけあって確かに速い。ただ、サンプル3も100万回ループ回して111ms, 260cpu_msの差なのでパフォーマンス的にはそんなに変わらない。

サンプル2のtest2で一気に処理時間増えてるのはファイル解析時にリフレクションが発生しているからかと。普通Logger系はstaticフィールドで持たせると思いますが、頻繁にスピンダウンが発生するとstaticフィールドもその度に初期化されるのでtest2のような状況もおこりえます。(たくさんのクラスのフィールドにLoggerがあるならなおさら)

 

結論:基本は公式の言うとおりにjava.util.logging.Loggerを使ってればOK。しかしcommons-loggingでJdk14Loggerを直接newしてもオーバーヘッドは大したことないのでcommons-logging派はこちらを使うといいかと。