一、現(xiàn)象

在服務器上通過curl命令調用一個Java服務的查詢接口，半天沒有任何響應。關于該服務的基本功能如下：

1、該服務是一個后臺刷新指示器的服務，即該服務會將用戶需要的指示器數(shù)據(jù)提前計算好，放入redis中，當用戶請求指示器數(shù)據(jù)時便從redis中獲??；

2、指示器涉及到的模型數(shù)據(jù)更新時會發(fā)送消息到kafka，該服務監(jiān)聽kafka消息，收到消息后觸發(fā)指示器刷新任務；

3、對于一些特殊的指示器，其涉及的項目和模型較多，且數(shù)據(jù)量比較大，無法通過kafka消息來觸發(fā)刷新，否則一直處于刷新過程中，便每隔10分鐘定時進行指示器的刷新，以盡量保證的數(shù)據(jù)的及時性；

4、該服務不對外提供接口，只預留一些指示器刷新的監(jiān)控接口，供內部開發(fā)人員使用；

5、相同代碼還部署了另外一個服務對外開放，用戶請求指示器數(shù)據(jù)時就向其請求，如果redis緩存中有便直接返回，沒有的話那個服務便實時計算。

二、排查

1、打印堆棧

　　看到上述的現(xiàn)象，第一反應就是服務掛了，于是便通過jps命令查看該服務的進程號，發(fā)現(xiàn)服務還在。那么會不會是tomcat的線程被占滿，沒有線程去響應請求，但是按理說是不會的，因為該服務并沒有對外提供接口。抱著好奇心還是通過jstack pid命令打印出堆棧來查看，如下圖所示。發(fā)現(xiàn)當前只有10個tomcat的線程，并且都處于空閑狀態(tài)，那么就不可能因為線程被占滿而導致curl接口沒有響應。

2、查看socket連接

　　就在一籌莫展之時，同事告訴我zabbix監(jiān)控那邊會每隔一分鐘調用該服務的查詢接口來獲取當前的刷新任務數(shù)，從而展示在zabbix上進行實時監(jiān)控。這時趕緊調用netstat -anp|grep 9097命令查看一下當前是否有請求，發(fā)現(xiàn)zabbix那邊的請求全部卡死了。

這些卡死的請求全部都在ESTABLISHED狀態(tài)，基本上把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區(qū)的內存占用率，O表示老年代的內存占用率，YGC表示年輕代GC的次數(shù)，YGCT表示年輕代GC的時間總和，F(xiàn)GC表示Full GC的次數(shù)，F(xiàn)GCT表示Ful GC的時間總和。從上圖可以看出，在195次Full GC后，Eden區(qū)僅僅過了4秒內存就基本上滿了，這時又發(fā)生了Full GC，即第196次Full GC。

　　從上圖可以看出，用兩次的FGCT相減，即4301減去4277，可以知道196次Full GC花了大約24秒，這期間服務基本上處于停滯的狀態(tài)，而且從Full GC后的老年代內存占用率可以看出，并沒有回收老年代多少內存，占用率依舊很高。這意味著幾秒后又將進行Full GC操作，反復循環(huán)。由此看出，該服務基本上一直處于卡死的狀態(tài)，內存將要溢出。那么，到底是什么對象長期占據(jù)著內存呢？

5、分析dump文件

　　這時想起，該服務為了提高相似指示器的計算效率，使用了google的緩存guava。每次計算完指示器后會將該指示器涉及到的模型數(shù)據(jù)存儲在緩存中，下次計算相同模型的指示器時可以直接從內存中獲取，而不需要訪問數(shù)據(jù)庫，因為數(shù)據(jù)量比較大，所以可以顯著提升查詢指示器的效率。guava緩存的失效時間是30分鐘，也就是說30分鐘內的Full GC是無法回收多少內存的。為了證明我的猜想，就在服務啟動參數(shù)上增加了-XX:+HeapDumpOnOutOfMemoryError。這樣在服務內存溢出時會自動生成dump文件，將dump文件導出，通過VisualVM就可以分析出究竟是什么占據(jù)著內存。

　　由于我的電腦內存有限，無法打開20G的dump文件，就將服務內存調整為3G，guava緩存分配2G，運行一段時間就生成了dump文件，通過VisualVm打開，如下圖所示。

從上圖可以看出，byte數(shù)組占據(jù)了46%的內存空間，點擊byte[]實例可以看到具體是哪些數(shù)據(jù)占據(jù)了內存，如下圖所示。

可以看到byte數(shù)組有大量的LazyString類型，即com.mysql.cj.util.LazyString，點擊詳情查看。

　　發(fā)現(xiàn)好多ResultSet沒有被釋放，這就是查詢指示器模型數(shù)據(jù)的返回結果。由于這些模型數(shù)據(jù)都被緩存對象引用著，而且緩存的有效期是30分鐘，所以新生代GC無法回收，直到進入老年代，如果沒有超過30分鐘緩存有效期Full GC也不會回收，所以內存被占滿。由于這些指示器計算都是并發(fā)的，30個線程同步查詢數(shù)據(jù)會導致內存中有大量的數(shù)據(jù)緩存對象，從而導致內存溢出。

三、優(yōu)化

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

1、不再使用guava緩存，每次都實時查詢指示器的數(shù)據(jù)。因為該服務是后臺刷新服務，將計算的好指示器結果存入redis緩存，不需要直接給用戶提供服務。因此，該服務不需要計算很快，只需要正確即可，取消guava緩存后新生代GC會很快回收掉不再使用的大對象，使得這些對象不會進入老年代引發(fā)Full GC，即使進入老年代也能通過Full GC回收掉，不至于內存溢出。

2、降低線程的并發(fā)數(shù)。雖然不使用緩存會提高內存的使用率，但是如果并發(fā)數(shù)過高，并且指示器數(shù)據(jù)量過大，那么在某一瞬間內存也會被占滿，且不會被Minor GC回收掉，從而進入老年代，直到觸發(fā)Full GC。

　　只有做到以上兩點，并且適當調大服務內存，這樣才會盡量讓大量的垃圾數(shù)據(jù)在年輕代就GC掉，而不是進入到老年代引發(fā)Full GC。

　　上圖是優(yōu)化后的GC日志，可以看出，新生代GC后回收了很多垃圾，并且很少一分部分對象會進入到老年代，這樣會減少Full GC的次數(shù)，從而解決系統(tǒng)卡死的問題。

四、總結

通過本次事故的排查，對于服務假死這樣的現(xiàn)象，一般的排查過程為：

1、查看服務進程是否存在；

2、根據(jù)進程號查看CPU占用率和內存占用率，這里可以使用arthas這樣第三方的插件，也可以使用jdk自帶的工具，如jstack，jstat，jmap等；

3、查看GC日志；

4、如果有內存溢出情況，可以查看dump文件找出溢出點。

到此這篇關于Java服務假死之生產事故的排查與優(yōu)化問題的文章就介紹到這了,更多相關Java服務假死內容請搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關文章希望大家以后多多支持腳本之家！

最新評論