EZLippi-浮生志

JVM解惑:消失的异常堆栈

最近在分析日志的时候发现有个日志捕捉了NullPointerException,但是没有异常堆栈信息,只有java.lang.NullPointerException这一条信息,无法知道是从哪里抛出来的, 经过分析是JIT编译器对异常进行了优化,当代码中的某个位置抛出同一个异常很多次后,JIT服务端编译器(C2)会将其优化成抛出一个事先编译好的、类型匹配的异常,异常堆栈信息就看不到了。

引用R大的一段话:

HotSpot VM有个许多人觉得“匪夷所思”的优化,叫做fast throw:有些特定的隐式异常类型(NullPointerException、ArithmeticException( / 0)之类)如果在代码里某个特定位置被抛出过多次的话,HotSpot Server Compiler(C2)会透明的决定用fast throw来优化这个抛出异常的地方——直接抛出一个事先分配好的、类型匹配的异常对象。这个对象的message和stack trace都被清空。抛出这个异常的速度是非常快,不但不用额外分配内存,而且也不用爬栈;但反面就是可能正好是需要知道哪里出问题的时候看不到stack trace了。从Sun JDK5开始要避免C2做这个优化还得额外传个VM参数:-XX:-OmitStackTraceInFastThrow。

问题重现

既然知道这是JIT编译优化导致的,那就很容易写代码来重现,测试代码如下,使用的是JDK1.8.0_25:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
public class Main {
public static void main(String[] args) {
for(int i = 0; i < 200000; i++) {
try {
((Object)null).getClass();
} catch (Exception e) {
System.out.println(i + ":" + e.getStackTrace().length);
if (e.getStackTrace().length == 0) {
System.out.println("stackTrace omit after " + i + " times");
e.printStackTrace();
break;
}
}
}

}
}

测试结果是在调用115712次后JIT做了编译优化,在第115713次时异常堆栈看不到了,stackTrace长度为0:

1
2
3
4
5
115711:1
115712:1
115713:0
stackTrace omit after 115713 times
java.lang.NullPointerException

解决办法

JVM提供了-XX:-OmitStackTraceInFastThrow这个虚拟机参数来告诉JIT编译器禁用这种异常fastThrow的优化,当然如果你使用-Xint参数后虚拟机运行在解释器模式也不会出现这个问题,但是禁用JIT会对整体的性能有影响,因此不建议使用-Xint参数,如果想看到具体的异常堆栈,推荐使用-XX:-OmitStackTraceInFastThrow参数。

那JVM为什么要对异常进行优化呢,这里就牵扯到另一个问题了,如果你在系统响应慢的时候分析过线程堆栈,可能遇到过线程耗在调用fillInStackTrace()这个native方法的时间非常长,fillInStackTrace()方法用来爬取线程的调用堆栈,我之前就遇到过Log4j打印日志非常慢的问题,结果抓取线程堆栈后发现线程都是卡在fillInStackTrace()这个native方法,如果有些使用场景不需要完整的调用堆栈时,建议重写fillInStackTrace(),让它直接return this,可以一定程度的提高系统的吞吐量。

fillInStackTrace优化

我们知道所有的Exception和Error都是Throwable的子类,构造子类实例前都先调用父类的实例构造方法,我们看下Throwable类的源码就会发现在构造方法里调用了fillInStackTrace()方法:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
/**
* Constructs a new throwable with {@code null} as its detail message.
* The cause is not initialized, and may subsequently be initialized by a
* call to {@link #initCause}.
*
* <p>The {@link #fillInStackTrace()} method is called to initialize
* the stack trace data in the newly created throwable.
*/

public Throwable() {
fillInStackTrace();
}

public synchronized Throwable fillInStackTrace() {
if (stackTrace != null || backtrace != null ) {
//这里调用native的fillInStackTrace方法
fillInStackTrace(0);
stackTrace = UNASSIGNED_STACK;
}
return this;
}

可以看到当stackTrace不为null时需要调用native的fillInStackTrace()方法,那什么时候stackTrace变量为null呢,通过追踪源码可以发现Throwable类有多个重载的构造方法,其中有个方法可以传递一个writableStackTrace参数,当这个参数为false的时候stackTrace就为null,这时候就不会调用native的fillInStackTrace()方法去爬取线程堆栈,当然你也可以重写fillInStackTrace()方法,让他直接返回this,这样也可以避免爬栈,但是还是建议大家谨慎使用,毕竟需求时刻在变,说不定什么时候就需要这个堆栈来定位问题了。

1
2
3
4
5
6
7
8
9
10
11
12
13
protected Throwable(String message, Throwable cause,
boolean enableSuppression,
boolean writableStackTrace)
{

if (writableStackTrace) {
fillInStackTrace();
} else {
stackTrace = null;
}
detailMessage = message;
this.cause = cause;
if (!enableSuppression)
suppressedExceptions = null;
}

前面提到了Log4j打印日志慢的问题,那Log4j打印日志为什么也涉及到这个fillInStackTrace方法呢,对Log4j有研究过的同学应该知道如果Log4j配置文件里配置了%C(类全限定包名)、%F(文件名)、%M(打印日志的方法名称)和%L(行号)这几个用于定位调用者信息的pattern时,Log4J会先抛出一个异常出来,然后从异常堆栈中来获取调用者的信息,既然是抛异常出来必然涉及到调用native的fillInStackTrace方法来爬取线程堆栈,因此开启这些参数对系统的性能是有影响的。

用Btrace定位异常的抛出者

前面写了一篇博文介绍怎么用Btrace来定位线上问题,为了证实前面的论断,我写了个btrace脚本来定位NullPointerException的抛出堆栈,如果你的系统禁用了Exception fastSlow,但是你想定位具体哪个方法抛出了某个异常,也可以参考下面这个脚本:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
@BTrace
public class TraceMethodArgsAndReturn {

//btrace不能保存全局变量,可以保存在ThreadLocal
@TLS static Throwable currentException;

//这里有两个重载方法是因为空指针异常有两个重载的构造方法
@OnMethod(clazz = "java.lang.NullPointerException", method = "<init>")
public static void traceNullPointerException(@Self Throwable self) {
currentException = self;
}
//匹配带参数的构造方法
@OnMethod(clazz = "java.lang.NullPointerException", method = "<init>")
public static void traceNullPointerException(@Self Throwable self, String message) {
currentException = self;
}

//异常构造完成后打印异常堆栈
@OnMethod(clazz = "java.lang.NullPointerException", method = "<init>",
location = @Location (Kind.RETURN))
public static void onThrowReturn() {
if (currentException != null) {
Threads.jstack(currentException);
println("=====================");
currentException = null;
}
}
}

执行文章最开始的Main方法后,使用jps获取java进程pid,然后使用Btrace $pid 脚本名称 来启动监控任务,可以发现在一段时间后不会打印异常堆栈了,因为JIT已经对代码做了优化,抛出了一个事先编译好的类型匹配的异常,因此也就不会调用NullPointerException的构造方法:

1
2
3
4
5
6
7
8
9
10
11
DEBUG: received com.sun.btrace.comm.MessageCommand@e93f3d5
java.lang.NullPointerException
DEBUG: received com.sun.btrace.comm.MessageCommand@4cee7fa0
Main.main(Main.java:5)
DEBUG: received com.sun.btrace.comm.MessageCommand@7a26928a
=====================
DEBUG: received com.sun.btrace.comm.MessageCommand@601cbd8c
java.lang.NullPointerException
DEBUG: received com.sun.btrace.comm.MessageCommand@7180e701
Main.main(Main.java:5)
输出115712条信息后没有堆栈信息了...

参考文章:

  1. NullPointerException stack trace not available without debug agent
  2. JDK-4292742 : NullPointerException with no stack trace
  3. Btrace入门到熟练小工完全指南
🐶 您的支持将鼓励我继续创作 🐶