谁吃掉了 Java 异常的代码栈?

[manecocomph]

转自: https://mp.weixin.qq.com/s/GUFvhOtJMg4tAdMVDWI8bA

通常情况下, 如果我们遇到某些异常, 都把出错异常栈打出来, 这样方便查看到底哪行代码出错了, 是怎么一层层调用到了这行代码. 可是有时候, 虽然我们明确写了打印出错异常栈, 可是偏偏日志里面却没有出错栈, 这是怎么一回事呢?



故事背景

某天, 有开发人员找到 SRE 说, 他们的代码出了一个新的空指针错误, 可是日志里面却没有出错栈, 想让 SRE 帮忙确定一下, 到底是日志丢了, 还是代码哪里出了问题.

SRE 查看了源代码, 代码确实是打印完整出错栈, 可是日志却没有相关信息. 于是 SRE 想使用 BTrace 暴力注入, 查看到底怎么回事. 可是事与愿违, 这些出错的机器, 由于未知的原因, SRE 的账号登录不了. 所以只能通过其它方式去解决这个谜题.



代码模拟

为了较为直观的展示这个问题, 考虑下面这段代码, 它最后打印出来的结果会是什么样子?



package com.tianxiaohui.art;



public class StackEater {



public static void main(String[] args) {

StackEater.makeException();

}



public static void makeException() {

//循环 N 次, 只为每次都发生空指针异常

for (int i = 0; i < 1000000000; i++) {

try {

Object obj = createObject();

System.out.println(obj.hashCode());

} catch (Exception e) {//打印出错栈

e.printStackTrace();

}

}

}



public static Object createObject() {

returnnull;//为了创造空指针异常, 返回一个空对象,

}

}



最开始的时候, 事情还是在我们预料之中:

图片




可是随着循环次数增加, 最后打印的结果, 变成了这个样子:

java.lang.NullPointerException

java.lang.NullPointerException

java.lang.NullPointerException



谜题答案

在讲出答案之前, 我们先复习一下 JIT 优化的一些细节: 当某些 Java 方法或者某些循环体里面的代码, 在某个滑动时间窗口之内执行的次数足够多, 足够 hot 的时候, JIT 就出手把他们编译成机器代码了. 编译的机器代码根据优化层度不同, 又分为几个等级. 代码越热, 优化层度越高.

另外, 在 Java 运行过程中, 如果出错产生异常, 一般都是把异常栈信息封装在 Throwable 或其子类中. 采集当前线程的异常栈对于 JVM 来说, 是一个相对耗时的操作, 需要额外耗费比较多的 CPU cycle.

针对 JDK 自带的一些异常类, 如果 JIT 做代码编译的时候, 会有更贴心的优化策略: 出于性能考虑, 把出错栈信息省略掉, 只保留异常类的类名. 同时, 提供了一个 JVM flag: -XX:+OmitStackTraceInFastThrow 来选择打开, 还是关闭这个贴心优化. 默认是打开的.

所以, 我们的故事当中, 就是因为那个 JDK 自带异常出错的频率太高, 导致 JIT 对它进行了优化, 最终在后面的日志中看不到那个异常栈. 为了看到那个异常栈, 要跑到最开始出错的时间点去查看日志.

[340244120w]

居然最后没有公众号链接！
不过说回来，我们为了减少异常栈输出，自定义业务类异常类都是
@Override
public Throwable fillInStackTrace() {
return null;
}

[sadfQED2]

这就是我不敢去写 java 的原因，jvm 各种奇奇怪怪的优化太多了。这特么谁能想到啊

[tedzhou1221]

类似情况，在我们生产有发生过。

公共方法，空指针。 一堆报错日志发到运维邮箱。内容就一行 就显示空指针，也没显示哪一行出问题……

[manecocomph]

@340244120w 哈哈, 原文里面有, 最后就不放了. 谢谢捧场. 你这个返回 null 的我还是第一次见. 涨见识.

[manecocomph]

@sadfQED2 JIT 编译时会有各种优化. 大多数不会产生这种异常.

[manecocomph]

@tedzhou1221 那基本就是这个问题. 所以要找到最初报这个空指针的地方. 或者使用 BTrace 检测 new NPEException 的点, 打印 stack.

[cheng6563]

这种一般找到第一个异常就行了。

[manecocomph]

@cheng6563 是的. 如果第一个异常太久了或者日志被 rotate 了 第一个日志就比较难找.

[timi]

如果日志滚没了，有办法让 JVM 逆优化回去吗

[manecocomph]

@timi 一段时间内这个方法或者 for 循环体内的方法不再过热. 它是计算一个滑动时间窗口内被执行的次数. 如果次数降下来 因为存编译代码的空间有限, 这段代码可能会被逆优化.

当然, 如果重启 server, 自然又恢复到开始状态了.

[justlikemaki]

线上遇到过这种问题，xx 同事说，加了个日志修复了。其实是，重启了就恢复了。

[manecocomph]

@justlikemaki 哈哈, 那是不是过段时间又重现了. xx 同事在去掉日志又可以修复一次...

[xuanbg]

@timi 不需要滚回去，重启就有了

[uselessVisitor]

排版难受

[hustmisa]

这不是很正常且符合逻辑的优化么

如果相同的异常堆栈特别多，类似你这种循环 100000，异常的堆栈会增加 io 甚至写满磁盘，这时候你重启或者找到错误开始的位置就能看到堆栈，而且一个完全重复无数次的东西记录干嘛，你业务日志会记录完全重复没用的东西么；
如果相同的错误很少，根本不会被省略。

[manecocomph]

@hustmisa 是正常且符合逻辑的优化. 只是很少看到这种文档介绍这种知识, 导致第一次见到这种情形, 不知道栈去哪里了.

[manecocomph]

@beichenhpy 是的, 我为了省事, 直接复制过来了. 直接读微信原文排版会好点. 下次写个提示.

[MineDog]

@340244120w #1 构造方法可以直接关闭，为什么要重写呢？

[340244120w]

@MineDog

一个是防止其他人滥用 e.printstacktrace 。

一个是性能问题，填充栈特别吃性能，而且还是加锁的方法。很多人诟病用异常代替业务里的 if 判断影响性能，就是这个原因。

[340244120w]

@MineDog 重写更简单，构造方法也挺好，主要当时也没注意到

[MineDog]

@340244120w #20 参数控制的方式更灵活吧

[340244120w]

@MineDog #21 嗯嗯

[hustmisa]

@manecocomph 嗯嗯确实是，这个优化的很隐蔽。。