Categories
程式開發

YGC問題排查,又讓我漲姿勢了!


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

我們團隊負責的廣告系統承接了比較大的C端流量,平峰期間的請求量基本達到了上千QPS,過去也遇到了很多次GC相關的線上問題。

這篇文章,我再分享一個更棘手的Young GC耗時過長的線上案例,同時會整理下YGC相關的知識點,希望讓你有所收穫。 內容分成以下2個部分:

從一次YGC耗時過長的案例說起YGC的相關知識點總結

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

今年4月份,我們的廣告服務在新版本上線後,收到了大量的服務超時告警,通過下面的監控圖可以看到:超時量突然大面積增加,1分鐘內甚至達到了上千次接口超時。 下面詳細介紹下該問題的排查過程。

YGC問題排查,又讓我漲姿勢了! 1

檢查監控

收到告警後,我們第一時間查看了監控系統,立馬發現了YoungGC耗時過長的異常。 我們的程序大概在21點50左右上線,通過下圖可以看出:在上線之前,YGC基本幾十毫秒內完成,而上線後YGC耗時明顯變長,最長甚至達到了3秒多。

YGC問題排查,又讓我漲姿勢了! 2

由於YGC期間程序會Stop The World,而我們上游系統設置的服務超時時間都在幾百毫秒,因此推斷:是因為YGC耗時過長引發了服務大面積超時。

按照GC問題的常規排查流程,我們立刻摘掉了一個節點,然後通過以下命令dump了堆內存文件用來保留現場。

jmap -dump:format = b,file =堆pid

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

確認JVM配置

用下面的命令,我們再次檢查了JVM的參數

ps aux | grep "applicationName=adsearch"
-Xms4g -Xmx4g -Xmn2g -Xss1024K
-XX:ParallelGCThreads=5
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
-XX:+UseCMSCompactAtFullCollection
-XX:CMSInitiatingOccupancyFraction=80

可以看到堆內存為4G,新生代和老年代均為2G,新生代採用ParNew收集器。

再通過命令jmap -heap pid 查到:新生代的Eden區為1.6G,S0和S1區均為0.2G。

本次上線並未修改JVM相關的任何參數,同時我們服務的請求量基本和往常持平。 因此猜測:此問題大概率和上線的代碼相關。

檢查代碼

再回到YGC的原理來思考這個問題,一次YGC的過程主要包括以下兩個步驟:

1、從GC Root掃描對象,對存活對象進行標註

2、將存活對象複製到S1區或者晉升到Old區

根據下面的監控圖可以看出:正常情況下,Survivor區的使用率一直維持在很低的水平(大概30M左右),但是上線後,Survivor區的使用率開始波動,最多的時候快佔滿0.2 G了。 而且,YGC耗時和Survivor區的使用率基本成正相關。 因此,我們推測:應該是長生命週期的對象越來越多,導致標註和復製過程的耗時增加。

YGC問題排查,又讓我漲姿勢了! 3

再回到服務的整體表現:上游流量並沒有出現明顯變化,正常情況下,核心接口的響應時間也基本在200ms以內,YGC的頻率大概每8秒進行1次。

很顯然,對於局部變量來說,在每次YGC後就能夠馬上被回收了。 那為什麼還會有如此多的對像在YGC後存活下來呢?

我們進一步將懷疑對象鎖定在:程序的全局變量或者類靜態變量上。 但是diff了本次上線的代碼,我們並未發現代碼中有引入此類變量。

對dump的堆內存文件進行分析

代碼排查沒有進展後,我們開始從堆內存文件中尋找線索,使用MAT工具導入了第1步dump出來的堆文件後,然後通過Dominator Tree視圖查看到了當前堆中的所有大對象。

YGC問題排查,又讓我漲姿勢了! 4

立馬發現NewOldMappingService這個類所佔的空間很大,通過代碼定位到:這個類位於第三方的client包中,由我們公司的商品團隊提供,用於實現新舊類目轉換(最近商品團隊在對類目體系進行改造,為了兼容舊業務,需要進行新舊類目映射)。

進一步查看代碼,發現這個類中存在大量的靜態HashMap,用於緩存新舊類目轉換時需要用到的各種數據,以減少RPC調用,提高轉換性能。

YGC問題排查,又讓我漲姿勢了! 5

原本以為,非常接近問題的真相了,但是深入排查發現:這個類的所有靜態變量全部在類加載時就初始化完數據了,雖然會占到100多M的內存,但是之後基本不會再新增數據。 並且,這個類早在3月份就上線使用了,client包的版本也一直沒變過。

經過上面種種分析,這個類的靜態HashMap會一直存活,經過多輪YGC後,最終晉升到老年代中,它不應該是YGC持續耗時過長的原因。 因此,我們暫時排除了這個可疑點。

分析YGC處理Reference的耗時

團隊對於YGC問題的排查經驗很少,不知道再往下該如何分析了。 基本掃光了網上可查到的所有案例,發現原因集中在這兩類上:

1、對存活對象標註時間過長:比如重載了Object類的Finalize方法,導致標註Final Reference耗時過長;或者String.intern方法使用不當,導致YGC掃描StringTable時間過長。

2、長周期對象積累過多:比如本地緩存使用不當,積累了太多存活對象;或者鎖競爭嚴重導致線程阻塞,局部變量的生命週期變長。

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

YGC問題排查,又讓我漲姿勢了! 6

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

再往後,我們添加了各種GC參數試圖尋找線索都沒有結果,似乎要黔驢技窮,沒有思路了。 綜合監控和種種分析來看:應該只有長周期對象才會引發我們這個問題。

折騰了好幾個小時,最終峰迴路轉,一個小伙伴重新從MAT堆內存中找到了第二個懷疑點。

YGC問題排查,又讓我漲姿勢了! 7

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

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

YGC問題排查,又讓我漲姿勢了! 8

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

至此,整個問題終於水落石出了。 這個BUG是因為架構部在對apollo client包進行定制化開發時不小心引入的,很顯然沒有經過仔細測試,並且剛好在我們上線前一天發佈到了中央倉庫中,而公司基礎組件庫的版本是通過super-pom方式統一維護的,業務無感知。

解決方案

為了快速驗證YGC耗時過長是因為此問題導致的,我們在一台服務器上直接用舊版本的apollo client 包進行了替換,然後重啟了服務,觀察了將近20分鐘,YGC恢復正常。

最後,我們通知架構部修復BUG,重新發布了super-pom,徹底解決了這個問題。

02 YGC的相關知識點總結

通過上面這個案例,可以看到YGC問​​題其實比較難排查。 相比FGC或者OOM,YGC的日誌很簡單,只知道新生代內存的變化和耗時,同時dump出來的堆內存必須要仔細排查才行。

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

YGC的相關知識點總結

5個問題重新認識新生代

YGC問題排查,又讓我漲姿勢了! 9

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

為什麼會有新生代?

如果不分代,所有對象全部在一個區域,每次GC都需要對全堆進行掃描,存在效率問題。 分代後,可分別控制回收頻率,並採用不同的回收算法,確保GC性能全局最優。

為什麼新生代會採用複制算法?

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

為什麼新生代需要兩個Survivor區?

為了節省空間考慮,如果採用傳統的複制算法,只有一個Survivor區,則Survivor區大小需要等於Eden區大小,此時空間消耗是8 * 2,而兩塊Survivor可以保持新對象始終在Eden區創建,存活對像在Survivor之間轉移即可,空間消耗是8+1+1,明顯後者的空間利用率更高。

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

YGC後,總有一塊Survivor區是空閒的,因此新生代的可用內存空間是90%。 在YGC的log中或者通過jmap -heap pid 命令查看新生代的空間時,如果發現capacity只有90%,不要覺得奇怪。

Eden區是如何加速內存分配的?

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

由於Eden區是連續的,因此bump-the-pointer在對象創建時,只需要檢查最後一個對像後面是否有足夠的內存即可,從而加快內存分配速度。

TLAB技術是對於多線程而言的,在Eden中為每個線程分配一塊區域,減少內存分配時的鎖衝突,加快內存分配速度,提升吞吐量。

新生代的4種回收器

YGC問題排查,又讓我漲姿勢了! 10

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

ParNew(並行回收器),將串行回收器多線程化,適合多CPU場景,需要搭配老年代CMS回收器一起使用。

ParallelGC(並行回收器),和ParNew不同點在於它關注吞吐量,可設置期望的停頓時間,它在工作時會自動調整堆大小和其他參數。

G1(Garage-First回收器),JDK 9及以後版本的默認回收器,兼顧新生代和老年代,將堆拆成一系列Region,不要求內存塊連續,新生代仍然是並行收集。

上述回收器均採用複制算法,都是獨占式的,執行期間都會Stop The World.

YGC的觸發時機

當Eden區空間不足時,就會觸發YGC。 結合新生代對象的內存分配看下詳細過程:

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

2、如果Eden區沒有合適的空間,則觸發YGC。

3、YGC時,對Eden區和From Survivor區的存活對象進行處理,如果滿足動態年齡判斷的條件或者To Survivor區空間不夠則直接進入老年代,如果老年代空間也不夠了,則會發生promotion failed ,觸發老年代的回收。 否則將存活對象複製到To Survivor區。

4、此時Eden區和From Survivor區的剩餘對象均為垃圾對象,可直接抹掉回收。

此外,老年代如果採用的是CMS回收器,為了減少CMS Remark階段的耗時,也有可能會觸發一次YGC,這裡不作展開。

YGC的執行過程

YGC採用的複制算法,主要分成以下兩個步驟:

1、查找GC Roots,將其引用的對象拷貝到S1區

2、遞歸遍歷第1步的對象,拷貝其引用的對像到S1區或者晉升到Old區

上述整個過程都是需要暫停業務線程的(STW),不過ParNew等新生代回收器可以多線程並行執行,提高處理效率。

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

YGC問題排查,又讓我漲姿勢了! 11

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

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

2、方法區中靜態屬性、常量引用的對象

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

4、被Synchronized鎖持有的對象

5、記錄當前被加載類的SystemDictionary

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

7、存在跨代引用的對象

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

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

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

YGC問題排查,又讓我漲姿勢了! 12

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

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

S1區為了方便維護內存區域,引入了兩個指針變量:_saved_mark_word和_top,其中_saved_mark_word表示當前遍歷對象的位置,_top表示當前可分配內存的位置,很顯然,_saved_mark_word到_top之間的對象都是已拷貝但未掃描的對象。

YGC問題排查,又讓我漲姿勢了! 13

貝到S1區,_top也會往前移動,直到_saved_mark_word追上_top,說明S1區所有對像都已經遍歷完成。

有一個細節點需要注意的是:拷貝對象的目標空間不一定是S1區,也可能是老年代。 如果一個對象的年齡(經歷的YGC次數)滿足動態年齡判定條件便直接晉升到老年代中。 對象的年齡保存在Java對像頭的mark word數據結構中(如果大家對Java並發鎖熟悉,肯定了解這個數據結構,不熟悉的建議查閱資料了解下,這裡不做展開)。

最後的話

這篇文章通過線上案例分析並結合原理講解,詳細介紹了YGC的相關知識。 從YGC實戰角度出發,再簡單總結一下:

1、首先要清楚YGC的執行原理,比如年輕代的堆內存結構、Eden區的內存分配機制、GC Roots掃描、對象拷貝過程等。

2、YGC的核心步驟是標註和復制,絕部分YGC問題都集中在這兩步,因此可以結合YGC日誌和堆內存變化情況逐一排查,同時dump的堆內存文件需要仔細分析。

看完三件事❤️

如果你覺得這篇內容對你還蠻有幫助,我想邀請你幫我三個小忙:

點贊,轉發,有你們的『點贊和評論』,才是我創造的動力。 關注公眾號『 java爛豬皮』,不定期分享原創知識。 同時可以期待後續文章ing🚀

YGC問題排查,又讓我漲姿勢了! 14

文章出處:https://club.perfma.com/article/1661497