一次 JVM “神优化” 导致的日志丢失问题
一、问题发生
今天同事私聊我,问了我一个问题,他说在一个美国的海外仓项目中发现一个奇怪的报错日志:只有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:有些特定的隐式异常类型(
NullPointerException、ArithmeticException(/ 0)之类)如果在代码里某个特定位置被抛出过多次的话,HotSpot Server Compiler(C2)会透明地决定用 fast throw 来优化这个抛出异常的地方——直接抛出一个事先分配好的、类型匹配的异常对象。这个对象的message和 stack trace 都被清空。
划重点: message 和 stack trace 都被清空!
简直是醍醐灌顶!
这种优化的目的是:**抛出这个异常的速度是非常快,不但不用额外分配内存,而且也不用爬栈;**但反面就是:可能正好是需要知道哪里出问题的时候看不到 stack trace 了。
这不就是我的问题吗?!
顺着这个思路,看了一下这个定时器最早的一次报错,果然是带完整的堆栈信息的。
结合我们的代码,至此可以破案了:获取库位信息并遍历的代码,它被高频调用,而且由于数据问题,它一直在报 NPE。
JVM 的 C2 编译器一看:“呦,指这行代码天天抛一样的异常,怪累的,我帮他优化一下吧!” 于是,它启动了 fast throw 机制,直接抛出预先分配好的、没有堆栈的 NPE 对象,大大提升了抛出异常的速度,但同时也“贴心”地清空了我的日志堆栈!
四、反思
这事儿说到底,是因为我们代码里的 NPE Bug 成了 JVM 优化的“燃料”。
当然,知道原因后,我们首先要做的肯定是修复那个导致 NPE 的 Bug。
但从 JVM 层面,如果你确实需要知道高频异常的堆栈,你可以通过一个 VM 参数来禁用这个优化:
-XX:-OmitStackTraceInFastThrow
不过,这个参数的意义是“以性能为代价,换取更完整的堆栈信息”,所以,更正确的姿势,永远是写出健壮的代码,避免高频抛出隐式异常!