背景

公司線上有個tomcat服務，里面合并部署了大概8個微服務，之所以沒有像其他微服務那樣單獨部署，其目的是為了節(jié)約服務器資源，況且這8個服務是屬于邊緣服務，并發(fā)不高，就算宕機也不會影響核心業(yè)務。

因為并發(fā)不高，所以線上一共部署了2個tomcat進行負載均衡。

這個tomcat剛上生產線，運行挺平穩(wěn)。大概過了大概1天后，運維同事反映2個tomcat節(jié)點均掛了。無法接受新的請求了。CPU飆升到100%。

排查過程一

接手這個問題后。首先大致看了下當時的JVM監(jiān)控。

CPU的確居高不下

FULL GC從大概這個小時的22分開始，就開始頻繁的進行FULL GC，一分鐘最高能進行10次FULL GC

minor GC每分鐘竟然接近60次，相當于每秒鐘都有minor GC

從老年代的使用情況也反應了這一點

隨機對線上應用分析了線程的cpu占用情況，用top -H -p pid命令

可以看到前面4條線程，都占用了大量的CPU資源。隨即進行了jstack，把線程棧信息拉下來，用前面4條線程的ID轉換16進制后進行搜索。發(fā)現并沒有找到相應的線程。所以判斷為不是應用線程導致的。

第一個結論

通過對當時JVM的的監(jiān)控情況，可以發(fā)現。這個小時的22分之前，系統(tǒng) 一直保持著一個比較穩(wěn)定的運行狀態(tài)，堆的使用率不高，但是22分之后，年輕代大量的minor gc后，老年代在幾分鐘之內被快速的填滿。導致了FULL GC。同時FULL GC不停的發(fā)生，導致了大量的STW，CPU被FULL GC線程占據，出現CPU飆高，應用線程由于STW再加上CPU過高，大量線程被阻塞。同時新的請求又不停的進來，最終tomcat的線程池被占滿，再也無法響應新的請求了。這個雪球終于還是滾大了。

分析完了案發(fā)現場。要解決的問題變成了：

是什么原因導致老年代被快速的填滿？

拉了下當時的JVM參數

-Djava.awt.headless=true -Dfile.encoding=UTF-8 -server -Xms2048m -Xmx4096m -Xmn2048m -Xss512k -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:+DisableExx
plicitGC -XX:MaxTenuringThreshold=5 -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCMSCompactAtFullCollection
-XX:+PrintGCDetails -Xloggc:/data/logs/gc.log

總共4個G的堆，年輕代單獨給了2個G，按照比率算，JVM內存各個區(qū)的分配情況如下：

所以開始懷疑是JVM參數設置的有問題導致的老年代被快速的占滿。

但是其實這參數已經是之前優(yōu)化后的結果了，eden區(qū)設置的挺大，大部分我們的方法產生的對象都是朝生夕死的對象，應該大部分都在年輕代會清理了。存活的對象才會進入survivor區(qū)。到達年齡或者觸發(fā)了進入老年代的條件后才會進入老年代?；旧侠夏甏锏膶ο蟠蟛糠謶撌且恢贝婊畹膶ο?。比如static修飾的對象啊，一直被引用的 緩存啊，spring容器中的bean等等。

我看了下垃圾回收進入老年代的觸發(fā)條件后（關注公眾號后回復“JVM”獲取JVM內存分配和回收機制的資料），發(fā)現這個場景應該是屬于大對象直接進老年代的這種，也就是說年輕代進行minor GC后，存活的對象足夠大，不足以在survivor區(qū)域放下了，就直接進入老年代了。

但是一次minor GC應該超過90%的對象都是無引用對象，只有少部分的對象才是存活的。而且這些個服務的并發(fā)一直不高，為什么一次minor GC后有那么大量的數據會存活呢。

隨即看了下當時的jmap -histo 命令產生的文件

發(fā)現String這個這個對象的示例竟然有9000多w個，占用堆超過2G。這肯定有問題。但是tomcat里有8個應用 ，不可能通過分析代碼來定位到。還是要從JVM入手來反推。

第二次結論

程序并發(fā)不高，但是在幾分鐘之內，在eden區(qū)產生了大量的對象，并且這些對象無法被minor GC回收 ，由于太大，觸發(fā)了大對象直接進老年代機制，老年代會迅速填滿，導致FULL GC，和后面CPU的飆升，從而導致tomcat的宕機。

基本判斷是，JVM參數應該沒有問題，很可能問題出在應用本身不斷產生無法被回收的對象上面。但是我暫時定位不到具體的代碼位置。

排查過程二

第二天，又看了下當時的JVM監(jiān)控，發(fā)現有這么一個監(jiān)控數據當時漏看了

這是FULL GC之后，老年代的使用率?？梢钥吹?。FULL GC后，老年代依然占據80%多的空間。full gc就根本清理不掉老年代的對象。這說明，老年代里的這些對象都是被程序引用著的。所以清理不掉。但是平穩(wěn)的時候，老年代一直維持著大概300M的堆。從這個小時的22分開始，之后就狂飆到接近2G。這肯定不正常。更加印證了我前面一個觀點。這是因為應用程序產生的無法回收的對象導致的。

但是當時我并沒有dump下來jvm的堆。所以只能等再次重現問題。

終于，在晚上9點多，這個問題又重現了，熟悉的配方，熟悉的味道。

直接jmap -dump，經過漫長的等待，產生了4.2G的一個堆快照文件dump.hprof，經過壓縮，得到一個466M的tar.gz文件

然后download到本地，解壓。

運行堆分析工具JProfile，裝載這個dump.hprof文件。

然后查看堆當時的所有類占比大小的信息

發(fā)現導致堆溢出，就是這個String對象，和之前Jmap得出的結果一樣，超過了2個G，并且無法被回收

隨即看大對象視圖，發(fā)現這些個String對象都是被java.util.ArrayList引用著的，也就是有一個ArrayList里，引用了超過2G的對象

然后查看引用的關系圖，往上溯源，源頭終于顯形：

這個ArrayList是被一個線程棧引用著，而這個線程棧信息里面，可以直接定位到相應的服務，相應的類。具體服務是Media這個微服務。

看來已經要逼近真相了！

第三次結論

本次大量頻繁的FULL GC是因為應用程序產生了大量無法被回收的數據，最終進入老年代，最終把老年代撐滿了導致的。具體的定位通過JVM的dump文件已經分析出，指向了Media這個服務的ImageCombineUtils.getComputedLines這個方法，是什么會產生尚不知道，需要具體分析代碼。

最后

得知了具體的代碼位置， 直接進去看。經過小伙伴提醒，發(fā)現這個代碼有一個問題。

這段代碼為一個拆詞方法，具體代碼就不貼了，里面有一個循環(huán)，每一次循環(huán)會往一個ArrayList里加一個String對象，在循環(huán)的某一個階段，會重置循環(huán)計數器i，在普通的參數下并沒有問題。但是某些特定的條件下。就會不停的重置循環(huán)計數器i，導致一個死循環(huán)。

以下是模擬出來的結果，可以看到，才運行了一會，這個ArrayList就產生了322w個對象，且大部分Stirng對象都是空值。

至此，水落石出。

最終結論

因為Media這個微服務的程序在某一些特殊場景下的一段程序導致了死循環(huán)，產生了一個超大的ArrayList。導致了年輕代的快速被填滿，然后觸發(fā)了大對象直接進老年代的機制，直接往老年代里面放。老年代被放滿之后。觸發(fā)FULL GC。但是這些ArrayList被GC ROOT根引用著，無法回收。導致回收不掉。老年代依舊滿的，隨機馬上又觸發(fā)FULL GC。同時因為老年代無法被回收，導致minor GC也沒法清理，不停的進行minor GC。大量GC導致STW和CPU飆升，導致應用線程卡頓，阻塞，直至最后整個服務無法接受請求。

到此這篇關于記一次公司JVM堆溢出抽絲剝繭定位的過程的文章就介紹到這了,更多相關JVM堆溢出抽絲剝繭定位內容請搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關文章希望大家以后多多支持腳本之家！

最新評論