報(bào)警了蹄梢，系統(tǒng)異常飆升到3000+傍睹。經(jīng)排查竟然是rpc接口超時(shí)了搀菩，但是服務(wù)提供方反饋系統(tǒng)1ms就返回了螃成，為什么consumer端耗時(shí)是13000+ms港令，網(wǎng)絡(luò)異常情況下的耗時(shí)也不可能這么長(zhǎng)呀，不科學(xué)~瞅了一下機(jī)器監(jiān)控锈颗，what顷霹，機(jī)器竟然一直都在full gc。立馬去機(jī)器上查看情況：用戶(hù)線程已全線暫停击吱，gc線程cpu占用率居高不下淋淀，rpc線程池堵塞。那是什么導(dǎo)致的頻繁的full gc呢覆醇？
GC日志
我們先去看看gc日志朵纷，看看是什么導(dǎo)致的頻繁full gc：
2018-10-12T12:17:35.328+0800: [Full GC (Metadata GC Threshold) 2018-10-12T12:17:35.328+0800: [CMS2018-10-12T12:17:36.998+0800: [CMS-concurrent-mark: 1.617/1.682 secs] [Times: user=1.70 sys=0.01, real=1.69 secs]
(concurrent mode failure): 1080352K->1080354K(2355200K), 5.0626275 secs] 1081703K->1080354K(3737600K), [Metaspace: 206712K->206712K(1282048K)], 5.0640593 secs] [Times: user=5.09 sys=0.00, real=5.06 secs]
2018-10-12T12:17:40.393+0800: [Full GC (Last ditch collection) 2018-10-12T12:17:40.393+0800: [CMS: 1080354K->1080354K(2355200K), 3.4270709 secs] 1080354K->1080354K(3737600K), [Metaspace: 206712K->206712K(1282048K)], 3.4283073 secs] [Times: user=3.33 sys=0.11, real=3.43 secs]
2018-10-12T12:17:43.833+0800: [Full GC (Metadata GC Threshold) 2018-10-12T12:17:43.834+0800: [CMS: 1080354K->1080354K(2355200K), 3.4584908 secs] 1080361K->1080354K(3737600K), [Metaspace: 206712K->206712K(1282048K)], 3.4598680 secs] [Times: user=3.48 sys=0.00, real=3.46 secs]
從gc日志能夠看出來(lái)炭臭，導(dǎo)致該full gc的原因是達(dá)到了metaspace的gc閾值，這里先解釋下Metadata GC Threshold和Last ditch collection：
-
Metadata GC Threshold：metaspace空間不能滿(mǎn)足分配時(shí)觸發(fā)袍辞，這個(gè)階段不會(huì)清理軟引用鞋仍； -
Last ditch collection：經(jīng)過(guò)Metadata GC Threshold觸發(fā)的full gc后還是不能滿(mǎn)足條件，這個(gè)時(shí)候會(huì)觸發(fā)再一次的gc cause為Last ditch collection的full gc搅吁，這次full gc會(huì)清理掉軟引用威创。
看到這里大家可能會(huì)有疑問(wèn)了，為啥你的gc日志打印了gc的原因呢谎懦？其實(shí)從jdk8開(kāi)始肚豺，gc日志會(huì)默認(rèn)打印gc cause，如果是jdk8之前的版本界拦，可以通過(guò)JVM參數(shù)-XX:+PrintGCCause來(lái)打印gc cause吸申。另外多嘴一句，觀察gc日志其實(shí)可以發(fā)現(xiàn)大量的gc都是因?yàn)?code>Allocation Failure觸發(fā)的享甸，大家不要以為這個(gè)不正常截碴，其實(shí)大部分的gc都是因?yàn)閮?nèi)存分配失敗觸發(fā)的。
言歸正傳蛉威，既然是metaspace區(qū)域使用達(dá)到gc閾值從而觸發(fā)的full gc隐岛，那我們來(lái)看一下MetaspaceSize和MaxMetaspaceSize的設(shè)置值：都是256m，但從gc日志也可以看出來(lái)（206712K->206712K）瓷翻，發(fā)生full gc時(shí)metaspace才使用206m，并沒(méi)有達(dá)到閾值呀割坠，這就奇怪了齐帚，沒(méi)有達(dá)到閾值為什么還觸發(fā)了full gc呢？看了下JVM各個(gè)區(qū)域使用情況彼哼，發(fā)現(xiàn)metaspace committed內(nèi)存達(dá)到262144k对妄，大于gc的閾值256m，基本上到這里敢朱，也就明確原因了：metaspace的內(nèi)存碎片化導(dǎo)致了該悲劇的誕生剪菱。
導(dǎo)致Full GC的罪魁禍?zhǔn)?/h3>
對(duì)于metaspace內(nèi)存碎片化，有一個(gè)場(chǎng)景倒是可以滿(mǎn)足拴签，那就是創(chuàng)建了大量的classloader孝常。目前就一次出現(xiàn)full gc時(shí)間點(diǎn)的heap dump不太能看出來(lái)問(wèn)題，我通過(guò)增加jvm參數(shù)-XX:+HeapDumpBeforeFullGC蚓哩、-XX:+HeapDumpAfterFullGC分別在發(fā)生full gc前后做heap dump构灸。通過(guò)對(duì)比分析full gc發(fā)生前后的heap dump，發(fā)現(xiàn)在full gc前創(chuàng)建了大量的sun.reflect.DelegatingClassLoader岸梨，full gc后該classloader也減少了約1000個(gè)喜颁。
到這里稠氮，導(dǎo)致該問(wèn)題的罪魁禍?zhǔn)拙驼业搅耍蔷褪?code>sun.reflect.DelegatingClassLoader半开，但是為什么類(lèi)加載器過(guò)多就會(huì)導(dǎo)致內(nèi)存碎片化呢隔披？在類(lèi)加載器第一次加載類(lèi)的時(shí)候，都會(huì)在metaspace區(qū)域?yàn)槠浞峙湟粔K內(nèi)存寂拆，并且每個(gè)類(lèi)加載器的內(nèi)存區(qū)域都是獨(dú)立的奢米，當(dāng)然咯，一定要走出這個(gè)誤區(qū)漓库，類(lèi)加載器的內(nèi)存分配跟加載類(lèi)的數(shù)量是沒(méi)有關(guān)系的恃慧，即使類(lèi)加載器只加載一個(gè)類(lèi)，也是會(huì)在metaspace為其分配一塊內(nèi)存的渺蒿。當(dāng)出現(xiàn)頻繁的類(lèi)加載器創(chuàng)建的時(shí)候痢士，這個(gè)時(shí)候就可能會(huì)出現(xiàn)metaspace內(nèi)存使用率低，但是committed的內(nèi)存已經(jīng)達(dá)到了full gc的閾值從而觸發(fā)了full gc茂装。
寫(xiě)在最后的
一次簡(jiǎn)單的線上小問(wèn)題分析怠蹂，如果項(xiàng)目有大流量入口頻繁使用反射就一定要注意了，警惕大流量帶來(lái)的大量反射類(lèi)加載器創(chuàng)建引發(fā)的頻繁full gc少态。
