相信大家在系統(tǒng)學(xué)習(xí)jvm的時候都會有遇到過這樣的問題，散落的jvm知識點(diǎn)知道很多，但是真正在線上環(huán)境遇到一些莫名其妙的gc異常時候卻無從下手去分析。

關(guān)于這塊的苦我也表示能夠理解，之前光是JVM相關(guān)的八股文就整理了許多，但是經(jīng)常是不知道如何在實(shí)戰(zhàn)中使用。最近也嘗試在模擬一些案例來訓(xùn)練自己的JVM相關(guān)知識，本文特意記錄下這段調(diào)優(yōu)經(jīng)歷。

Java應(yīng)用的GC評估

可能大多數(shù)程序員在開發(fā)完某個需求之后，往線上環(huán)境一丟，然后就基本不怎么關(guān)注后續(xù)的變化了。但是是否有考慮過，這些新引入的代碼會對原有系統(tǒng)造成的影響呢？下邊我們通過一段實(shí)戰(zhàn)來帶各位讀者較好地去深入理解這個過程。

模擬場景

有一個應(yīng)用程序（暫且稱呼為moment服務(wù)）準(zhǔn)備在小程序上開展社交動態(tài)推送功能，大概就是每次用戶刷新頁面時候便會按照一定規(guī)則推送出20條用戶動態(tài)數(shù)據(jù)。由于該產(chǎn)品的c端用戶數(shù)量比較多，于是便在上線該產(chǎn)品之前進(jìn)行了相應(yīng)的壓測，判斷該功能的承載能力。

在壓測開始的初期，接口響應(yīng)速度都還可以，但是漸漸地開始加壓的時候，發(fā)現(xiàn)程序出現(xiàn)了OOM。經(jīng)過排查后，排除數(shù)據(jù)庫層的問題。于是開始懷疑是否是Java應(yīng)用內(nèi)部出現(xiàn)了異常。

應(yīng)用的啟動參數(shù)：

java
 -Xmx1512m
 -Xms1512m
 -Xmn1024m 
 -XX:+UseConcMarkSweepGC 
 -XX:+UseParNewGC  
 -XX:+HeapDumpOnOutOfMemoryError  
 -XX:+PrintGCDetails 
 -XX:+PrintGCTimeStamps 
 -Xloggc:log/gc.log 
 -jar qiyu-framework-demo-jvm.jar

單節(jié)點(diǎn)壓測，壓力測試10w次請求，1000并發(fā)。使用ab工具進(jìn)行壓力測試：

ab -n100000 -c1000 http://localhost:8080/user/batch-query

jstat 查看GC，每隔5秒打印一次，持續(xù)20次

jstat -gc 5673 5000 20

經(jīng)過一段時間的施壓，在施壓的持續(xù)了1分鐘之后，YGC的頻率讓人感覺著實(shí)有些高。通常一個健康的系統(tǒng)ygc應(yīng)該是20-30min左右一次，full gc可能是好幾周才一次。

通過jstat可以看出，年輕代的gc會比較頻繁，并且停頓時間嚴(yán)重影響了正常的業(yè)務(wù)使用。為了得到更加精準(zhǔn)的數(shù)據(jù)，我嘗試將gc日志放到GCeasy工具上進(jìn)行可視化分析：

這是一款非常不錯的gc日志分析工具

https://www.gceasy.io/

GC日志的可視化分析

首先是JVM內(nèi)存中的占用分析，很清晰地可以看出，年輕代的內(nèi)存和老年代的內(nèi)存幾乎占滿，元空間基本沒有變動過。

然后是整個系統(tǒng)的GC耗時分析：

從整體來看，大部分的GC耗時都是在0-100ms內(nèi)，極端情況下的GC耗時可能會達(dá)到700ms。

接下來是看看GC回收對堆內(nèi)存整體的一個影響。觀測發(fā)現(xiàn)，基本每次GC都能夠回收達(dá)改200mb左右的內(nèi)存。

再繼續(xù)分析，可以發(fā)現(xiàn)CMS回收器在回收的各個階段中所消耗的時間：初始標(biāo)記，并發(fā)標(biāo)記，修正標(biāo)記，并發(fā)清除

除了單純分析GC回收的耗時之外，這款工具還有個非常贊的功能，可以幫助我們分析這段時間內(nèi)，該Java程序產(chǎn)生對象的速率：

可以發(fā)現(xiàn)，一秒大概要產(chǎn)生445mb的對象，大概一秒就會有2.5mb對象晉升到老年代。

內(nèi)存逃逸分析沒有發(fā)現(xiàn)異常記錄。

通過對這份報告分析完畢之后，我的第一直覺告訴我，年輕代不足，需要對年輕代內(nèi)存進(jìn)行增加。但是仔細(xì)觀察下，產(chǎn)生對象的速率竟然高達(dá)445mb/s，這感覺非常不正常啊，極度懷疑是程序內(nèi)部存在大對象的情況。

于是嘗試使用jvisualVM這款工具進(jìn)行深入分析，通過對CPU樣例的監(jiān)控，發(fā)現(xiàn)了一些異常信息：

似乎這個方法對CPU的消耗比較高，接著是內(nèi)存的一個監(jiān)控：

此時大概可以定位出異常方法所在的位置了，接下來便是對系統(tǒng)內(nèi)部的業(yè)務(wù)代碼進(jìn)行分析了。

最后排查結(jié)果發(fā)現(xiàn)，其實(shí)是系統(tǒng)內(nèi)部的一個方法調(diào)用，加載了5k個User對象到內(nèi)存中做計(jì)算，而每個User對象里存放了一個大小為1kb的byte數(shù)組。大概的代碼邏輯為：

于是便需要從業(yè)務(wù)層面對該方法進(jìn)行優(yōu)化，例如調(diào)小5k這個數(shù)值，同時對User對象內(nèi)的byte數(shù)組進(jìn)行過濾（因?yàn)閷?shí)際使用不到這個字段）。

調(diào)整后發(fā)現(xiàn)GC的頻率降低了許多，比較正常。

頻繁GC的排查思路總結(jié)

通過本次實(shí)驗(yàn)，大概能夠梳理出Java應(yīng)用在出現(xiàn)頻繁GC的時候該如何去排查問題點(diǎn)，大致為：

• 通過結(jié)合工具分析GC日志，排查是否有大量對象頻繁創(chuàng)建所導(dǎo)致。

• 通過對GC日志的分析能夠排查出年輕代和老年代的GC頻率。

• 通過對CPU占用比較高的線程，或者內(nèi)存占用比較高的對象進(jìn)行分析，定位異常點(diǎn)。

• 最后結(jié)合業(yè)務(wù)系統(tǒng)代碼進(jìn)行分析，精確定位異常點(diǎn)。

以上就是JVM完全解讀之GC日志記錄分析的詳細(xì)內(nèi)容，更多關(guān)于JVM解讀GC日志記錄分析的資料請關(guān)注腳本之家其它相關(guān)文章！