覚えたら書く

IT関係のデベロッパとして日々覚えたことを書き残したいです。twitter: @yyoshikaw

例外のスタックトレースが出力されなくなる

Java

Javaアプリケーションを実行していると、ずっと出力できていた例外（Exception）のスタックトレース（StackTrace）が出力されなくなる場合があります。
気づいてみたら、あれ？ログに例外のスタックトレースが出ていない！　というような状況に出くわすことが稀にあったりします。

同じスタックトレースを何度も何度も出力していると、HotSpot VMの最適化が適用されて本現象が発生する様です。

HotSpot VMの実行時最適化の一環で、繰り返し出力される一部の組み込み例外では、
同じインスタンスを使い回すことでインスタンス生成コストを抑える処理が行われる様です。
使いまわされる例外のインスタンスは、他の場所ででthrowされた例外の情報が混入しないように、スタックトレースそのものが省略されるようです。

これを抑止するためのVMオプションが -XX:-OmitStackTraceInFastThrow です。

このオプションを指定すると、この最適化が行われなくなり、スタックトレースが出ないということは無くなります。

サンプルで試してみましょう。


基本的にひたすらNullPointerExceptionのスタックトレースをログ出力するサンプルになっています


(1) 数回NullPointerExceptionのスタックトレースを出力する

繰り返し3回だけNullPointerExceptionのスタックトレースをログ出力します

■実行用プログラム

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class OmitExceptionSample {

    private static final Logger logger = LoggerFactory.getLogger(OmitExceptionSample.class);

    private static String nullString = null;

    public static void main(String[] args) {
        for (int i = 0; i < 3; i++) {
            traceNulPointerException(i);
        }

    }

    private static void  traceNulPointerException(int index) {
        logger.info("call traceNulPointerException {}", index);
        try {
            int length = nullString.length();
        } catch (NullPointerException e) {
            logger.warn("Caught Exception.", e);
        }
    }
}


■実行結果

16:41:32.922 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 0
16:41:32.932 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
    at net.yyuki.exception.OmitExceptionSample.traceNulPointerException(OmitExceptionSample.java:22)
    at net.yyuki.exception.OmitExceptionSample.main(OmitExceptionSample.java:14)
16:41:32.933 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 1
16:41:32.933 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
    at net.yyuki.exception.OmitExceptionSample.traceNulPointerException(OmitExceptionSample.java:22)
    at net.yyuki.exception.OmitExceptionSample.main(OmitExceptionSample.java:14)
16:41:32.933 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 2
16:41:32.933 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
    at net.yyuki.exception.OmitExceptionSample.traceNulPointerException(OmitExceptionSample.java:22)
    at net.yyuki.exception.OmitExceptionSample.main(OmitExceptionSample.java:14)

スタックトレースが出力され続けています。


(2) 10万回NullPointerExceptionのスタックトレースを出力する

繰り返し10万回NullPointerExceptionのスタックトレースをログ出力します

■実行用プログラム

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class OmitExceptionSample {

    private static final Logger logger = LoggerFactory.getLogger(OmitExceptionSample.class);

    private static String nullString = null;

    public static void main(String[] args) {
        for (int i = 0; i < 100000; i++) {
            traceNulPointerException(i);
        }

    }

    private static void  traceNulPointerException(int index) {
        logger.info("call traceNulPointerException {}", index);
        try {
            int length = nullString.length();
        } catch (NullPointerException e) {
            logger.warn("Caught Exception.", e);
        }
    }
}


■実行結果

16:43:14.822 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 0
16:43:14.822 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
    at net.yyuki.exception.OmitExceptionSample.traceNulPointerException(OmitExceptionSample.java:22)
    at net.yyuki.exception.OmitExceptionSample.main(OmitExceptionSample.java:14)
16:43:14.823 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 1
16:43:14.823 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
    at net.yyuki.exception.OmitExceptionSample.traceNulPointerException(OmitExceptionSample.java:22)
    at net.yyuki.exception.OmitExceptionSample.main(OmitExceptionSample.java:14)

（中略）

16:43:15.753 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 99996
16:43:15.753 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
16:43:15.753 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 99997
16:43:15.753 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
16:43:15.753 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 99998
16:43:15.753 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
16:43:15.753 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 99999
16:43:15.753 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null

最初はスタックトレースが出力さていますが、後半出力されなくなっています。


(3) -XX:-OmitStackTraceInFastThrowを指定する。

-XX:-OmitStackTraceInFastThrowをVMオプションに指定して、実行してみます。10万回NullPointerExceptionのスタックトレースを出力します。

実行用のプログラムは、(2)と同じです

■実行結果

16:43:04.722 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 0
16:43:04.722 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
    at net.yyuki.exception.OmitExceptionSample.traceNulPointerException(OmitExceptionSample.java:22)
    at net.yyuki.exception.OmitExceptionSample.main(OmitExceptionSample.java:14)
16:43:04.723 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 1
16:43:04.723 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
    at net.yyuki.exception.OmitExceptionSample.traceNulPointerException(OmitExceptionSample.java:22)
    at net.yyuki.exception.OmitExceptionSample.main(OmitExceptionSample.java:14)

（中略）

16:47:08.694 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 99996
16:47:08.694 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
    at net.yyuki.exception.OmitExceptionSample.traceNulPointerException(OmitExceptionSample.java:22)
    at net.yyuki.exception.OmitExceptionSample.main(OmitExceptionSample.java:14)
16:47:08.694 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 99997
16:47:08.694 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
    at net.yyuki.exception.OmitExceptionSample.traceNulPointerException(OmitExceptionSample.java:22)
    at net.yyuki.exception.OmitExceptionSample.main(OmitExceptionSample.java:14)
16:47:08.694 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 99998
16:47:08.694 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
    at net.yyuki.exception.OmitExceptionSample.traceNulPointerException(OmitExceptionSample.java:22)
    at net.yyuki.exception.OmitExceptionSample.main(OmitExceptionSample.java:14)
16:47:08.694 [main] INFO net.yyuki.exception.OmitExceptionSample - call traceNulPointerException 99999
16:47:08.694 [main] WARN net.yyuki.exception.OmitExceptionSample - Caught Exception.
java.lang.NullPointerException: null
    at net.yyuki.exception.OmitExceptionSample.traceNulPointerException(OmitExceptionSample.java:22)
    at net.yyuki.exception.OmitExceptionSample.main(OmitExceptionSample.java:14)

最後までスタックトレースが出力さています。


まとめ

組み込み例外のスタックトレースを何度も出力しなければならないが、そのスタックトレースが出なくなるのを抑止したい場合は、
-XX:-OmitStackTraceInFastThrow の VMオプション を付与しましょう。