一、问题发生

今天同事私聊我,问了我一个问题,他说在一个美国的海外仓项目中发现一个奇怪的报错日志:只有error 日志信息和一个 NPE 日常,但是没有打印出具体的堆栈。

他问我有没有遇到过。

我心里第一个想法:是不是打印日志的地方写得不规范,只把 Exception 的 message 打印了,类似这样:

log.error("…… ", exception.getMessage());

去看了一下代码,发现代码中其实是完整打印的:

try {
    // 执行调度逻辑:方法内部调用算法服务,分配库存
} catch (Exception exception) {
     log.error("……",  exception);
} finally {
     //
}

二、求助 AI

面对这个反常的现象,我一开始也向我的好帮手——AI 提问了。

我尝试了各种姿势,并给了一些上下文,去问 AI,得到了一些排查方向:
​1. 确认日志框架​
确认项目使用的是 Logback, Log4j2 还是其他日志框架。
​2. 检查日志级别​
确保记录异常时使用的级别(如 ERROR)在配置中是启用的。
​3. 检查日志配置​
核对配置文件(如 logback.xml, log4j2.xml),看输出目的地(控制台、文件)是否正确。
​4. 验证日志实现​
在 catch块中增加简单输出(如 System.out.println),确认代码执行路径。
……

但似乎没找到我想要的答案。

三、拨云见日:十年前的“老帖子”

我决定重新梳理所有上下文,包括业务的调用频率、JVM 的运行环境等等。这个定时器是高频运行的,且每次都会在同一个地方NPE

我抱着试一试的心态,在 Google/知乎上搜索一些“Java 异常 堆栈 丢失 性能优化”之类的关键词。结果,R 大在 十年前 的回答,瞬间击碎了所有的迷雾!

帖子地址: 重载 Throwable.fillInStackTrace() 方法以提高Java性能这样的做法对吗? - RednaxelaFX的回答 - 知乎

R 大的回答里提到了一个 HotSpot VM 的“神优化”——fast throw

HotSpot VM 有个许多人觉得“匪夷所思”的优化,叫做 fast throw:有些特定的隐式异常类型(NullPointerExceptionArithmeticException/ 0)之类)如果在代码里某个特定位置被抛出过多次的话,HotSpot Server Compiler(C2)会透明地决定用 fast throw 来优化这个抛出异常的地方——直接抛出一个事先分配好的、类型匹配的异常对象。这个对象的 messagestack trace 都被清空

划重点: messagestack trace 都被清空

简直是醍醐灌顶!

这种优化的目的是:**抛出这个异常的速度是非常快,不但不用额外分配内存,而且也不用爬栈;**但反面就是:可能正好是需要知道哪里出问题的时候看不到 stack trace 了。

这不就是我的问题吗?!

顺着这个思路,看了一下这个定时器最早的一次报错,果然是带完整的堆栈信息的。
结合我们的代码,至此可以破案了:获取库位信息并遍历的代码,它被高频调用,而且由于数据问题,它一直在报 NPE

JVM 的 C2 编译器一看:“呦,指这行代码天天抛一样的异常,怪累的,我帮他优化一下吧!” 于是,它启动了 fast throw 机制,直接抛出预先分配好的、没有堆栈的 NPE 对象,大大提升了抛出异常的速度,但同时也“贴心”地清空了我的日志堆栈!

四、反思

这事儿说到底,是因为我们代码里的 NPE Bug 成了 JVM 优化的“燃料”。

当然,知道原因后,我们首先要做的肯定是修复那个导致 NPE 的 Bug。

但从 JVM 层面,如果你确实需要知道高频异常的堆栈,你可以通过一个 VM 参数来禁用这个优化:

-XX:-OmitStackTraceInFastThrow

不过,这个参数的意义是“以性能为代价,换取更完整的堆栈信息”,所以,更正确的姿势,永远是写出健壮的代码,避免高频抛出隐式异常!