異常堆棧丟失
今天登陸服務器進行例行的檢查,發現異常日志文件里有很多nullPointException,只有簡單的異常名稱,卻沒有堆棧信息。沒有異常堆棧,無法定位錯誤,也就不能修改了。到網上搜索信息,原來大家也遇到過這樣的問題。
正確的解決方法是增加一個VM Options:-XX:-OmitStackTraceInFastThrow。這個參數的好處如下:
“JVM對一些特定的異常類型做了Fast Throw優化,如果檢測到在代碼里某個位置連續多次拋出同一類型異常的話,C2會決定用Fast Throw方式來拋出異常,而異常Trace即詳細的異常棧信息會被清空。這種異常拋出速度非常快,因為不需要在堆里分配內存,也不需要構造完整的異常棧信息。”
這個參數,支持的異常類型如下:
- NullPointerException
- ArithmeticException
- ArrayIndexOutOfBoundsException
- ArrayStoreException
- ClassCastException
翻閱了大量的關于此問題的文章,介紹信息大同小異。通過這個方案,開啟輸出空指針錯誤,很快就定位問題,并解決了。
解決問題后,進行了一番的測試和驗證,如下:
問題驗證
眾多網絡文章,都指出在異常出現5000次以上時,才會丟失堆棧信息。按照網絡文章的測試代碼,在6600多次的時候丟失堆棧信息,但是并不穩定。代碼如下:
public class JAVANPE extends Thread {
private static int count = 0;
@Override
public void run() {
try {
System.out.println("getSimpleName is:"+this.getClass().getSimpleName() + " execute count:" + (++count));
String str = null;
System.out.println(str.length());
} catch (Throwable e) {
e.printStackTrace();
}
}
}
public class TestFastThrow {
public static void main(String[] args) throws InterruptedException {
JavaNPE javaNPE = new JavaNPE();
ExecutorService executorService = Executors.newFixedThreadPool(10);
for (int i = 0; i < Integer.MAX_VALUE; i++) {
executorService.execute(javaNPE);
//防止打出的日志太快
Thread.sleep(2);
}
}
}
這是一個多線程的程序,寫單線程的測試程序,是否可行呢?于是就嘗試了第一版,代碼如下:
public static void main(String args[]) {
for (int i = 0; i < 10000; i++) {
try {
String value = null;
value.substring(0, 100);
} catch (Exception ex) {
ex.printStackTrace();
}
}
}
但是,很遺憾,這個程序的異常堆棧信息并不會丟失。程序修改如下:
public void method2() {
String value = null;
value.substring(0, 100);
}
public static void main(String args[]) {
ExceptionTest exceptionTest = new ExceptionTest(1);
for (int i = 0; i < 10000; i++) {
try {
exceptionTest.method2();
} catch (Exception ex) {
ex.printStackTrace();
}
}
}
這個程序在第5530~5550次的時候,會丟失異常堆棧信息,是不穩定的。分析上述兩段單線程的測試代碼,第一段因為異常信息沒有到方法的外面,jvm不能追蹤到異常堆棧信息,所以并不會起作用。
性能優化明顯嗎?
首先,在網絡上的文章,都著重說C2編譯器的優化,并沒有說明C1編譯器。通過我的實驗,C1和C2編譯器的默認行為是一樣的,都是開啟OmitStackTraceInFastThrow的。C1和C2編譯器,是指Java及時編譯技術(JIT),在啟動應用程序是,java -client是啟動C1編譯器;java -server是啟動C2編譯器。
這個參數真的有性能優化嗎?測試代碼沒有IO輸出,純測試代碼的執行速度,測試代碼如下:
public void testPerformance() {
long start = System.currentTimeMillis();
System.out.println("start");
for (int i = 0; i < 1000 * 1000; i++) {
try {
this.method();
} catch (Exception ex) {
}
}
System.out.println("used " + (System.currentTimeMillis() - start));
}
public void method() {
String value = null;
value.substring(0, 100);
}
測試結果如下:
測試結果發現,關閉堆棧后性能確實有了很大的提升,在輸出堆棧的情況下,性能隨著調用次數的增多,呈線性增長。
測試代碼中的堆棧信息,只有一層,把調用異常堆棧的深度增加到20,是不是創建的對象而更多,耗時時間更長呢?關閉參數的情況下,確實是,調用1M次,時間增加到由13秒增加到20秒;啟用參數的情況下,耗時卻從400毫秒減少到150毫秒!
經測試發現:同樣都是在5500多次的時候,丟掉異常的堆棧信息。并且20層異常堆棧,執行這5500多次,耗時120毫秒;層數較少的只用了70毫秒。也就是說,堆棧層數越多,丟掉堆棧后的性能越好!具體是什么原因,就需要閱讀源代碼了!如果你知道,歡迎留言探討。