記一次公司JVM堆溢出抽絲剝繭定位的過程解析
背景
公司線上有個(gè)tomcat服務(wù),里面合并部署了大概8個(gè)微服務(wù),之所以沒有像其他微服務(wù)那樣單獨(dú)部署,其目的是為了節(jié)約服務(wù)器資源,況且這8個(gè)服務(wù)是屬于邊緣服務(wù),并發(fā)不高,就算宕機(jī)也不會影響核心業(yè)務(wù)。
因?yàn)椴l(fā)不高,所以線上一共部署了2個(gè)tomcat進(jìn)行負(fù)載均衡。
這個(gè)tomcat剛上生產(chǎn)線,運(yùn)行挺平穩(wěn)。大概過了大概1天后,運(yùn)維同事反映2個(gè)tomcat節(jié)點(diǎn)均掛了。無法接受新的請求了。CPU飆升到100%。
排查過程一
接手這個(gè)問題后。首先大致看了下當(dāng)時(shí)的JVM監(jiān)控。
CPU的確居高不下
FULL GC從大概這個(gè)小時(shí)的22分開始,就開始頻繁的進(jìn)行FULL GC,一分鐘最高能進(jìn)行10次FULL GC
minor GC每分鐘竟然接近60次,相當(dāng)于每秒鐘都有minor GC
從老年代的使用情況也反應(yīng)了這一點(diǎn)
隨機(jī)對線上應(yīng)用分析了線程的cpu占用情況,用top -H -p pid命令
可以看到前面4條線程,都占用了大量的CPU資源。隨即進(jìn)行了jstack,把線程棧信息拉下來,用前面4條線程的ID轉(zhuǎn)換16進(jìn)制后進(jìn)行搜索。發(fā)現(xiàn)并沒有找到相應(yīng)的線程。所以判斷為不是應(yīng)用線程導(dǎo)致的。
第一個(gè)結(jié)論
通過對當(dāng)時(shí)JVM的的監(jiān)控情況,可以發(fā)現(xiàn)。這個(gè)小時(shí)的22分之前,系統(tǒng) 一直保持著一個(gè)比較穩(wěn)定的運(yùn)行狀態(tài),堆的使用率不高,但是22分之后,年輕代大量的minor gc后,老年代在幾分鐘之內(nèi)被快速的填滿。導(dǎo)致了FULL GC。同時(shí)FULL GC不停的發(fā)生,導(dǎo)致了大量的STW,CPU被FULL GC線程占據(jù),出現(xiàn)CPU飆高,應(yīng)用線程由于STW再加上CPU過高,大量線程被阻塞。同時(shí)新的請求又不停的進(jìn)來,最終tomcat的線程池被占滿,再也無法響應(yīng)新的請求了。這個(gè)雪球終于還是滾大了。
分析完了案發(fā)現(xiàn)場。要解決的問題變成了:
是什么原因?qū)е吕夏甏豢焖俚奶顫M?
拉了下當(dāng)時(shí)的JVM參數(shù)
-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è)G的堆,年輕代單獨(dú)給了2個(gè)G,按照比率算,JVM內(nèi)存各個(gè)區(qū)的分配情況如下:
所以開始懷疑是JVM參數(shù)設(shè)置的有問題導(dǎo)致的老年代被快速的占滿。
但是其實(shí)這參數(shù)已經(jīng)是之前優(yōu)化后的結(jié)果了,eden區(qū)設(shè)置的挺大,大部分我們的方法產(chǎn)生的對象都是朝生夕死的對象,應(yīng)該大部分都在年輕代會清理了。存活的對象才會進(jìn)入survivor區(qū)。到達(dá)年齡或者觸發(fā)了進(jìn)入老年代的條件后才會進(jìn)入老年代。基本上老年代里的對象大部分應(yīng)該是一直存活的對象。比如static修飾的對象啊,一直被引用的 緩存啊,spring容器中的bean等等。
我看了下垃圾回收進(jìn)入老年代的觸發(fā)條件后(關(guān)注公眾號后回復(fù)“JVM”獲取JVM內(nèi)存分配和回收機(jī)制的資料),發(fā)現(xiàn)這個(gè)場景應(yīng)該是屬于大對象直接進(jìn)老年代的這種,也就是說年輕代進(jìn)行minor GC后,存活的對象足夠大,不足以在survivor區(qū)域放下了,就直接進(jìn)入老年代了。
但是一次minor GC應(yīng)該超過90%的對象都是無引用對象,只有少部分的對象才是存活的。而且這些個(gè)服務(wù)的并發(fā)一直不高,為什么一次minor GC后有那么大量的數(shù)據(jù)會存活呢。
隨即看了下當(dāng)時(shí)的jmap -histo 命令產(chǎn)生的文件
發(fā)現(xiàn)String這個(gè)這個(gè)對象的示例竟然有9000多w個(gè),占用堆超過2G。這肯定有問題。但是tomcat里有8個(gè)應(yīng)用 ,不可能通過分析代碼來定位到。還是要從JVM入手來反推。
第二次結(jié)論
程序并發(fā)不高,但是在幾分鐘之內(nèi),在eden區(qū)產(chǎn)生了大量的對象,并且這些對象無法被minor GC回收 ,由于太大,觸發(fā)了大對象直接進(jìn)老年代機(jī)制,老年代會迅速填滿,導(dǎo)致FULL GC,和后面CPU的飆升,從而導(dǎo)致tomcat的宕機(jī)。
基本判斷是,JVM參數(shù)應(yīng)該沒有問題,很可能問題出在應(yīng)用本身不斷產(chǎn)生無法被回收的對象上面。但是我暫時(shí)定位不到具體的代碼位置。
排查過程二
第二天,又看了下當(dāng)時(shí)的JVM監(jiān)控,發(fā)現(xiàn)有這么一個(gè)監(jiān)控?cái)?shù)據(jù)當(dāng)時(shí)漏看了
這是FULL GC之后,老年代的使用率。可以看到。FULL GC后,老年代依然占據(jù)80%多的空間。full gc就根本清理不掉老年代的對象。這說明,老年代里的這些對象都是被程序引用著的。所以清理不掉。但是平穩(wěn)的時(shí)候,老年代一直維持著大概300M的堆。從這個(gè)小時(shí)的22分開始,之后就狂飆到接近2G。這肯定不正常。更加印證了我前面一個(gè)觀點(diǎn)。這是因?yàn)閼?yīng)用程序產(chǎn)生的無法回收的對象導(dǎo)致的。
但是當(dāng)時(shí)我并沒有dump下來jvm的堆。所以只能等再次重現(xiàn)問題。
終于,在晚上9點(diǎn)多,這個(gè)問題又重現(xiàn)了,熟悉的配方,熟悉的味道。
直接jmap -dump,經(jīng)過漫長的等待,產(chǎn)生了4.2G的一個(gè)堆快照文件dump.hprof,經(jīng)過壓縮,得到一個(gè)466M的tar.gz文件
然后download到本地,解壓。
運(yùn)行堆分析工具JProfile,裝載這個(gè)dump.hprof文件。
然后查看堆當(dāng)時(shí)的所有類占比大小的信息
發(fā)現(xiàn)導(dǎo)致堆溢出,就是這個(gè)String對象,和之前Jmap得出的結(jié)果一樣,超過了2個(gè)G,并且無法被回收
隨即看大對象視圖,發(fā)現(xiàn)這些個(gè)String對象都是被java.util.ArrayList引用著的,也就是有一個(gè)ArrayList里,引用了超過2G的對象
然后查看引用的關(guān)系圖,往上溯源,源頭終于顯形:
這個(gè)ArrayList是被一個(gè)線程棧引用著,而這個(gè)線程棧信息里面,可以直接定位到相應(yīng)的服務(wù),相應(yīng)的類。具體服務(wù)是Media這個(gè)微服務(wù)。
看來已經(jīng)要逼近真相了!
第三次結(jié)論
本次大量頻繁的FULL GC是因?yàn)閼?yīng)用程序產(chǎn)生了大量無法被回收的數(shù)據(jù),最終進(jìn)入老年代,最終把老年代撐滿了導(dǎo)致的。具體的定位通過JVM的dump文件已經(jīng)分析出,指向了Media這個(gè)服務(wù)的ImageCombineUtils.getComputedLines這個(gè)方法,是什么會產(chǎn)生尚不知道,需要具體分析代碼。
最后
得知了具體的代碼位置, 直接進(jìn)去看。經(jīng)過小伙伴提醒,發(fā)現(xiàn)這個(gè)代碼有一個(gè)問題。
這段代碼為一個(gè)拆詞方法,具體代碼就不貼了,里面有一個(gè)循環(huán),每一次循環(huán)會往一個(gè)ArrayList里加一個(gè)String對象,在循環(huán)的某一個(gè)階段,會重置循環(huán)計(jì)數(shù)器i,在普通的參數(shù)下并沒有問題。但是某些特定的條件下。就會不停的重置循環(huán)計(jì)數(shù)器i,導(dǎo)致一個(gè)死循環(huán)。
以下是模擬出來的結(jié)果,可以看到,才運(yùn)行了一會,這個(gè)ArrayList就產(chǎn)生了322w個(gè)對象,且大部分Stirng對象都是空值。
至此,水落石出。
最終結(jié)論
因?yàn)镸edia這個(gè)微服務(wù)的程序在某一些特殊場景下的一段程序?qū)е铝怂姥h(huán),產(chǎn)生了一個(gè)超大的ArrayList。導(dǎo)致了年輕代的快速被填滿,然后觸發(fā)了大對象直接進(jìn)老年代的機(jī)制,直接往老年代里面放。老年代被放滿之后。觸發(fā)FULL GC。但是這些ArrayList被GC ROOT根引用著,無法回收。導(dǎo)致回收不掉。老年代依舊滿的,隨機(jī)馬上又觸發(fā)FULL GC。同時(shí)因?yàn)槔夏甏鸁o法被回收,導(dǎo)致minor GC也沒法清理,不停的進(jìn)行minor GC。大量GC導(dǎo)致STW和CPU飆升,導(dǎo)致應(yīng)用線程卡頓,阻塞,直至最后整個(gè)服務(wù)無法接受請求。
到此這篇關(guān)于記一次公司JVM堆溢出抽絲剝繭定位的過程的文章就介紹到這了,更多相關(guān)JVM堆溢出抽絲剝繭定位內(nèi)容請搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家!
相關(guān)文章
SpringMVC實(shí)現(xiàn)文件上傳和下載的工具類
這篇文章主要為大家詳細(xì)介紹了SpringMVC實(shí)現(xiàn)文件上傳和下載的工具類,文中示例代碼介紹的非常詳細(xì),具有一定的參考價(jià)值,感興趣的小伙伴們可以參考一下2020-05-05spring-spring容器中bean知識點(diǎn)總結(jié)
在本篇文章里小編給大家分享了關(guān)于spring-spring容器中bean知識點(diǎn)總結(jié),有需要的朋友們可以學(xué)習(xí)下。2019-08-08將Java的List結(jié)構(gòu)通過GSON庫轉(zhuǎn)換為JSON的方法示例
GONS是Google在GitHub上開源的Java類庫,提供各種Java對象和JSON格式對象之間的轉(zhuǎn)換功能,將Java的List結(jié)構(gòu)通過GSON庫轉(zhuǎn)換為JSON的方法示例2016-06-06Hibernate基于ThreadLocal管理Session過程解析
這篇文章主要介紹了Hibernate基于ThreadLocal管理Session過程解析,文中通過示例代碼介紹的非常詳細(xì),對大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值,需要的朋友可以參考下2020-10-10SpringBoot集成ElasticSearch(ES)實(shí)現(xiàn)全文搜索功能
Elasticsearch是一個(gè)開源的分布式搜索和分析引擎,它被設(shè)計(jì)用于處理大規(guī)模數(shù)據(jù)集,它提供了一個(gè)分布式多用戶能力的全文搜索引擎,本文將給大家介紹SpringBoot集成ElasticSearch(ES)實(shí)現(xiàn)全文搜索功能,需要的朋友可以參考下2024-02-02Java實(shí)現(xiàn)字符串倒序輸出的四種方法匯總
這篇文章主要介紹了Java實(shí)現(xiàn)字符串倒序輸出的四種方法匯總,具有很好的參考價(jià)值,希望對大家有所幫助。如有錯(cuò)誤或未考慮完全的地方,望不吝賜教2023-06-06