YGC問題排查，又讓我漲姿勢了！

在高并發(fā)下，Java程序的GC問題屬于很典型的一類問題，帶來的影響往往會被進一步放大。不管是「GC頻率過快」還是「GC耗時太長」，由于GC期間都存在Stop The World問題，因此很容易導(dǎo)致服務(wù)超時，引發(fā)性能問題。

我們團隊負(fù)責(zé)的廣告系統(tǒng)承接了比較大的C端流量，平峰期間的請求量基本達到了上千QPS，過去也遇到了很多次GC相關(guān)的線上問題。

5月份的這篇文章我介紹了一個Full GC過于頻繁的案例，并且針對JVM的堆內(nèi)存結(jié)構(gòu)和GC原理進行了系統(tǒng)性的總結(jié)。

這篇文章，我再分享一個更棘手的Young GC耗時過長的線上案例，同時會整理下YGC相關(guān)的知識點，希望讓你有所收獲。內(nèi)容分成以下2個部分：

• 從一次YGC耗時過長的案例說起

• YGC的相關(guān)知識點總結(jié)

01 從一次YGC耗時過長的案例說起

今年4月份，我們的廣告服務(wù)在新版本上線后，收到了大量的服務(wù)超時告警，通過下面的監(jiān)控圖可以看到：超時量突然大面積增加，1分鐘內(nèi)甚至達到了上千次接口超時。下面詳細(xì)介紹下該問題的排查過程。

1.?檢查監(jiān)控

收到告警后，我們第一時間查看了監(jiān)控系統(tǒng)，立馬發(fā)現(xiàn)了YoungGC耗時過長的異常。我們的程序大概在21點50左右上線，通過下圖可以看出：在上線之前，YGC基本幾十毫秒內(nèi)完成，而上線后YGC耗時明顯變長，最長甚至達到了3秒多。

由于YGC期間程序會Stop The World，而我們上游系統(tǒng)設(shè)置的服務(wù)超時時間都在幾百毫秒，因此推斷：是因為YGC耗時過長引發(fā)了服務(wù)大面積超時。

按照GC問題的常規(guī)排查流程，我們立刻摘掉了一個節(jié)點，然后通過以下命令dump了堆內(nèi)存文件用來保留現(xiàn)場。

jmap?-dump:format=b,file=heap pid

最后對線上服務(wù)做了回滾處理，回滾后服務(wù)立馬恢復(fù)了正常，接下來就是長達1天的問題排查和修復(fù)過程。

2. 確認(rèn)JVM配置

用下面的命令，我們再次檢查了JVM的參數(shù)

ps aux | grep "applicationName=adsearch"

-Xms4g -Xmx4g -Xmn2g -Xss1024K?

-XX:ParallelGCThreads=5?

-XX:+UseConcMarkSweepGC?

-XX:+UseParNewGC?

-XX:+UseCMSCompactAtFullCollection?

-XX:CMSInitiatingOccupancyFraction=80

可以看到堆內(nèi)存為4G，新生代和老年代均為2G，新生代采用ParNew收集器。

再通過命令 jmap?-heap pid?查到：新生代的Eden區(qū)為1.6G，S0和S1區(qū)均為0.2G。

本次上線并未修改JVM相關(guān)的任何參數(shù)，同時我們服務(wù)的請求量基本和往常持平。因此猜測：此問題大概率和上線的代碼相關(guān)。

3. 檢查代碼

再回到Y(jié)GC的原理來思考這個問題，一次YGC的過程主要包括以下兩個步驟：

1、從GC Root掃描對象，對存活對象進行標(biāo)注

2、將存活對象復(fù)制到S1區(qū)或者晉升到Old區(qū)

根據(jù)下面的監(jiān)控圖可以看出：正常情況下，Survivor區(qū)的使用率一直維持在很低的水平（大概30M左右），但是上線后，Survivor區(qū)的使用率開始波動，最多的時候快占滿0.2G了。而且，YGC耗時和Survivor區(qū)的使用率基本成正相關(guān)。因此，我們推測：應(yīng)該是長生命周期的對象越來越多，導(dǎo)致標(biāo)注和復(fù)制過程的耗時增加。

再回到服務(wù)的整體表現(xiàn)：上游流量并沒有出現(xiàn)明顯變化，正常情況下，核心接口的響應(yīng)時間也基本在200ms以內(nèi)，YGC的頻率大概每8秒進行1次。

很顯然，對于局部變量來說，在每次YGC后就能夠馬上被回收了。那為什么還會有如此多的對象在YGC后存活下來呢？

我們進一步將懷疑對象鎖定在：程序的全局變量或者類靜態(tài)變量上。但是diff了本次上線的代碼，我們并未發(fā)現(xiàn)代碼中有引入此類變量。

4. 對dump的堆內(nèi)存文件進行分析

代碼排查沒有進展后，我們開始從堆內(nèi)存文件中尋找線索，使用MAT工具導(dǎo)入了第1步dump出來的堆文件后，然后通過Dominator Tree視圖查看到了當(dāng)前堆中的所有大對象。

立馬發(fā)現(xiàn)NewOldMappingService這個類所占的空間很大，通過代碼定位到：這個類位于第三方的client包中，由我們公司的商品團隊提供，用于實現(xiàn)新舊類目轉(zhuǎn)換（最近商品團隊在對類目體系進行改造，為了兼容舊業(yè)務(wù)，需要進行新舊類目映射）。

進一步查看代碼，發(fā)現(xiàn)這個類中存在大量的靜態(tài)HashMap，用于緩存新舊類目轉(zhuǎn)換時需要用到的各種數(shù)據(jù)，以減少RPC調(diào)用，提高轉(zhuǎn)換性能。

原本以為，非常接近問題的真相了，但是深入排查發(fā)現(xiàn)：這個類的所有靜態(tài)變量全部在類加載時就初始化完數(shù)據(jù)了，雖然會占到100多M的內(nèi)存，但是之后基本不會再新增數(shù)據(jù)。并且，這個類早在3月份就上線使用了，client包的版本也一直沒變過。

經(jīng)過上面種種分析，這個類的靜態(tài)HashMap會一直存活，經(jīng)過多輪YGC后，最終晉升到老年代中，它不應(yīng)該是YGC持續(xù)耗時過長的原因。因此，我們暫時排除了這個可疑點。

5. 分析YGC處理Reference的耗時

團隊對于YGC問題的排查經(jīng)驗很少，不知道再往下該如何分析了。基本掃光了網(wǎng)上可查到的所有案例，發(fā)現(xiàn)原因集中在這兩類上：

1、對存活對象標(biāo)注時間過長：比如重載了Object類的Finalize方法，導(dǎo)致標(biāo)注Final Reference耗時過長；或者String.intern方法使用不當(dāng)，導(dǎo)致YGC掃描StringTable時間過長。

2、長周期對象積累過多：比如本地緩存使用不當(dāng)，積累了太多存活對象；或者鎖競爭嚴(yán)重導(dǎo)致線程阻塞，局部變量的生命周期變長。

針對第1類問題，可以通過以下參數(shù)顯示GC處理Reference的耗時-XX:+PrintReferenceGC。添加此參數(shù)后，可以看到不同類型的 reference 處理耗時都很短，因此又排除了此項因素。

6. 再回到長周期對象進行分析

再往后，我們添加了各種GC參數(shù)試圖尋找線索都沒有結(jié)果，似乎要黔驢技窮，沒有思路了。綜合監(jiān)控和種種分析來看：應(yīng)該只有長周期對象才會引發(fā)我們這個問題。

折騰了好幾個小時，最終峰回路轉(zhuǎn)，一個小伙伴重新從MAT堆內(nèi)存中找到了第二個懷疑點。

從上面的截圖可以看到：大對象中排在第3位的ConfigService類進入了我們的視野，該類的一個ArrayList變量中竟然包含了270W個對象，而且大部分都是相同的元素。

ConfigService這個類在第三方Apollo的包中，不過源代碼被公司架構(gòu)部進行了二次改造，通過代碼可以看出：問題出在了第11行，每次調(diào)用getConfig方法時都會往List中添加元素，并且未做去重處理。

我們的廣告服務(wù)在apollo中存儲了大量的廣告策略配置，而且大部分請求都會調(diào)用ConfigService的getConfig方法來獲取配置，因此會不斷地往靜態(tài)變量namespaces中添加新對象，從而引發(fā)此問題。

至此，整個問題終于水落石出了。這個BUG是因為架構(gòu)部在對apollo client包進行定制化開發(fā)時不小心引入的，很顯然沒有經(jīng)過仔細(xì)測試，并且剛好在我們上線前一天發(fā)布到了中央倉庫中，而公司基礎(chǔ)組件庫的版本是通過super-pom方式統(tǒng)一維護的，業(yè)務(wù)無感知。

7.?解決方案

為了快速驗證YGC耗時過長是因為此問題導(dǎo)致的，我們在一臺服務(wù)器上直接用舊版本的apollo client 包進行了替換，然后重啟了服務(wù)，觀察了將近20分鐘，YGC恢復(fù)正常。

最后，我們通知架構(gòu)部修復(fù)BUG，重新發(fā)布了super-pom，徹底解決了這個問題。

02?YGC的相關(guān)知識點總結(jié)

通過上面這個案例，可以看到Y(jié)GC問題其實比較難排查。相比FGC或者OOM，YGC的日志很簡單，只知道新生代內(nèi)存的變化和耗時，同時dump出來的堆內(nèi)存必須要仔細(xì)排查才行。

另外，如果不清楚YGC的流程，排查起來會更加困難。這里，我對YGC相關(guān)的知識點再做下梳理，方便大家更全面的理解YGC。

1. 5個問題重新認(rèn)識新生代

YGC 在新生代中進行，首先要清楚新生代的堆結(jié)構(gòu)劃分。新生代分為Eden區(qū)和兩個Survivor區(qū)，其中Eden:from:to = 8:1:1 (比例可以通過參數(shù) –XX:SurvivorRatio 來設(shè)定 )，這是最基本的認(rèn)識。

為什么會有新生代？

如果不分代，所有對象全部在一個區(qū)域，每次GC都需要對全堆進行掃描，存在效率問題。分代后，可分別控制回收頻率，并采用不同的回收算法，確保GC性能全局最優(yōu)。

為什么新生代會采用復(fù)制算法？

新生代的對象朝生夕死，大約90%的新建對象可以被很快回收，復(fù)制算法成本低，同時還能保證空間沒有碎片。雖然標(biāo)記整理算法也可以保證沒有碎片，但是由于新生代要清理的對象數(shù)量很大，將存活的對象整理到待清理對象之前，需要大量的移動操作，時間復(fù)雜度比復(fù)制算法高。

為什么新生代需要兩個Survivor區(qū)？

為了節(jié)省空間考慮，如果采用傳統(tǒng)的復(fù)制算法，只有一個Survivor區(qū)，則Survivor區(qū)大小需要等于Eden區(qū)大小，此時空間消耗是8 * 2，而兩塊Survivor可以保持新對象始終在Eden區(qū)創(chuàng)建，存活對象在Survivor之間轉(zhuǎn)移即可，空間消耗是8+1+1，明顯后者的空間利用率更高。

新生代的實際可用空間是多少？

YGC后，總有一塊Survivor區(qū)是空閑的，因此新生代的可用內(nèi)存空間是90%。在YGC的log中或者通過 jmap -heap pid 命令查看新生代的空間時，如果發(fā)現(xiàn)capacity只有90%，不要覺得奇怪。

Eden區(qū)是如何加速內(nèi)存分配的？

HotSpot虛擬機使用了兩種技術(shù)來加快內(nèi)存分配。分別是bump-the-pointer和TLAB（Thread Local Allocation Buffers）。

由于Eden區(qū)是連續(xù)的，因此bump-the-pointer在對象創(chuàng)建時，只需要檢查最后一個對象后面是否有足夠的內(nèi)存即可，從而加快內(nèi)存分配速度。

TLAB技術(shù)是對于多線程而言的，在Eden中為每個線程分配一塊區(qū)域，減少內(nèi)存分配時的鎖沖突，加快內(nèi)存分配速度，提升吞吐量。

2. 新生代的4種回收器

SerialGC（串行回收器），最古老的一種，單線程執(zhí)行，適合單CPU場景。

ParNew（并行回收器），將串行回收器多線程化，適合多CPU場景，需要搭配老年代CMS回收器一起使用。

ParallelGC（并行回收器），和ParNew不同點在于它關(guān)注吞吐量，可設(shè)置期望的停頓時間，它在工作時會自動調(diào)整堆大小和其他參數(shù)。

G1（Garage-First回收器），JDK 9及以后版本的默認(rèn)回收器，兼顧新生代和老年代，將堆拆成一系列Region，不要求內(nèi)存塊連續(xù)，新生代仍然是并行收集。

上述回收器均采用復(fù)制算法，都是獨占式的，執(zhí)行期間都會Stop The World.

3. YGC的觸發(fā)時機

當(dāng)Eden區(qū)空間不足時，就會觸發(fā)YGC。結(jié)合新生代對象的內(nèi)存分配看下詳細(xì)過程：

1、新對象會先嘗試在棧上分配，如果不行則嘗試在TLAB分配，否則再看是否滿足大對象條件要在老年代分配，最后才考慮在Eden區(qū)申請空間。

2、如果Eden區(qū)沒有合適的空間，則觸發(fā)YGC。

3、YGC時，對Eden區(qū)和From Survivor區(qū)的存活對象進行處理，如果滿足動態(tài)年齡判斷的條件或者To Survivor區(qū)空間不夠則直接進入老年代，如果老年代空間也不夠了，則會發(fā)生promotion failed，觸發(fā)老年代的回收。否則將存活對象復(fù)制到To Survivor區(qū)。

4、此時Eden區(qū)和From Survivor區(qū)的剩余對象均為垃圾對象，可直接抹掉回收。

此外，老年代如果采用的是CMS回收器，為了減少CMS Remark階段的耗時，也有可能會觸發(fā)一次YGC，這里不作展開。

4. YGC的執(zhí)行過程

YGC采用的復(fù)制算法，主要分成以下兩個步驟：

1、查找GC Roots，將其引用的對象拷貝到S1區(qū)

2、遞歸遍歷第1步的對象，拷貝其引用的對象到S1區(qū)或者晉升到Old區(qū)

上述整個過程都是需要暫停業(yè)務(wù)線程的（STW），不過ParNew等新生代回收器可以多線程并行執(zhí)行，提高處理效率。

YGC通過可達性分析算法，從GC Root（可達對象的起點）開始向下搜索，標(biāo)記出當(dāng)前存活的對象，那么剩下未被標(biāo)記的對象就是需要回收的對象。

可作為YGC時GC Root的對象包括以下幾種：

1、虛擬機棧中引用的對象

2、方法區(qū)中靜態(tài)屬性、常量引用的對象

3、本地方法棧中引用的對象

4、被Synchronized鎖持有的對象

5、記錄當(dāng)前被加載類的SystemDictionary

6、記錄字符串常量引用的StringTable

7、存在跨代引用的對象

8、和GC Root處于同一CardTable的對象

其中1-3是大家容易想到的，而4-8很容易被忽視，卻極有可能是分析YGC問題時的線索入口。

另外需要注意的是，針對下圖中跨代引用的情況，老年代的對象A也必須作為GC Root的一部分，但是如果每次YGC時都去掃描老年代，肯定存在效率問題。在HotSpot JVM，引入卡表（Card Table）來對跨代引用的標(biāo)記進行加速。

Card Table，簡單理解是一種空間換時間的思路，因為存在跨代引用的對象大概占比不到1%，因此可將堆空間劃分成大小為512字節(jié)的卡頁，如果卡頁中有一個對象存在跨代引用，則可以用1個字節(jié)來標(biāo)識該卡頁是dirty狀態(tài)，卡頁狀態(tài)進一步通過寫屏障技術(shù)進行維護。

遍歷完GC Roots后，便能夠找出第一批存活的對象，然后將其拷貝到S1區(qū)。接下來，就是一個遞歸查找和拷貝存活對象的過程。

S1區(qū)為了方便維護內(nèi)存區(qū)域，引入了兩個指針變量：_saved_mark_word和_top，其中_saved_mark_word表示當(dāng)前遍歷對象的位置，_top表示當(dāng)前可分配內(nèi)存的位置，很顯然，_saved_mark_word到_top之間的對象都是已拷貝但未掃描的對象。

如上圖所示，每次掃描完一個對象，_saved_mark_word會往前移動，期間如果有新對象也會拷貝到S1區(qū)，_top也會往前移動，直到_saved_mark_word追上_top，說明S1區(qū)所有對象都已經(jīng)遍歷完成。

有一個細(xì)節(jié)點需要注意的是：拷貝對象的目標(biāo)空間不一定是S1區(qū)，也可能是老年代。如果一個對象的年齡（經(jīng)歷的YGC次數(shù)）滿足動態(tài)年齡判定條件便直接晉升到老年代中。對象的年齡保存在Java對象頭的mark word數(shù)據(jù)結(jié)構(gòu)中（如果大家對Java并發(fā)鎖熟悉，肯定了解這個數(shù)據(jù)結(jié)構(gòu)，不熟悉的建議查閱資料了解下，這里不做展開）。

最后的話

這篇文章通過線上案例分析并結(jié)合原理講解，詳細(xì)介紹了YGC的相關(guān)知識。從YGC實戰(zhàn)角度出發(fā)，再簡單總結(jié)一下：

1、首先要清楚YGC的執(zhí)行原理，比如年輕代的堆內(nèi)存結(jié)構(gòu)、Eden區(qū)的內(nèi)存分配機制、GC Roots掃描、對象拷貝過程等。

2、YGC的核心步驟是標(biāo)注和復(fù)制，絕部分YGC問題都集中在這兩步，因此可以結(jié)合YGC日志和堆內(nèi)存變化情況逐一排查，同時dump的堆內(nèi)存文件需要仔細(xì)分析。

有道無術(shù)，術(shù)可成；有術(shù)無道，止于術(shù)

歡迎大家關(guān)注Java之道公眾號

好文章，我在看??