記一次公司JVM堆溢出抽絲剝繭定位的過程

背景

公司線上有個tomcat服務，裏面合併部署了大概8個微服務，之因此沒有像其餘微服務那樣單獨部署，其目的是爲了節約服務器資源，何況這8個服務是屬於邊緣服務，併發不高，就算宕機也不會影響核心業務。

由於併發不高，因此線上一共部署了2個tomcat進行負載均衡。

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

排查過程一

接手這個問題後。首先大體看了下當時的JVM監控。

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進制後進行搜索。發現並無找到相應的線程。因此判斷爲不是應用線程致使的。

第一個結論

經過對當時JVM的的監控狀況，能夠發現。這個小時的22分以前，系統 一直保持着一個比較穩定的運行狀態，堆的使用率不高，可是22分以後，年輕代大量的minor gc後，老年代在幾分鐘以內被快速的填滿。致使了FULL GC。同時FULL GC不停的發生，致使了大量的STW，CPU被FULL GC線程佔據，出現CPU飆高，應用線程因爲STW再加上CPU太高，大量線程被阻塞。同時新的請求又不停的進來，最終tomcat的線程池被佔滿，再也沒法響應新的請求了。這個雪球終於仍是滾大了。

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

是什麼緣由致使老年代被快速的填滿？

拉了下當時的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內存各個區的分配狀況以下：

因此開始懷疑是JVM參數設置的有問題致使的老年代被快速的佔滿。

可是其實這參數已是以前優化後的結果了，eden區設置的挺大，大部分咱們的方法產生的對象都是朝生夕死的對象，應該大部分都在年輕代會清理了。存活的對象纔會進入survivor區。到達年齡或者觸發了進入老年代的條件後纔會進入老年代。基本上老年代裏的對象大部分應該是一直存活的對象。好比static修飾的對象啊，一直被引用的 緩存啊，spring容器中的bean等等。

我看了下垃圾回收進入老年代的觸發條件後（關注公衆號後回覆「JVM」獲取JVM內存分配和回收機制的資料），發現這個場景應該是屬於大對象直接進老年代的這種，也就是說年輕代進行minor GC後，存活的對象足夠大，不足以在survivor區域放下了，就直接進入老年代了。

可是一次minor GC應該超過90%的對象都是無引用對象，只有少部分的對象纔是存活的。並且這些個服務的併發一直不高，爲何一次minor GC後有那麼大量的數據會存活呢。

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

發現String這個這個對象的示例居然有9000多w個，佔用堆超過2G。這確定有問題。可是tomcat裏有8個應用 ，不可能經過分析代碼來定位到。仍是要從JVM入手來反推。

第二次結論

程序併發不高，可是在幾分鐘以內，在eden區產生了大量的對象，而且這些對象沒法被minor GC回收 ，因爲太大，觸發了大對象直接進老年代機制，老年代會迅速填滿，致使FULL GC，和後面CPU的飆升，從而致使tomcat的宕機。

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

排查過程二

次日，又看了下當時的JVM監控，發現有這麼一個監控數據當時漏看了

這是FULL GC以後，老年代的使用率。能夠看到。FULL GC後，老年代依然佔據80%多的空間。full gc就根本清理不掉老年代的對象。這說明，老年代裏的這些對象都是被程序引用着的。因此清理不掉。可是平穩的時候，老年代一直維持着大概300M的堆。從這個小時的22分開始，以後就狂飆到接近2G。這確定不正常。更加印證了我前面一個觀點。這是由於應用程序產生的沒法回收的對象致使的。

可是當時我並無dump下來jvm的堆。因此只能等再次重現問題。

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

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

而後download到本地，解壓。

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

而後查看堆當時的全部類佔比大小的信息

發現致使堆溢出，就是這個String對象，和以前Jmap得出的結果同樣，超過了2個G，而且沒法被回收

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

而後查看引用的關係圖，往上溯源，源頭終於顯形：

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

看來已經要逼近真相了！

第三次結論

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

最後

得知了具體的代碼位置， 直接進去看。通過小夥伴提醒，發現這個代碼有一個問題。

這段代碼爲一個拆詞方法，具體代碼就不貼了，裏面有一個循環，每一次循環會往一個ArrayList里加一個String對象，在循環的某一個階段，會重置循環計數器i，在普通的參數下並無問題。可是某些特定的條件下。就會不停的重置循環計數器i，致使一個死循環。

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

至此，水落石出。

最終結論

由於Media這個微服務的程序在某一些特殊場景下的一段程序致使了死循環，產生了一個超大的ArrayList。致使了年輕代的快速被填滿，而後觸發了大對象直接進老年代的機制，直接往老年代裏面放。老年代被放滿以後。觸發FULL GC。可是這些ArrayList被GC ROOT根引用着，沒法回收。致使回收不掉。老年代依舊滿的，隨機立刻又觸發FULL GC。同時由於老年代沒法被回收，致使minor GC也無法清理，不停的進行minor GC。大量GC致使STW和CPU飆升，致使應用線程卡頓，阻塞，直至最後整個服務沒法接受請求。

聯繫做者

微信關注 「jishuyuanren」或者掃描如下二維碼獲取更多技術乾貨：

關注公衆號後回覆「JVM」獲取JVM內存分配和回收機制的資料