Java异常堆栈丢失的现象及解决方法

问题描述

查看线上log时，发现了一些npe异常，但是没有堆栈信息。

...
java.lang.NullPointerException
...

没有堆栈信息，也就意味着没法定位问题代码，第一反应是查看记日志的代码（用的logback），确认没有问题后，开始google和stackOverflow。

结论

一般情况下，当异常发生时，JVM会回溯调用栈，构建异常对象（包含完整的堆栈信息）。但是出于性能考虑，如果某个方法一直抛出同样的异常，比如npe，JVM会重新编译该方法（JIT编译器），然后抛出事先创建好的异常（没有堆栈信息）。

JDK5.0的发布说明里有相关描述：

The compiler in the server VM now provides correct stack backtraces for all "cold" built-in exceptions. For performance purposes, when such an exception is thrown a few times, the method may be recompiled. After recompilation, the compiler may choose a faster tactic using preallocated exceptions that do not provide a stack trace. To disable completely the use of preallocated exceptions, use this new flag: -XX:-OmitStackTraceInFastThrow.

https://www.oracle.com/technetwork/java/javase/relnotes-139183.html

复现&解决方案

复现问题

执行如下代码：

for (int i = 0; i < 200000; i++) {
    try {
        ((String) null).toString();
    } catch (Exception e) {
        int stackTraceLength = e.getStackTrace().length;
        System.out.println(i + "，堆栈长度：" + stackTraceLength);
    }
}

在我的电脑上，循环115716次后，堆栈长度就为0了，即堆栈信息为空，如下：

...
115713，堆栈长度：1
115714，堆栈长度：1
115715，堆栈长度：0
115716，堆栈长度：0
...

所以，验证了JVM确实会进行一些优化，出现没有堆栈的异常。

解决方案

• 通过JVM参数禁用此优化。
  JDK5.0 Release Notes里说的很明确，通过添加JVM参数禁用此优化：-XX:-OmitStackTraceInFastThrow。
• 查看更早之前的log，直到相关的异常堆栈，解决掉。
  如上文所说，只有某个异常出现了若干次后，才可能触发优化条件。所以，最初的日志里肯定是有完整的堆栈信息。

如果日志比较少，考虑直接往前追溯log，找到异常堆栈，解决问题。
如果日志比较多，考虑在线上先给JVM增加参数禁用此优化，解决问题后，再移除参数，开启优化。

最后

以此为假设，在线上往前追溯log，最终在5天前的日志里找到了相关异常的堆栈信息，定位到问题，解决起来就比较简单了。
本文以流水账的方式描述了遇到的问题和解决方案，其实还是很多东西值得继续调研，比如JVM为什么要这个优化，JVM的异常机制是如何运行的，为什么会这么慢，等等。

参考

[1] Hotspot caused exceptions to lose their stack traces in production – and the fix