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

背景

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

因為並發不高,所以線上一共部署了2個tomcat進行負載均衡。

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

排查過程一

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

CPU的確居高不下

file

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

file

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

file

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

file

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

file

可以看到前面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內存各個區的分配情況如下:

file

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

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

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

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

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

file

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

第二次結論

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

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

排查過程二

第二天,又看了下當時的JVM監控,發現有這麼一個監控數據當時漏看了

file

這是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文件。

然後查看堆當時的所有類佔比大小的信息

file

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

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

file

然後查看引用的關係圖,往上溯源,源頭終於顯形:

file

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

看來已經要逼近真相了!

第三次結論

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

最後

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

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

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

file

至此,水落石出。

最終結論

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

聯繫作者

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

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