技術文章 » 如何從消失的異常堆疊定位線上問題

如何從消失的異常堆疊定位線上問題

2023-06-29 12:01:59

一、消失的異常堆疊

在618保障大促穩定性過程中，消失的異常堆疊可能會給我們帶來嚴重的麻煩，因為這些堆疊資訊是我們解決線上問題的關鍵之一。如何快速定位問題？想必大家心中都有自己的答案，當然最簡單直接的辦法還是查詢異常堆疊資訊。

然而有時異常堆疊並不完整，只有一句描述，如下：

Caused by: java.lang.NullPointerException

造成這種現象的原因其實很簡單，原因如下：

JIT編譯器對異常進行了優化，當程式碼中的某個位置丟擲同一個異常很多次後,
JIT伺服器端編譯器(C2)會將其優化成丟擲一個事先編譯好的、型別匹配的異常,異常堆疊資訊就看不到了。

二、Fast Throw

Fast Throw，欄位上理解就是快速拋異常，目前需要滿足以下條件才有如此的優化：

  • 只針對HotSpot VM才有, 例如oracleJDK, libericaJDK等

  • 特定位置丟擲很多次,其實就是JIT將它優化了

  • JIT必須使用C2才會這樣優化,不丟擲原來的異常,改用fast throw丟擲

  • 這是一個事先分配好的異常,message和堆疊都是空的

可以看出,如果某個異常在同一位置被丟擲多次,會被JIT C2優化成空異常,例如本文的NullPointerException,既沒有message,也沒有堆疊.但他的速度非常快,不用分配記憶體和獲取堆疊.

如果想關閉這個優化,設定-XX:-OmitStackTraceInFastThrow即可。

存在即合理，既然存在fast throw的優化，必然有其價值。fast throw優化的原因是為了提高效能。當同一種異常在相同的位置被丟擲多次，編譯器就會重新編譯此方法。重編譯後，編譯器可能會使用不提供跟蹤的預分配異常來選擇更快的策略。

本地測試了一下丟擲NullPointerException,在開啟與關閉fast throw的效能。

執行次數 開啟Fast Throw 關閉Fast Throw
10w 996ms 3525ms
100w 5983ms 28345ms
500w 35678ms ——

言而簡之，不能因此出現了消失的異常堆疊就嘗試關閉fast throw優化功能。

三、問題原因定位

對於線上環境中觸發了Fast Throw機制，則可以通過向前追溯相同的紀錄檔來定位問題。

如在開門紅中，有個介面的可用率調到98.3%（不是100%），如下圖。

然後搜尋紀錄檔發現大量的Caused by: java.lang.NullPointerException，沒有詳細的異常堆疊，很顯然是由於fast throw導致的，然後不斷向前追溯相同的紀錄檔來定位問題如下圖。

19:05:32.592 [JSF-BZ-22001-245-T-522] ERROR com.jd.m.soa.shop.service.jsf.shop.impl.ShopSoaOutSideJsfServiceImpl - ShopSoaOutSideJsfServiceImpl.getKACard error
com.jd.sirector.SirectorException: java.lang.NullPointerException
	at com.jd.sirector.ScriptRuntime.waitIfNecessary(ScriptRuntime.java:129) ~[sirector-core-0.2.2-beta.jar:?]
	at com.jd.sirector.ScriptRuntime.run(ScriptRuntime.java:66) ~[sirector-core-0.2.2-beta.jar:?]
	at com.jd.sirector.Sirector.publish(Sirector.java:153) ~[sirector-core-0.2.2-beta.jar:?]
	****************
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_60]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_60]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_60]
	at java.lang.Thread.run(Thread.java:745) ~[?:1.8.0_60]
Caused by: java.lang.NullPointerException
	at com.jd.******************wProxy.java:321) ~[shop-soa-service-1.1.jar:?]
	**************
	... 5 more
19:05:44.063 [JSF-BZ-22001-245-T-503] ERROR com.jd.m.soa.shop.service.jsf.shop.impl.ShopSoaOutSideJsfServiceImpl - ShopSoaOutSideJsfServiceImpl.getKACard error
com.jd.sirector.SirectorException: java.lang.NullPointerException
	at com.jd.sirector.ScriptRuntime.waitIfNecessary(ScriptRuntime.java:129) ~[sirector-core-0.2.2-beta.jar:?]
	at com.jd.sirector.ScriptRuntime.run(ScriptRuntime.java:66) ~[sirector-core-0.2.2-beta.jar:?]
	at com.jd.sirector.Sirector.publish(Sirector.java:153) ~[sirector-core-0.2.2-beta.jar:?]
	****************
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_60]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_60]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_60]
	at java.lang.Thread.run(Thread.java:745) ~[?:1.8.0_60]
Caused by: java.lang.NullPointerException
19:05:47.831 [pool-84-thread-10] ERROR com.jd.m.soa.shop.service.base.shop.impl.ShopBaseServiceImpl - 上游返回的店鋪星級值非法。value=0.0

出現問題的原因找到了，接著就分析原因。原因很簡單，由於某一臺機器效能波動導致介面超時將兜底物件快取，後續邏輯在處理的過種中物件中的Boolean屬性值在轉boolean時出現NPE，問題根源還是程式碼相容性不足夠好。

這這臺機器進行系統檢視層分析，發現TCP重傳數較高，如下左圖。

四、問題原因分析

TCP重傳主要是為了保證資料傳輸的可靠性，TCP是一種保證可靠傳輸的機制，如重傳與確認機制、資料校驗、資料分片、流量控制、擁塞控制等。TCP重傳的型別有超時重傳和快速重傳。超時重傳是在請求包傳送出去時開啟計時器，當到達時間之後，沒有收到ACK，則進行重傳直到達到上限次數或者收到ACK。快速重傳則依賴於封包的期望序列號，並進行一致性檢查。

  • 多臺機器或者同一機房同時TCP重傳

很大原因是網路抖動

  • 單機或者某個應用出現TCP重傳

一般是由於鏈路的伺服器或埠無法存取，對於虛擬機器器或者docker，還需要考慮宿主機的問題。

通過系統級分析，最後確定是由於宿主機連線性問題導致docker範例TCP重傳增高，當然最重要的是補充相關的指標監控。

總之，無論是在大促期間還在平時，遇到問題首先解決好問題，更為重要的是追本溯原，找出問題的根因，以便推動團隊優化和提升。

作者：京東零售 張帥

來源：京東雲開發者社群