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)