[[399235]]

本文轉(zhuǎn)載自微信公眾號(hào)「咖啡拿鐵」，作者咖啡拿鐵。轉(zhuǎn)載本文請(qǐng)聯(lián)系咖啡拿鐵公眾號(hào)。

 背景

gc問(wèn)題一直是一個(gè)很難排查的問(wèn)題，但是他又是一個(gè)經(jīng)常在我們開(kāi)發(fā)業(yè)務(wù)中出現(xiàn)的。這不，最近在我的項(xiàng)目中就出現(xiàn)了一個(gè)比較奇葩的gc問(wèn)題，排查過(guò)程比較繁瑣，所以在這里分享一下這個(gè)整個(gè)排查過(guò)程，希望對(duì)大家有一定的幫助

排查過(guò)程

確定GC出問(wèn)題

在某一天的上午突然出現(xiàn)了報(bào)警，發(fā)現(xiàn)是ZK斷開(kāi)了鏈接，

從圖上看我們這個(gè)錯(cuò)誤是間斷性的出現(xiàn)，最開(kāi)始以為是zk出現(xiàn)了問(wèn)題，后來(lái)經(jīng)過(guò)排查其他服務(wù)的zk并沒(méi)有出現(xiàn)任何問(wèn)題。所以就懷疑是內(nèi)部的代碼出現(xiàn)問(wèn)題導(dǎo)致的，研究之后發(fā)現(xiàn)是zk出現(xiàn)了心跳超時(shí)情況才導(dǎo)致的斷開(kāi)鏈接，所以就懷疑了兩種情況：

• 網(wǎng)絡(luò)有抖動(dòng)
• 機(jī)器間歇性卡死

如果網(wǎng)絡(luò)有抖動(dòng)的話的確是會(huì)出現(xiàn)偶發(fā)性超時(shí)，但是很明顯，其他所有的服務(wù)都沒(méi)問(wèn)題，應(yīng)該不是抖動(dòng)導(dǎo)致。所以機(jī)器應(yīng)該是間歇性的一個(gè)卡死，一般出現(xiàn)這個(gè)情況首當(dāng)其沖的就是我們CPU被打滿了，導(dǎo)致機(jī)器卡死，發(fā)現(xiàn)CPU并無(wú)問(wèn)題，然后就是我們的gc帶來(lái)的STW,會(huì)導(dǎo)致我們的jvm進(jìn)程卡頓。

觀察之后的確是young gc很慢，導(dǎo)致我們的JVM發(fā)生了GC卡頓，所以出現(xiàn)了這個(gè)現(xiàn)象。

排查原因

GC出現(xiàn)問(wèn)題一般來(lái)說(shuō)兩大法寶可以解決大部分問(wèn)題：

• GC日志
• dump文件

出現(xiàn)問(wèn)題之后我立馬打開(kāi)了GC日志，截圖如下：

可以發(fā)現(xiàn)我們的young gc已經(jīng)達(dá)到2.7s了，大家知道我們的young gc是全程STW的，那就意味著每次gc就會(huì)卡頓2.7s，那么zk超時(shí)斷開(kāi)鏈接也就符合正常了。再看了下這個(gè)gc收集情況，每次也能完全收集。在日志中很明顯在root scanning的時(shí)間比較長(zhǎng)，當(dāng)時(shí)對(duì)這個(gè)階段不太熟悉(后面會(huì)繼續(xù)講)，所以一直也不明白為什么這樣，在網(wǎng)上各種搜索，也沒(méi)有結(jié)論。

這個(gè)時(shí)候我在why哥公眾號(hào)讀到了一篇文章：https://mp.weixin.qq.com/s/KDUccdLALWdjNBrFjVR74Q, 建議大家可以閱讀一下這篇文章，這個(gè)文章中主要談到了我們jvm的一個(gè)優(yōu)化，大家都知道我們進(jìn)入STW的時(shí)候是需要一個(gè)安全點(diǎn)才可以的，而詢問(wèn)是否進(jìn)入到安全點(diǎn)是需要耗費(fèi)資源的，所以jvm在做jit優(yōu)化的時(shí)候會(huì)講counted loop 也就是計(jì)數(shù)循環(huán)優(yōu)化成整個(gè)循環(huán)結(jié)束之后再進(jìn)入安全點(diǎn)，在小米的技術(shù)文章中也提到了相關(guān)的問(wèn)題:《HBase實(shí)戰(zhàn)：記一次Safepoint導(dǎo)致長(zhǎng)時(shí)間STW的踩坑之旅》 。

看完這兩個(gè)文章之后，我突然想到了我們的代碼也是counted loop的形式，所以就懷疑有可能也是這個(gè)問(wèn)題導(dǎo)致的，馬上進(jìn)行代碼優(yōu)化，將for(int i = 0; i< n; i++) 中的int 換成了long，就可以避免這種jit的優(yōu)化，馬上興沖沖的將其上線，結(jié)果過(guò)了一天之后依然存在這個(gè)問(wèn)題，此時(shí)人都快崩潰，搞了半天原來(lái)不是這個(gè)問(wèn)題導(dǎo)致的。

定位問(wèn)題

對(duì)于G1之前只是看了些原理相關(guān)的，但是此時(shí)原理相關(guān)的東西好像在這里基本沒(méi)啥用，所以我決定系統(tǒng)性的學(xué)習(xí)一下，這里我選擇的是《jvm G1源碼分析和調(diào)優(yōu)》這本書(shū)，在讀到5.4節(jié)的時(shí)候：

發(fā)現(xiàn)有兩個(gè)之前沒(méi)有見(jiàn)過(guò)的參數(shù)，一個(gè)是G1LogLevel,一個(gè)是UnlockExperimentalVMOptions，從解釋說(shuō)明上來(lái)看配置了之后能獲取到更加詳細(xì)的YGC日志，于是加上了這個(gè)參數(shù)然后繼續(xù)觀察，日志格式太長(zhǎng)，只截取了部分日志信息，有興趣的可以下來(lái)自己打印一下：

可以發(fā)現(xiàn)在SystemDictionary Roots階段是比較慢的，但是這個(gè)又是啥玩意呢?在書(shū)里面是沒(méi)有任何介紹的，于是又進(jìn)行大量谷歌，終于是找到了一篇你假笨寫(xiě)的一篇文章：JVM源碼分析之自定義類加載器如何拉長(zhǎng)YGC，強(qiáng)烈推薦大家讀完這篇文章。

好了最后我來(lái)盤(pán)一盤(pán)到底為什么會(huì)出現(xiàn)gc慢的問(wèn)題呢?我們這個(gè)定時(shí)任務(wù)是一個(gè)定時(shí)查詢微信退款信息的，微信的退款信息需要解析XML,就有如下代碼:

而我們的罪魁禍?zhǔn)灼鋵?shí)就在這個(gè)new XStream這個(gè)方法中，我們的默認(rèn)構(gòu)造方法會(huì)調(diào)用下面的這個(gè)構(gòu)造方法：

需要注意的是我們每次創(chuàng)建一個(gè)XStream都會(huì)新創(chuàng)建一個(gè)ClassLoader，先解釋一下ClassLoader，這里直接引用你假笨的一段話：

這里著重要說(shuō)的兩個(gè)概念是初始類加載器和定義類加載器。舉個(gè)栗子說(shuō)吧，AClassLoader->BClassLoader->CClassLoader，表示AClassLoader在加載類的時(shí)候會(huì)委托BClassLoader類加載器來(lái)加載，BClassLoader加載類的時(shí)候會(huì)委托CClassLoader來(lái)加載，假如我們使用AClassLoader來(lái)加載X這個(gè)類，而X這個(gè)類最終是被CClassLoader來(lái)加載的，那么我們稱CClassLoader為X類的定義類加載器，而AClassLoader為X類的初始類加載器，JVM在加載某個(gè)類的時(shí)候?qū)ClassLoader和CClassLoader進(jìn)行記錄，記錄的數(shù)據(jù)結(jié)構(gòu)是一個(gè)叫做SystemDictionary的hashtable，其key是根據(jù)ClassLoader對(duì)象和類名算出來(lái)的hash值(其實(shí)是一個(gè)entry，可以根據(jù)這個(gè)hash值找到具體的index位置，然后構(gòu)建一個(gè)包含kalssName和classloader對(duì)象的entry放到map里)，而value是真正的由定義類加載器加載的Klass對(duì)象，因?yàn)槌跏碱惣虞d器和定義類加載器是不同的classloader，因此算出來(lái)的hash值也是不同的，因此在SystemDictionary里會(huì)有多項(xiàng)值的value都是指向同一個(gè)Klass對(duì)象。

我們把這個(gè)放到我們的場(chǎng)景來(lái)看就是下面這個(gè)情況：

由于我們每次請(qǐng)求都會(huì)新創(chuàng)建一個(gè)Xstream對(duì)象，從而也會(huì)新創(chuàng)建一個(gè)ClassLoader，由于我們的ClassLoader的key是根據(jù)每個(gè)對(duì)象來(lái)算出來(lái)的hash值，如果每次都新創(chuàng)建，自然hash值不一樣，從而導(dǎo)致我們有很多ClassLoader指向XStream這個(gè)class。為什么SystemDictionary的大小會(huì)影響我們GC時(shí)間呢?

想象一下這么個(gè)情況，我們加載了一個(gè)類，然后構(gòu)建了一個(gè)對(duì)象(這個(gè)對(duì)象在eden里構(gòu)建)當(dāng)一個(gè)屬性設(shè)置到這個(gè)類(static變量)里，如果gc發(fā)生的時(shí)候，這個(gè)對(duì)象是不是要被找出來(lái)標(biāo)活才行，那么自然而然我們加載的類肯定是我們一項(xiàng)重要的gc root，這樣SystemDictionary就成為了gc過(guò)程中的被掃描對(duì)象了。

我們的class信息是被分配在哪里的呢?在java7的話是在永久代，在java8就來(lái)到了元數(shù)據(jù)空間也就是我們的堆上，所以我們的young gc的時(shí)候是不會(huì)回收我們的class信息的，那么我們?cè)趺唇鉀Q這個(gè)問(wèn)題呢?

• java7: 在G1垃圾收集器中，只有在進(jìn)行full GC的時(shí)候，永久代才會(huì)被回收，這一過(guò)程是stop-the-world的。當(dāng)不做Full GC的時(shí)候，G1運(yùn)行是最優(yōu)化的。只有當(dāng)永久代滿了或者應(yīng)用分配內(nèi)存的速度超過(guò)了G1回收垃圾的速度的時(shí)候，G1才會(huì)觸發(fā)Full GC。在CMS垃圾收集器中，我們可以使用-XX:+CMSClassUnloadingEnabled在CMS concurrent cycle中回收集永久代。在G1里面沒(méi)有對(duì)應(yīng)的設(shè)置。G1只有在stop-the-world的Full GC的時(shí)候，才會(huì)回收永久代。我們可以根據(jù)應(yīng)用的需要，設(shè)置PermSize和MaxPermSize參數(shù)來(lái)調(diào)優(yōu)永久代的大小。
• java8：提供了四個(gè)參數(shù)-XX:MetaspaceSize，-XX:MaxMetaspaceSize，-XX:MinMetaspaceFreeRatio，-XX:MaxMetaspaceFreeRatio用來(lái)控制元空間的大小，當(dāng)超過(guò)比例或者大小的時(shí)候就會(huì)進(jìn)行收集。

但是我們這個(gè)問(wèn)題不應(yīng)該通過(guò)垃圾收集去解決，而是應(yīng)該從根源上去解決，那就是不能使用默認(rèn)的XStream構(gòu)造函數(shù),而是需要使用固定ClassLoader的構(gòu)造函數(shù)。

經(jīng)過(guò)修改之后上線，經(jīng)過(guò)觀察，沒(méi)有出現(xiàn)慢GC的現(xiàn)象。

最后

經(jīng)過(guò)這次排查的經(jīng)驗(yàn)來(lái)看，遇到GC問(wèn)題尤其是那種比較不常見(jiàn)的，真的是非常難搞，你可能需要對(duì)這個(gè)問(wèn)題進(jìn)行系統(tǒng)的學(xué)習(xí)，以及大量的查找資料才能找到原因，我在排查這個(gè)問(wèn)題的時(shí)候掉了不少頭發(fā)。在這里記錄一下這個(gè)經(jīng)驗(yàn)，希望對(duì)大家以后的一些排查能有幫助。