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オプション を付与しましょう。