一、現(xiàn)象

在服務(wù)器上通過curl命令調(diào)用一個Java服務(wù)的查詢接口，半天沒有任何響應(yīng)。關(guān)于該服務(wù)的基本功能如下：

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

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

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

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

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

二、排查

1、打印堆棧

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

2、查看socket連接

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

這些卡死的請求全部都在ESTABLISHED狀態(tài)，基本上把tomcat的socket連接全部占滿了，這下終于明白為啥調(diào)用查詢接口，服務(wù)沒有響應(yīng)了，但是為什么這些查詢接口會卡死呢？

3、查看JVM基本信息

　　想要弄明白這個問題，還是要查看一下JVM內(nèi)部的信息，是否內(nèi)存溢出或者CPU占滿，這里采用arthas插件，下載arthas后就可以通過java -jar arthas-boot.jar直接啟動。

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

通過dashboard命令查看服務(wù)運行的基本信息

　　從上圖可以看出，CPU占用率不是很高，但是內(nèi)存占用率比較高，特別是老年代，該服務(wù)總共分配了20G的內(nèi)存，新生代10G，老年代10G 。服務(wù)啟動不久后就進行了Full GC，很快老年代就被占滿，這說明有很多大對象在內(nèi)存中，并且沒有被Minor GC回收掉，進入了老年代。

4、查看GC日志

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

　　E表示Eden區(qū)的內(nèi)存占用率，O表示老年代的內(nèi)存占用率，YGC表示年輕代GC的次數(shù)，YGCT表示年輕代GC的時間總和，F(xiàn)GC表示Full GC的次數(shù)，F(xiàn)GCT表示Ful GC的時間總和。從上圖可以看出，在195次Full GC后，Eden區(qū)僅僅過了4秒內(nèi)存就基本上滿了，這時又發(fā)生了Full GC，即第196次Full GC。

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

5、分析dump文件

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

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

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

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

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

三、優(yōu)化

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

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

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

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

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

四、總結(jié)

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

1、查看服務(wù)進程是否存在；

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

3、查看GC日志；

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

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

最新評論