JVM異常不列印堆疊資訊 [ -XX:-OmitStackTraceInFastThrow ]

問題現象

	最近在排查線上日誌的時候發現有個日誌捕捉了NullPointerException，但是沒有異常堆疊資訊
	,只有java.lang.NullPointerException:null這一條資訊,無法知道是從哪裡丟擲來的如圖：

	經過分析是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 < 300000; i++) {
           try {
               ((Object)null).getClass();
           } catch (Exception e) {
               System.out.println(i + ":" + e.getStackTrace().length);
               if (e.getStackTrace().length == 0) {
                   System.out.println("stackTrace no stack after " + i + " times");
                   e.printStackTrace();
                   break;
               }
           }
       }

    }
}

測試結果是在呼叫115712次後JIT做了編譯優化,在第115713次時異常堆疊看不到了,stackTrace長度為0:

115713:1
115714:1
115715:0
stackTrace omit after 115715 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方法來爬取執行緒堆疊,因此開啟這些引數對系統的效能是有影響的。

官方文件

文件地址：https://www.oracle.com/java/technologies/javase/release-notes-introduction.html#vm
內容：