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

菠菜東發表於2020-07-20

背景

公司線上有個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記憶體分配和回收機制的資料

相關文章