前幾天有同學(xué)找我查一個(gè)空指針問(wèn)題，Java 打印日志時(shí)，異常堆棧信息被吞了，導(dǎo)致定位不到出問(wèn)題的地方。

現(xiàn)象

捕獲異常打印日志的代碼類似這樣：

try {
    // ...
} catch (Exception e) {
    log.error("系統(tǒng)異常 customerCode:{},data:{}", customerCode, data, e);
    // ...
}

查到的日志是這樣的：

2023-06-26 11:11:11.111 ERROR 1 --- [pool-1-thread-1] c.mazhuang.service.impl.TestServiceImpl  : 系統(tǒng)異常 customerCode:123,data:{"name":"mazhuang","age":18}
java.lang.NullPointerException: null

異常堆棧丟了。

分析

在之前的一篇文章里已經(jīng)驗(yàn)證過(guò)這種寫(xiě)法是可以正常打印異常和堆棧信息的：AI 自動(dòng)補(bǔ)全的這句日志能正常打印嗎？

再三確認(rèn)代碼寫(xiě)法沒(méi)問(wèn)題，納悶之下只好搜索了一下關(guān)鍵詞「Java異常堆棧丟失」，發(fā)現(xiàn)了這篇文章：Java異常堆棧丟失的現(xiàn)象及解決方法，這里面提到的問(wèn)題與我們遇到的一樣，而且給出了 Oracle 官方文檔里的相關(guān)說(shuō)明：

https://www.oracle.com/java/technologies/javase/release-notes-introduction.html

The compiler in the server VM now provides correct stack backtraces for all “cold” built-in exceptions. For performance purposes, when such an exception is thrown a few times, the method may be recompiled. After recompilation, the compiler may choose a faster tactic using preallocated exceptions that do not provide a stack trace. To disable completely the use of preallocated exceptions, use this new flag: -XX:-OmitStackTraceInFastThrow.

大致意思就是說(shuō)，為了提高性能，JVM 會(huì)針對(duì)一些內(nèi)建異常進(jìn)行優(yōu)化，在這些異常被某方法多次拋出時(shí)，JVM 可能會(huì)重編譯該方法，這時(shí)候就可能會(huì)使用不提供堆棧信息的預(yù)分配異常。如果想要完全禁用預(yù)分配異常，可以使用 -XX:-OmitStackTraceInFastThrow 參數(shù)。

了解到這個(gè)信息后，翻了翻從服務(wù)上次發(fā)版以來(lái)的這條日志，果然最早的十幾次打印是有異常堆棧的，后面就沒(méi)有了。

解決方案

回溯歷史日志，找到正常打印的堆棧信息，定位和解決問(wèn)題；

也可以考慮在 JVM 參數(shù)里加上 -XX:-OmitStackTraceInFastThrow 參數(shù)，禁用優(yōu)化；

本地復(fù)現(xiàn)

在本地寫(xiě)一個(gè)簡(jiǎn)單的程序復(fù)現(xiàn)一下：

public class StackTraceInFastThrowDemo {
    public static void main(String[] args) {
        int count = 0;
        boolean flag = true;
        while (flag) {
            try {
                count++;
                npeTest(null);
            } catch (Exception e) {
                int stackTraceLength = e.getStackTrace().length;
                System.out.printf("count: %d, stacktrace length: %d%n", count, stackTraceLength);
                if (stackTraceLength == 0) {
                    flag = false;
                }
            }
        }
    }

    public static void npeTest(Integer i) {
        System.out.println(i.toString());
    }
}

不添加 -XX:-OmitStackTraceInFastThrow 作為 JVM 參數(shù)時(shí)，運(yùn)行結(jié)果如下：

...
count: 5783, stacktrace length: 2
count: 5784, stacktrace length: 2
count: 5785, stacktrace length: 0

Process finished with exit code 0

在我本機(jī)一般運(yùn)行五六千次后，會(huì)出現(xiàn)異常堆棧丟失的情況。

添加 -XX:-OmitStackTraceInFastThrow 作為 JVM 參數(shù)時(shí)，運(yùn)行結(jié)果如下：

...
count: 3146938, stacktrace length: 2
count: 3146939, stacktrace length: 2
count: 3146940, stacktrace length: 
Process finished with exit code 137 (interrupted by signal 9: SIGKILL)

運(yùn)行了幾百萬(wàn)次也不會(huì)出現(xiàn)異常堆棧丟失的情況，手動(dòng)終止程序。

完整源碼見(jiàn)：https://github.com/mzlogin/java-notes/blob/master/src/org/mazhuang/StackTraceInFastThrowDemo.java