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

起因

我们发现线上某个应用突然报了大量的空指针的错误, 于是根据程序日志去排查到底是什么原因导致的空指针.

首先, 我们找到最近的一个出错日志, 发现里面只有一行有用的日志:

java.lang.NullPointerException

没有发现出错栈, 通常我们会把异常的消息先打出来, 然后再把出错栈再打出来, 可是这个却不是这样.

我们一开始怀疑是不是打日志的地方只打印了异常的消息, 没有打印出错栈. 但是要找到打印日志的地方, 必须知道哪里打印的日志, 可是没有出错栈, 就找不到源代码. 于是陷入了现有蛋, 还是先有鸡蛋问题.

当我们一筹莫展的时候, 有人重启了一台机器. 这个错误还一直在, 可是新重启的机器上报出来的错误里面却有出错栈. 神奇!

代码模拟

我们用一段代码模拟这个操作:

public class OmitStackTrace {
	public static void doSomething() {
		// 循环 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() {
		return null;// 为了创造空指针异常, 返回一个空对象,
	}

	public static void main(String[] args) {
		OmitStackTrace.doSomething();
	}
}

上面的代码模拟一个空指针异常的错误, 只是特别多的重复打印异常. 如果运行上面的代码, 一开始的时候, 出错日志是这样的:

java.lang.NullPointerException
	at com.tianxiaohui.OmitStackTrace.doSomething(OmitStackTrace.java:9)
	at com.tianxiaohui.OmitStackTrace.main(OmitStackTrace.java:24)
java.lang.NullPointerException
	at com.tianxiaohui.OmitStackTrace.doSomething(OmitStackTrace.java:9)
	at com.tianxiaohui.OmitStackTrace.main(OmitStackTrace.java:24)
java.lang.NullPointerException
	at com.tianxiaohui.OmitStackTrace.doSomething(OmitStackTrace.java:9)
	at com.tianxiaohui.OmitStackTrace.main(OmitStackTrace.java:24)

当打印到足够的次数之后, 就变成了下面的样子:

java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException

原因

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

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

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

$ java  -XX:+PrintFlagsFinal -version | grep OmitStackTraceInFastThrow.
     bool OmitStackTraceInFastThrow                = true                                      {product} {default}
openjdk version "17.0.4.1" 2022-08-12 LTS

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

Java 异常的出错栈不见了

起因

代码模拟

原因