javaのExceptionのコストについて

弊社提供サービスのおみせやさんへ負荷テストをかけていた際に、特定の条件で非常にパフォーマンスが悪くなることが発覚しました。
調査の結果、根本原因はキャッシュに使用しているMemcachedからオブジェクトをデシリアライズする際のSerializableVersionIDの食い違いにより例外が大量に発生していることが原因でした。
それをうけて、Javaの例外はコストが高いということは言われているので、どれほどのコストがかかるかの実験を行ないました。

実行環境

テストは私の開発機で行いました。
実験に使用したコードは、この記事の一番下に記述しています。

実験その１. 例外を投げるコストの検証

例外なしのものと、例外ありのものでどれほど実行時間に差が出るかを検証しました。

結果

実行時間の単位はミリ秒

やはり、例外の処理はコストがかかることがわかります。
特にStackTraceを取得してしまうと、ただ例外を処理するだけよりさらに５倍以上の時間がかかってしまっており、非常にパフォーマンスが悪いことがわかりました。
例外が投げられない場合は、try/catch clauseの有無については、ほとんど影響は見られませんでした。(多少は影響があるみたいですが、実際の環境ではこんなオーバーヘッドより他の無駄な処理に気を使ったほうがはるかに生産的です。)

実験その２. 例外時のStackTraceの深さによる実行時間の変化の検証

２つ目の実験は、Methodのネスト数=StackTraceの深さを変えて実験を行なってみました。
実験１と同様の処理を行う途中に再帰関数を使って適当な深さをプラスして、例外の処理時間の変化を検証しました。

実行時間の単位はミリ秒

図１:例外発生時のNest数と実行時間の関係

スタックトレースの深さに比例して、実行時間が増加していることがわかります。

教訓

• なるべく例外を使わないプログラムを書いたほうが、パフォーマンスは良くなる
• 特定の条件で大量に例外が投げられる場合は、StackTraceを出さないようにしておいたほうが良い

ただし、StackTraceを出力するのはデバッグや問題の調査に非常に有用であるため極力出したほうがいいです。
パフォーマンスを気にするあまりに例外関連のログを減らしても、問題がどこで起きているかがわからなくなってしまうと本末転倒なので、例外はコストが高いということは頭の片隅に置きつつ十分にログは出力するようにしましょう。

付録

実行結果例

Each test loops 100000 times.

---- Test exception cost ----
Not throw exception: 3 msecs
Not throw exception with try/catch: 4 msecs
Catch exception and get nothing: 83 msecs
Catch exception and get only message: 79 msecs
Catch exception and get message and stacktrace: 385 msecs

---- Test stack trace depth cost ---
1 nested
  not throw: 2 msecs
  throw    : 561 msecs
5 nested
  not throw: 1 msecs
  throw    : 813 msecs
10 nested
  not throw: 1 msecs
  throw    : 1170 msecs
20 nested
  not throw: 3 msecs
  throw    : 1868 msecs
50 nested
  not throw: 7 msecs
  throw    : 3961 msecs

検証コード

public class ExceptionTest{

    static final int LoopCount = 500000;

    public static void main(String[] args){
        System.out.println(String.format("Each test loops %s times.",LoopCount));

        System.out.println();
        System.out.println("---- Test exception cost ----");
        testExceptionCost();

        System.out.println();
        System.out.println("---- Test stack trace depth cost ---");
        testStackDepthCost();

    }

    static void testExceptionCost(){

        doLoop("Not throw exception",new Function(){
            public void apply(){
                notThrowException();
            }
        });
        doLoop("Not throw exception with try/catch",new Function(){
            public void apply(){
                try{
                    notThrowException();
                }catch(Exception e){
                    String message = e.getMessage();
                    e.getStackTrace();
                }
            }
        });

        doLoop("Catch exception and get nothing",new Function(){
            public void apply(){
                try{
                    throwException();
                }catch(Exception e){
                }
            }
        });

        doLoop("Catch exception and get only message",new Function(){
            public void apply(){
                try{
                    throwException();
                }catch(Exception e){
                    String message = e.getMessage();
                }
            }
        });

        doLoop("Catch exception and get message and stacktrace",new Function(){
            public void apply(){
                try{
                    throwException();
                }catch(Exception e){
                    String message = e.getMessage();
                    e.getStackTrace();
                }
            }
        });
    }

    static void testStackDepthCost(){
        testNested(1);
        testNested(5);
        testNested(10);
        testNested(20);
        testNested(50);;
    }

    static interface Function{
        public void apply();
    }

    static void doLoop(String message , Function func){
        long start = System.currentTimeMillis();
        for(int i = 0;i < LoopCount;i++){
            func.apply();
        }
        long delta = System.currentTimeMillis() - start;
        System.out.println(String.format("%s: %s msecs",message,delta));
    }

    static void notThrowException(){
        someProcess();
        Object o = new Object();
    }
    static void throwException(){
        someProcess();
        throw new RuntimeException("Error");
    }

    static void nestedThrowException(int nest) throws Exception{
        if(nest <= 0) {
            someProcess();
            throw new Exception("Nest " + nest);
        }
        else nestedThrowException(nest - 1);
    }
    static void nestedNotThrowException(int nest) throws Exception{
        if(nest <= 0){
            someProcess();
        }
        else nestedNotThrowException(nest - 1);
    }

    static void testNested(final int nest){
        System.out.println(nest + " nested");
        doLoop("  not throw",new Function(){
            public void apply(){
                try{
                    nestedNotThrowException(nest);
                }catch(Exception e){
                    String message = e.getMessage();
                    e.getStackTrace();
                }
            }
        });
        doLoop("  throw    ",new Function(){
            public void apply(){
                try{
                    nestedThrowException(nest);
                }catch(Exception e){
                    String message = e.getMessage();
                    e.getStackTrace();
                }
            }
        });
    }
    static void someProcess(){
        int a = 1;
        int b = 1;
        int c = a + b;
    }
}

Tags

• Tweet