Java服務假死之生產事故的排查與優化問題

2022-07-05 14:05:23

一、現象

在伺服器上通過curl命令呼叫一個Java服務的查詢介面，半天沒有任何響應。關於該服務的基本功能如下：

1、該服務是一個後臺重新整理指示器的服務，即該服務會將使用者需要的指示器資料提前計算好，放入redis中，當用戶請求指示器資料時便從redis中獲取；

2、指示器涉及到的模型資料更新時會傳送訊息到kafka，該服務監聽kafka訊息，收到訊息後觸發指示器重新整理任務；

3、對於一些特殊的指示器，其涉及的專案和模型較多，且資料量比較大，無法通過kafka訊息來觸發重新整理，否則一直處於重新整理過程中，便每隔10分鐘定時進行指示器的重新整理，以儘量保證的資料的及時性；

4、該服務不對外提供介面，只預留一些指示器重新整理的監控介面，供內部開發人員使用；

5、相同程式碼還部署了另外一個服務對外開放，使用者請求指示器資料時就向其請求，如果redis快取中有便直接返回，沒有的話那個服務便實時計算。

二、排查

1、列印堆疊

　　看到上述的現象，第一反應就是服務掛了，於是便通過jps命令檢視該服務的程序號，發現服務還在。那麼會不會是tomcat的執行緒被佔滿，沒有執行緒去響應請求，但是按理說是不會的，因為該服務並沒有對外提供介面。抱著好奇心還是通過jstack pid命令列印出堆疊來檢視，如下圖所示。發現當前只有10個tomcat的執行緒，並且都處於空閒狀態，那麼就不可能因為執行緒被佔滿而導致curl介面沒有響應。

2、檢視socket連線

　　就在一籌莫展之時，同事告訴我zabbix監控那邊會每隔一分鐘呼叫該服務的查詢介面來獲取當前的重新整理任務數，從而展示在zabbix上進行實時監控。這時趕緊呼叫netstat -anp|grep 9097命令檢視一下當前是否有請求，發現zabbix那邊的請求全部卡死了。

這些卡死的請求全部都在ESTABLISHED狀態，基本上把tomcat的socket連線全部佔滿了，這下終於明白為啥呼叫查詢介面，服務沒有響應了，但是為什麼這些查詢介面會卡死呢？

3、檢視JVM基本資訊

　　想要弄明白這個問題，還是要檢視一下JVM內部的資訊，是否記憶體溢位或者CPU佔滿，這裡採用arthas外掛，下載arthas後就可以通過java -jar arthas-boot.jar直接啟動。

該服務是第一個，選擇1按enter鍵進入

通過dashboard命令檢視服務執行的基本資訊

　　從上圖可以看出，CPU佔用率不是很高，但是記憶體佔用率比較高，特別是老年代，該服務總共分配了20G的記憶體，新生代10G，老年代10G 。服務啟動不久後就進行了Full GC，很快老年代就被佔滿，這說明有很多大物件在記憶體中，並且沒有被Minor GC回收掉，進入了老年代。

4、檢視GC紀錄檔

　　為了驗證我的猜想，通過jstat -gcutil221446 1s命令每隔1s將GC資訊實時列印出來，如下圖所示。

　　E表示Eden區的記憶體佔用率，O表示老年代的記憶體佔用率，YGC表示年輕代GC的次數，YGCT表示年輕代GC的時間總和，FGC表示Full GC的次數，FGCT表示Ful GC的時間總和。從上圖可以看出，在195次Full GC後，Eden區僅僅過了4秒記憶體就基本上滿了，這時又發生了Full GC，即第196次Full GC。

　　從上圖可以看出，用兩次的FGCT相減，即4301減去4277，可以知道196次Full GC花了大約24秒，這期間服務基本上處於停滯的狀態，而且從Full GC後的老年代記憶體佔用率可以看出，並沒有回收老年代多少記憶體，佔用率依舊很高。這意味著幾秒後又將進行Full GC操作，反覆迴圈。由此看出，該服務基本上一直處於卡死的狀態，記憶體將要溢位。那麼，到底是什麼物件長期佔據著記憶體呢？

5、分析dump檔案

　　這時想起，該服務為了提高相似指示器的計算效率，使用了google的快取guava。每次計算完指示器後會將該指示器涉及到的模型資料儲存在快取中，下次計算相同模型的指示器時可以直接從記憶體中獲取，而不需要存取資料庫，因為資料量比較大，所以可以顯著提升查詢指示器的效率。guava快取的失效時間是30分鐘，也就是說30分鐘內的Full GC是無法回收多少記憶體的。為了證明我的猜想，就在服務啟動引數上增加了-XX:+HeapDumpOnOutOfMemoryError。這樣在服務記憶體溢位時會自動生成dump檔案，將dump檔案匯出，通過VisualVM就可以分析出究竟是什麼佔據著記憶體。

　　由於我的電腦記憶體有限，無法開啟20G的dump檔案，就將服務記憶體調整為3G，guava快取分配2G，執行一段時間就生成了dump檔案，通過VisualVm開啟，如下圖所示。

從上圖可以看出，byte陣列佔據了46%的記憶體空間，點選byte[]範例可以看到具體是哪些資料佔據了記憶體，如下圖所示。

可以看到byte陣列有大量的LazyString型別，即com.mysql.cj.util.LazyString，點選詳情檢視。

　　發現好多ResultSet沒有被釋放，這就是查詢指示器模型資料的返回結果。由於這些模型資料都被快取物件參照著，而且快取的有效期是30分鐘，所以新生代GC無法回收，直到進入老年代，如果沒有超過30分鐘快取有效期Full GC也不會回收，所以記憶體被佔滿。由於這些指示器計算都是並行的，30個執行緒同步查詢資料會導致記憶體中有大量的資料快取物件，從而導致記憶體溢位。

三、優化

　　針對以上分析出的原因，有以下兩點優化建議：

1、不再使用guava快取，每次都實時查詢指示器的資料。因為該服務是後臺重新整理服務，將計算的好指示器結果存入redis快取，不需要直接給使用者提供服務。因此，該服務不需要計算很快，只需要正確即可，取消guava快取後新生代GC會很快回收掉不再使用的大物件，使得這些物件不會進入老年代引發Full GC，即使進入老年代也能通過Full GC回收掉，不至於記憶體溢位。

2、降低執行緒的並行數。雖然不使用快取會提高記憶體的使用率，但是如果並行數過高，並且指示器資料量過大，那麼在某一瞬間記憶體也會被佔滿，且不會被Minor GC回收掉，從而進入老年代，直到觸發Full GC。

　　只有做到以上兩點，並且適當調大服務記憶體，這樣才會儘量讓大量的垃圾資料在年輕代就GC掉，而不是進入到老年代引發Full GC。