背景

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

因?yàn)椴l(fā)不高，所以線(xiàn)上一共部署了2個(gè)tomcat進(jìn)行負(fù)載均衡。

這個(gè)tomcat剛上生產(chǎn)線(xiàn)，運(yùn)行挺平穩(wěn)。大概過(guò)了大概1天后，運(yùn)維同事反映2個(gè)tomcat節(jié)點(diǎn)均掛了。無(wú)法接受新的請(qǐng)求了。CPU飆升到100%。

排查過(guò)程一

接手這個(gè)問(wèn)題后。首先大致看了下當(dāng)時(shí)的JVM監(jiān)控。

CPU的確居高不下

FULL GC從大概這個(gè)小時(shí)的22分開(kāi)始，就開(kāi)始頻繁的進(jìn)行FULL GC，一分鐘最高能進(jìn)行10次FULL GC

minor GC每分鐘竟然接近60次，相當(dāng)于每秒鐘都有minor GC

從老年代的使用情況也反應(yīng)了這一點(diǎn)

隨機(jī)對(duì)線(xiàn)上應(yīng)用分析了線(xiàn)程的cpu占用情況，用top -H -p pid命令

可以看到前面4條線(xiàn)程，都占用了大量的CPU資源。隨即進(jìn)行了jstack，把線(xiàn)程棧信息拉下來(lái)，用前面4條線(xiàn)程的ID轉(zhuǎn)換16進(jìn)制后進(jìn)行搜索。發(fā)現(xiàn)并沒(méi)有找到相應(yīng)的線(xiàn)程。所以判斷為不是應(yīng)用線(xiàn)程導(dǎo)致的。

第一個(gè)結(jié)論

通過(guò)對(duì)當(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)被快速的填滿(mǎn)。導(dǎo)致了FULL GC。同時(shí)FULL GC不停的發(fā)生，導(dǎo)致了大量的STW，CPU被FULL GC線(xiàn)程占據(jù)，出現(xiàn)CPU飆高，應(yīng)用線(xiàn)程由于STW再加上CPU過(guò)高，大量線(xiàn)程被阻塞。同時(shí)新的請(qǐng)求又不停的進(jìn)來(lái)，最終tomcat的線(xiàn)程池被占滿(mǎn)，再也無(wú)法響應(yīng)新的請(qǐng)求了。這個(gè)雪球終于還是滾大了。

分析完了案發(fā)現(xiàn)場(chǎng)。要解決的問(wèn)題變成了：

是什么原因?qū)е吕夏甏豢焖俚奶顫M(mǎn)？

拉了下當(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ū)的分配情況如下：

所以開(kāi)始懷疑是JVM參數(shù)設(shè)置的有問(wèn)題導(dǎo)致的老年代被快速的占滿(mǎn)。

但是其實(shí)這參數(shù)已經(jīng)是之前優(yōu)化后的結(jié)果了，eden區(qū)設(shè)置的挺大，大部分我們的方法產(chǎn)生的對(duì)象都是朝生夕死的對(duì)象，應(yīng)該大部分都在年輕代會(huì)清理了。存活的對(duì)象才會(huì)進(jìn)入survivor區(qū)。到達(dá)年齡或者觸發(fā)了進(jìn)入老年代的條件后才會(huì)進(jìn)入老年代。基本上老年代里的對(duì)象大部分應(yīng)該是一直存活的對(duì)象。比如static修飾的對(duì)象啊，一直被引用的 緩存啊，spring容器中的bean等等。

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

但是一次minor GC應(yīng)該超過(guò)90%的對(duì)象都是無(wú)引用對(duì)象，只有少部分的對(duì)象才是存活的。而且這些個(gè)服務(wù)的并發(fā)一直不高，為什么一次minor GC后有那么大量的數(shù)據(jù)會(huì)存活呢。

隨即看了下當(dāng)時(shí)的jmap -histo 命令產(chǎn)生的文件

發(fā)現(xiàn)String這個(gè)這個(gè)對(duì)象的示例竟然有9000多w個(gè)，占用堆超過(guò)2G。這肯定有問(wèn)題。但是tomcat里有8個(gè)應(yīng)用 ，不可能通過(guò)分析代碼來(lái)定位到。還是要從JVM入手來(lái)反推。

第二次結(jié)論

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

基本判斷是，JVM參數(shù)應(yīng)該沒(méi)有問(wèn)題，很可能問(wèn)題出在應(yīng)用本身不斷產(chǎn)生無(wú)法被回收的對(duì)象上面。但是我暫時(shí)定位不到具體的代碼位置。

排查過(guò)程二

第二天，又看了下當(dāng)時(shí)的JVM監(jiān)控，發(fā)現(xiàn)有這么一個(gè)監(jiān)控?cái)?shù)據(jù)當(dāng)時(shí)漏看了

這是FULL GC之后，老年代的使用率?？梢钥吹健ULL GC后，老年代依然占據(jù)80%多的空間。full gc就根本清理不掉老年代的對(duì)象。這說(shuō)明，老年代里的這些對(duì)象都是被程序引用著的。所以清理不掉。但是平穩(wěn)的時(shí)候，老年代一直維持著大概300M的堆。從這個(gè)小時(shí)的22分開(kāi)始，之后就狂飆到接近2G。這肯定不正常。更加印證了我前面一個(gè)觀點(diǎn)。這是因?yàn)閼?yīng)用程序產(chǎn)生的無(wú)法回收的對(duì)象導(dǎo)致的。

但是當(dāng)時(shí)我并沒(méi)有dump下來(lái)jvm的堆。所以只能等再次重現(xiàn)問(wèn)題。

終于，在晚上9點(diǎn)多，這個(gè)問(wèn)題又重現(xiàn)了，熟悉的配方，熟悉的味道。

直接jmap -dump，經(jīng)過(guò)漫長(zhǎng)的等待，產(chǎn)生了4.2G的一個(gè)堆快照文件dump.hprof，經(jīng)過(guò)壓縮，得到一個(gè)466M的tar.gz文件

然后download到本地，解壓。

運(yùn)行堆分析工具JProfile，裝載這個(gè)dump.hprof文件。

然后查看堆當(dāng)時(shí)的所有類(lèi)占比大小的信息

發(fā)現(xiàn)導(dǎo)致堆溢出，就是這個(gè)String對(duì)象，和之前Jmap得出的結(jié)果一樣，超過(guò)了2個(gè)G，并且無(wú)法被回收

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

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

這個(gè)ArrayList是被一個(gè)線(xiàn)程棧引用著，而這個(gè)線(xiàn)程棧信息里面，可以直接定位到相應(yīng)的服務(wù)，相應(yīng)的類(lèi)。具體服務(wù)是Media這個(gè)微服務(wù)。

看來(lái)已經(jīng)要逼近真相了！

第三次結(jié)論

本次大量頻繁的FULL GC是因?yàn)閼?yīng)用程序產(chǎn)生了大量無(wú)法被回收的數(shù)據(jù)，最終進(jìn)入老年代，最終把老年代撐滿(mǎn)了導(dǎo)致的。具體的定位通過(guò)JVM的dump文件已經(jīng)分析出，指向了Media這個(gè)服務(wù)的ImageCombineUtils.getComputedLines這個(gè)方法，是什么會(huì)產(chǎn)生尚不知道，需要具體分析代碼。

最后

得知了具體的代碼位置， 直接進(jìn)去看。經(jīng)過(guò)小伙伴提醒，發(fā)現(xiàn)這個(gè)代碼有一個(gè)問(wèn)題。

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

以下是模擬出來(lái)的結(jié)果，可以看到，才運(yùn)行了一會(huì)，這個(gè)ArrayList就產(chǎn)生了322w個(gè)對(duì)象，且大部分Stirng對(duì)象都是空值。

至此，水落石出。

最終結(jié)論

因?yàn)镸edia這個(gè)微服務(wù)的程序在某一些特殊場(chǎng)景下的一段程序?qū)е铝怂姥h(huán)，產(chǎn)生了一個(gè)超大的ArrayList。導(dǎo)致了年輕代的快速被填滿(mǎn)，然后觸發(fā)了大對(duì)象直接進(jìn)老年代的機(jī)制，直接往老年代里面放。老年代被放滿(mǎn)之后。觸發(fā)FULL GC。但是這些ArrayList被GC ROOT根引用著，無(wú)法回收。導(dǎo)致回收不掉。老年代依舊滿(mǎn)的，隨機(jī)馬上又觸發(fā)FULL GC。同時(shí)因?yàn)槔夏甏鸁o(wú)法被回收，導(dǎo)致minor GC也沒(méi)法清理，不停的進(jìn)行minor GC。大量GC導(dǎo)致STW和CPU飆升，導(dǎo)致應(yīng)用線(xiàn)程卡頓，阻塞，直至最后整個(gè)服務(wù)無(wú)法接受請(qǐng)求。

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

最新評(píng)論