問題描述
查看線上log時,發現了一些npe異常,但是沒有堆棧信息。
...
java.lang.NullPointerException
...
沒有堆棧信息,也就意味着沒法定位問題代碼,第一反應是查看記日志的代碼(用的logback),確認沒有問題后,開始google和stackOverflow。
結論
一般情況下,當異常發生時,JVM會回溯調用棧,構建異常對象(包含完整的堆棧信息)。但是出於性能考慮,如果某個方法一直拋出同樣的異常,比如npe,JVM會重新編譯該方法(JIT編譯器),然后拋出事先創建好的異常(沒有堆棧信息)。
JDK5.0的發布說明里有相關描述:
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.
https://www.oracle.com/technetwork/java/javase/relnotes-139183.html
復現&解決方案
復現問題
執行如下代碼:
for (int i = 0; i < 200000; i++) {
try {
((String) null).toString();
} catch (Exception e) {
int stackTraceLength = e.getStackTrace().length;
System.out.println(i + ",堆棧長度:" + stackTraceLength);
}
}
在我的電腦上,循環115716次后,堆棧長度就為0了,即堆棧信息為空,如下:
...
115713,堆棧長度:1
115714,堆棧長度:1
115715,堆棧長度:0
115716,堆棧長度:0
...
所以,驗證了JVM確實會進行一些優化,出現沒有堆棧的異常。
解決方案
- 通過JVM參數禁用此優化。
JDK5.0 Release Notes里說的很明確,通過添加JVM參數禁用此優化:-XX:-OmitStackTraceInFastThrow。 - 查看更早之前的log,直到相關的異常堆棧,解決掉。
如上文所說,只有某個異常出現了若干次后,才可能觸發優化條件。所以,最初的日志里肯定是有完整的堆棧信息。
如果日志比較少,考慮直接往前追溯log,找到異常堆棧,解決問題。
如果日志比較多,考慮在線上先給JVM增加參數禁用此優化,解決問題后,再移除參數,開啟優化。
最后
以此為假設,在線上往前追溯log,最終在5天前的日志里找到了相關異常的堆棧信息,定位到問題,解決起來就比較簡單了。
本文以流水賬的方式描述了遇到的問題和解決方案,其實還是很多東西值得繼續調研,比如JVM為什么要這個優化,JVM的異常機制是如何運行的,為什么會這么慢,等等。
參考
[1] Hotspot caused exceptions to lose their stack traces in production – and the fix