如何從消失的例外堆疊定位線上問題

一、消失的例外堆疊

在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機制，則可以通過向前追溯相同的日志來定位問題，

如在開門紅中，有個介面的可用率調到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=https://www.cnblogs.com/Jcloud/p/0.0

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

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

四、問題原因分析

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

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

很大原因是網路抖動

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

一般是由于鏈路的服務器或埠無法訪問，對于虛擬機或者docker，還需要考慮宿主機的問題，

通過系統級分析，最后確定是由于宿主機連接性問題導致docker實體TCP重傳增高，當然最重要的是補充相關的指標監控，

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

作者：京東零售 張帥

來源：京東云開發者社區

標籤：其他

上一篇：WEB系統安全之開源軟體風險使用評估

下一篇：返回列表