JVM参数OmitStackTraceInFastThrow致使的异常栈信息不见了

问题描述

某天收到生产环境error日志告警（对error.log监控，超过必定大小就会给开发人员发送告警短信）。可是tail查看最新的异常信息只有这些，好忧伤：

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

后来有个同事从error.log前面开始看起，能看到完整的异常栈信息，大体以下，这样的信息就可以准确的定位问题：

... ...
java.lang.NullPointerException
	at com.qifu58.WithNPE.run(OmitStackTraceInFastThrowTest.java:36)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
java.lang.NullPointerException
	at com.qifu58.WithNPE.run(OmitStackTraceInFastThrowTest.java:36)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
java.lang.NullPointerException
	at com.qifu58.WithNPE.run(OmitStackTraceInFastThrowTest.java:36)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
... ...

那么前面那段只有简单的java.lang.NullPointerException，没有详细异常栈信息的缘由是什么呢？这须要从一个JVM参数提及。

缘由分析

JVM中有个参数：OmitStackTraceInFastThrow，字面意思是省略异常栈信息从而快速抛出，那么JVM是如何作到快速抛出的呢？JVM对一些特定的异常类型作了Fast Throw优化，若是检测到在代码里某个位置连续屡次抛出同一类型异常的话，C2会决定用Fast Throw方式来抛出异常，而异常Trace即详细的异常栈信息会被清空。这种异常抛出速度很是快，由于不须要在堆里分配内存，也不须要构造完整的异常栈信息。相关的源码的JVM源码的graphKit.cpp文件中，相关源码以下：

//------------------------------builtin_throw----------------------------------
void GraphKit::builtin_throw(Deoptimization::DeoptReason reason, Node* arg) {
  bool must_throw = true;

  ... ...
  // 首先判断条件是否知足
  // If this particular condition has not yet happened at this
  // bytecode, then use the uncommon trap mechanism, and allow for
  // a future recompilation if several traps occur here.
  // If the throw is hot（表示在代码某个位置重复抛出异常）, try to use a more complicated inline mechanism
  // which keeps execution inside the compiled code.
  bool treat_throw_as_hot = false;

  if (ProfileTraps) {
    if (too_many_traps(reason)) {
      treat_throw_as_hot = true;
    }
    // (If there is no MDO at all, assume it is early in
    // execution, and that any deopts are part of the
    // startup transient, and don't need to be remembered.)

    // Also, if there is a local exception handler, treat all throws
    // as hot if there has been at least one in this method.
    if (C->trap_count(reason) != 0
        && method()->method_data()->trap_count(reason) != 0
        && has_ex_handler()) {
        treat_throw_as_hot = true;
    }
  }

  // If this throw happens frequently, an uncommon trap might cause
  // a performance pothole.  If there is a local exception handler,
  // and if this particular bytecode appears to be deoptimizing often,
  // let us handle the throw inline, with a preconstructed instance.
  // Note:   If the deopt count has blown up, the uncommon trap
  // runtime is going to flush this nmethod, not matter what.
  // 这里要知足两个条件：1.检测到频繁抛出异常，2. OmitStackTraceInFastThrow为true，或StackTraceInThrowable为false
  if (treat_throw_as_hot
      && (!StackTraceInThrowable || OmitStackTraceInFastThrow)) {
    // If the throw is local, we use a pre-existing instance and
    // punt on the backtrace.  This would lead to a missing backtrace
    // (a repeat of 4292742) if the backtrace object is ever asked
    // for its backtrace.
    // Fixing this remaining case of 4292742 requires some flavor of
    // escape analysis.  Leave that for the future.
    ciInstance* ex_obj = NULL;
    switch (reason) {
    case Deoptimization::Reason_null_check:
      ex_obj = env()->NullPointerException_instance();
      break;
    case Deoptimization::Reason_div0_check:
      ex_obj = env()->ArithmeticException_instance();
      break;
    case Deoptimization::Reason_range_check:
      ex_obj = env()->ArrayIndexOutOfBoundsException_instance();
      break;
    case Deoptimization::Reason_class_check:
      if (java_bc() == Bytecodes::_aastore) {
        ex_obj = env()->ArrayStoreException_instance();
      } else {
        ex_obj = env()->ClassCastException_instance();
      }
      break;
    }
    ... ...
}

说明：OmitStackTraceInFastThrow和StackTraceInThrowable都默认为true，因此条件(!StackTraceInThrowable || OmitStackTraceInFastThrow)为true，即JVM默认开启了Fast Throw优化。若是想关闭这个优化，很简单，配置-XX:-OmitStackTraceInFastThrow，StackTraceInThrowable保持默认配置-XX:+OmitStackTraceInFastThrow便可。

另外，根据这段源码的switch .. case ..部分可知，JVM只对几个特定类型异常开启了Fast Throw优化，这些异常包括：NullPointerException，ArithmeticException，ArrayIndexOutOfBoundsException，ArrayStoreException，ClassCastException。

问题验证

为了验证这个问题，笔者写了下面这段代码：

public class OmitStackTraceInFastThrowTest {

    public static void main(String[] args) throws InterruptedException {
        NPEThread npeThread = new NPEThread();
        ExecutorService executorService = Executors.newFixedThreadPool(20);
        for (int i=0; i<Integer.MAX_VALUE; i++) {
            executorService.execute(npeThread);
            // 稍微sleep一下, 是为了避免要让异常抛出太快, 致使控制台输出太快, 把有异常栈信息冲掉, 只留下fast throw方式抛出的异常
            Thread.sleep(2);
        }
    }
}
class NPEThread extends Thread {
    private static int count = 0;
    @Override
    public void run() {
        try{
            System.out.println(this.getClass().getSimpleName()+"--"+(++count));
            String str = null;
            // 制造空指针NPE
            System.out.println(str.length());
        }catch (Throwable e){
            e.printStackTrace();
        }
    }
}

运行部分日志以下：

java.lang.NullPointerException
	at com.qifu58.WithNPE.run(OmitStackTraceInFastThrowTest.java:36)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
java.lang.NullPointerException
	at com.qifu58.WithNPE.run(OmitStackTraceInFastThrowTest.java:36)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
java.lang.NullPointerException
WithNPE--6675
	at com.qifu58.WithNPE.run(OmitStackTraceInFastThrowTest.java:36)
WithNPE--6676
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
WithNPE--6677
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
java.lang.NullPointerException
WithNPE--6678
	at com.qifu58.WithNPE.run(OmitStackTraceInFastThrowTest.java:36)
WithNPE--6679
WithNPE--6680
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
WithNPE--6681
java.lang.NullPointerException
WithNPE--6682
java.lang.NullPointerException
WithNPE--6683
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException

从这段日志可知，抛出了几千次带有详细异常栈信息的异常后，只会抛出java.lang.NullPointerException这种没有详细异常栈信息只有异常类型的异常信息。这就是Fast Throw优化后抛出的异常。若是咱们配置了-XX:-OmitStackTraceInFastThrow，再次运行，就不会看到Fast Throw优化后抛出的异常，全是包含了详细异常栈的异常信息。

配置JVM参数关闭Fast Throw后，即便抛出了1w+次异常，依然全是包含了详细异常栈的异常信息，日志以下：

NPEThread--10566
NPEThread--10567
java.lang.NullPointerException
	at com.qifu58.NPEThread.run(OmitStackTraceInFastThrowTest.java:34)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
java.lang.NullPointerException
	at com.qifu58.NPEThread.run(OmitStackTraceInFastThrowTest.java:34)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
NPEThread--10568
java.lang.NullPointerException
	at com.qifu58.NPEThread.run(OmitStackTraceInFastThrowTest.java:34)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
NPEThread--10569
java.lang.NullPointerException
	at com.qifu58.NPEThread.run(OmitStackTraceInFastThrowTest.java:34)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)