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:

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:

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()方法:

/**
 * 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,这样也可以避免爬栈,但是还是建议大家谨慎使用，毕竟需求时刻在变，说不定什么时候就需要这个堆栈来定位问题了。

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,但是你想定位具体哪个方法抛出了某个异常,也可以参考下面这个脚本：

@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的构造方法:

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条信息后没有堆栈信息了...复制代码