前言

JVM的GC機制讓Java程序員省去了自己垃圾回收的煩惱，大大提高了生產(chǎn)效率。但是正因為JVM垃圾回收機制足夠優(yōu)秀，導致很多Java程序員對JVM這個黑盒了解甚少，很多人沒有去了解它，很多人也沒機會去了解它。然而要想成為一名優(yōu)秀的Java程序員，了解JVM和它的GC機制，寫出JVM GC機制更喜歡的代碼，是必須要掌握的一門技術；

這篇文章我主要說一下如何初步診斷JVM的GC是否正常，重點講解診斷GC，而不是JVM基礎和GC基礎。所以看這篇文章，需要對JVM有一定的了解，比如常用的垃圾回收器，堆的模型以及分代等，如果你還對JVM一無所知，那么請先花點時間看一下周志明的<<深入理解Java虛擬機>>，重點關注"第二部分 自動內(nèi)存管理機制"。

GC概念糾正

對GC機制有一定了解的同學都知道，GC主要有YoungGC，OldGC，F(xiàn)ullGC（還有G1中獨有的Mixed GC，收集整個young區(qū)以及部分Old區(qū)，提及的概率相對少很多，本篇文章不打算講解），在講解如何判斷這三種GC是否正常之前，先再次解釋一下這三種GC，因為很多很多的同學對OldGC和FullGC有誤解；

• YoungGC：應該是最沒有歧義的一種GC了，只是有些地方稱之為Minor GC，或者簡稱YGC，都是沒有問題的；
• OldGC：截止Java發(fā)展到現(xiàn)在JDK9為止，只單獨回收Old區(qū)的只有CMS GC，且是CMS的concurrent collection模式（CMS有兩種模式，請參考寒泉子的文章JVM源碼分析之SystemGC完全解讀）。G1出來之前，CMS GC也是OLTP系統(tǒng)最常用的；而JDK8以前默認的垃圾回收器ParallelOldGC，在Old滿后觸發(fā)的是FullGC；
• FullGC：有些地方稱之為Major GC，Major GC通常是跟FullGC是等價的，都是收集整個GC堆。但因為HotSpot VM發(fā)展了這么多年，外界對各種名詞的解讀已經(jīng)完全混亂了，當有人說“Major GC”的時候一定要問清楚他想要指的是上面的FullGC還是OldGC（參考R大的Major GC和Full GC的區(qū)別）。對這個GC的誤解最大，尤其最常用的ParNew+CMS組合，很多人誤解FullGC可能是受到jstat結(jié)果的影響。如果配置了CMS垃圾回收器，那么jstat中的FGC并不表示就一定發(fā)生了FullGC，很有可能是發(fā)生了CMS GC，而且每發(fā)生一次CMS GC，jstat中的FGC就會+2（因為CMS GC時初始化標記和重新標記都會STW，所以FGC的值會+2，可以通過讓JVM按照預期GC提供的代碼驗證）；事實上，F(xiàn)ullGC的觸發(fā)條件比較苛刻，判斷是否發(fā)生了FullGC最好通過GC日志，所以強烈建議生產(chǎn)環(huán)境開啟GC日志，它的價值遠大于它對性能的影響；

FullGC觸發(fā)條件

• 沒有配置 -XX:+DisableExplicitGC情況下System.gc()可能會觸發(fā)FullGC；
• Promotion failed；
• concurrent mode failure；
• Metaspace Space使用達到MaxMetaspace閾值；
• 執(zhí)行jmap -histo:live或者jmap -dump:live

說明：統(tǒng)計發(fā)現(xiàn)之前YGC的平均晉升大小比目前old gen剩余的空間大，觸發(fā)CMS GC；Metaspace Space使用達到Metaspace閾值是觸發(fā)CMS GC；

執(zhí)行jmap -histo:live觸發(fā)FullGC的gc log如下--關鍵詞Heap Inspection Initiated GC，通過jstat -gccause pid 2s的LGCC列也能看到同樣的關鍵詞：
[Full GC (Heap Inspection Initiated GC) 2018-03-29T15:26:51.070+0800: 51.754: [CMS: 82418K->55047K(131072K), 0.3246618 secs] 138712K->55047K(249088K), [Metaspace: 60713K->60713K(1103872K)], 0.3249927 secs] [Times: user=0.32 sys=0.01, real=0.32 secs]

執(zhí)行jmap -dump:live觸發(fā)FullGC的gc log如下--關鍵詞Heap Dump Initiated GC，通過jstat -gccause pid 2s的LGCC列也能看到同樣的關鍵詞：
[Full GC (Heap Dump Initiated GC) 2018-03-29T15:31:53.825+0800: 354.510: [CMS2018-03-29T15:31:53.825+0800: 354.510: [CMS: 55047K->56358K(131072K), 0.3116120 secs] 84678K->56358K(249088K), [Metaspace: 62153K->62153K(1105920K)], 0.3119138 secs] [Times: user=0.31 sys=0.00, real=0.31 secs]

健康的GC

診斷GC的第一步，當然是知道你的JVM的GC是否正常。那么GC是否正常，首先就要看YoungGC，OldGC和FullGC是否正常；無論是定位YoungGC，OldGC，F(xiàn)ullGC哪一種GC，判斷其是否正常主要從兩個維度：GC頻率和STW時間；要得到這兩個維度的值，我們需要知道JVM運行了多久，執(zhí)行如下命令即可：

ps -p pid -o etime

運行結(jié)果參考，下面的運行結(jié)果表示這個JVM運行了24天16個小時37分35秒，如果JVM運行時間沒有超過一天，執(zhí)行結(jié)果是這樣"16:37:35"：

[afei@ubuntu ~]$ ps -p 11864 -o etime
    ELAPSED
24-16:37:35

那么怎樣的GC頻率和STW時間才算是正常呢？這里以我以前開發(fā)過的一個讀多寫少的dubbo服務作為參考，該dubbo服務基本情況如下：

• 日調(diào)用量1億+次，接口平均響應時間6ms以內(nèi)
• 4個JVM
• 每個JVM設置Xmx和Xms為4G，Xmn1G
• 4核CPU&8G內(nèi)存服務器
• JDK7
• AWS云虛擬機

GC情況如下圖所示：

GC統(tǒng)計信息

根據(jù)這張圖輸出數(shù)據(jù)，可以得到如下一些信息：

1. JVM運行總時間為6944534秒（day*24*3600+hour*3600+minutes*60+second）
2. YoungGC頻率為4s/次（建議通過GC日志中兩次YoungGC時間差計算得出）
3. CMS GC頻率為9天/次（FGC=18，即最多發(fā)生9次CMS GC，所以CMS GC頻率為80/9≈9天/次）
4. 每次YoungGC的時間為6ms（通過YGCT/YGC計算得出）
5. FullGC幾乎沒有（JVM總計運行80天，F(xiàn)GC才18，即使是18次FullGC，F(xiàn)ullGC頻率也才4.5天/次，更何況實際上FGC=18肯定包含了若干次CMS GC）

根據(jù)上面的GC情況，給個可參考的健康的GC狀況：

1. YoungGC頻率5秒/次；
2. CMS GC頻率不超過1天/次；
3. 每次YoungGC的時間不超過20ms；
4. FullGC頻率盡可能完全杜絕；

說明：G1&CMS時，F(xiàn)ullGC回收算法會退化成Serial+SerialOld，即單線程串行回收，且完全STW，影響很大且STW時間完全不可預估，所以FullGC頻率盡可能完全杜絕。另外，可參考的健康的GC狀況這里只是參考，不是絕對，不能說這個GC狀況有多好，起碼橫向?qū)Ρ葮I(yè)務規(guī)模，以及服務器規(guī)格，你的GC狀況不能與上面的dubbo服務有明顯的差距；

了解GC健康時候的樣子，那么接下來把脈你的JVM GC，一一講解YoungGC，OldGC，F(xiàn)ullGC?？纯词怯屑苍陔砝恚€是在肌膚，還是在腸胃，甚至已經(jīng)在骨髓病入膏肓了；

YoungGC

YoungGC是最頻繁發(fā)生的，發(fā)生的概率是OldGC和FullGC的的10倍，100倍，甚至1000倍。同時YoungGC的問題也是最難定位的。這里給出YoungGC定位三板斧（都是踩過坑）：

1. 查看服務器SWAP&IO情況，如果服務器發(fā)生SWAP，會嚴重拖慢GC效率，導致STW時間異常長，拉長接口響應時間，從而影響用戶體驗（推薦神器sar，yum install sysstat即可，想了解該命令，請搜索"linux sar"）；
2. 查看StringTable情況（請參考探索StringTable提升YGC性能）
3. 排查每次YoungGC后幸存對象大?。↗VM模型基于分配的對象朝生夕死的假設設計，如果每次YoungGC后幸存對象較大，可能存在問題）
4. 未完待續(xù)……（可以在留言中分享你的IDEA）

排查每次YoungGC后幸存對象大小可通過GC日志中發(fā)生YoungGC的日志計算得出：
例如下面兩行GC日志，第二次YoungGC相比第一次YoungGC，整個Heap并沒有增長（都是647K），說明回收效果非常理想：
2017-11-28T10:22:57.332+0800: [GC (Allocation Failure) 2017-11-28T10:22:57.332+0800: [ParNew: 7974K->0K(9216K), 0.0016636 secs] 7974K->647K(19456K), 0.0016865 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2017-11-28T10:22:57.334+0800: [GC (Allocation Failure) 2017-11-28T10:22:57.334+0800: [ParNew: 7318K->0K(9216K), 0.0002355 secs] 7965K->647K(19456K), 0.0002742 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
再看下面兩行GC日志，第二次YoungGC相比第一次YoungGC，整個Heap從2707K增長到了4743K，說明回收效果一般：
2017-11-28T10:26:41.890+0800: [GC (Allocation Failure) 2017-11-28T10:26:41.890+0800: [ParNew: 7783K->657K(9216K), 0.0013021 secs] 7783K->2707K(19456K), 0.0013416 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2017-11-28T10:26:41.892+0800: [GC (Allocation Failure) 2017-11-28T10:26:41.892+0800: [ParNew: 7982K->0K(9216K), 0.0018354 secs] 10032K->4743K(19456K), 0.0018536 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

可參考的健康的GC狀況給出建議YoungGC頻率5秒/次，經(jīng)驗值3秒~6秒/次都是比較合理的YoungGC頻率；

• 如果YoungGC頻率遠高于這個值，例如20秒/次，30秒/次，甚至60秒/次，這種情況下，JVM相當空閑，處于基本上無事可做的狀態(tài)。建議縮容，減少服務器浪費；
• 如果YoungGC頻率遠低于這個值，例如1秒/次，甚至1秒/好多次，這種情況下，JVM相當繁忙，建議follow如下步驟進行初步癥斷：

1. 檢查Young區(qū)，Young區(qū)在整個堆占比在25%~40%比較合理，如果Young區(qū)太小，建議擴大Xmn。
2. 檢查SurvivorRatio，保持默認值8即可，Eden:S0:S1=8:1:1是一個比較合理的值；

OldGC

上面已經(jīng)提及：到目前為止HotSpot JVM虛擬機只單獨回收Old區(qū)的只有CMS GC。觸發(fā)CMS GC條件比較簡單，JVM有一個線程定時掃描Old區(qū)，時間間隔可以通過參數(shù)-XX:CMSWaitDuration=2000設置（默認就是2s），如果發(fā)現(xiàn)Old區(qū)占比超過參數(shù)-XX:CMSInitiatingOccupancyFraction=75設定值（CMS條件下默認為68%），就會觸發(fā)CMS GC。建議搭配-XX:+UseCMSInitiatingOccupancyOnly參數(shù)使用，簡化CMS GC觸發(fā)條件，只有在Old區(qū)占比滿足條件的情況下才觸發(fā)CMS GC；

可參考的健康的GC狀況給出建議CMS GC頻率不超過1天/次，如果CMS GC頻率1天發(fā)生數(shù)次，甚至上10次，說明你的GC情況病的不輕了，建議follow如下步驟進行初步癥斷：

1. 檢查Young區(qū)與Old區(qū)比值，盡量留60%以上的堆空間給Old區(qū)；
2. 通過jstat查看每次YoungGC后晉升到Old區(qū)對象占比，如果發(fā)現(xiàn)每次YoungGC后Old區(qū)漲好幾個百分點，甚至上10個點，說明有大對象，建議dump（jmap -dump:format=b,file=app.bin pid）后用MAT分析；
3. 如果不停的CMS GC，Old區(qū)降不下去，建議先執(zhí)行jmap -histo pid | head -n20 查看TOP20對象分布，如果除了[B和[C，即byte[]和char[]，還有其他占比較大的實例，如下圖所示中TOP1的Object數(shù)組，也可通過dump后用MAT分析問題；
4. 如果TOP20對象中有StandartSession對象，排查你的業(yè)務代碼中有沒有顯示使用HttpSession，例如String id = request.getSession().getId();，一般的OLTP系統(tǒng)幾乎不會使用HttpSession，且HttpSession的的生命周期很長，會加快Old區(qū)增長速度；

異常的大對象.png

FullGC

• 如果配置CMS，由于CMS采用標記清理算法，會有內(nèi)存碎片的問題，推薦配置一個查看內(nèi)存碎片程度的JVM參數(shù)PrintFLSStatistics。
• 如果配置ParallelOldGC，那么每次Old區(qū)滿后，會觸發(fā)FullGC，如果FullGC頻率過高，也可以通過上面OldGC段落提及的排查方法；
• 如果沒有配置-XX:+DisableExplicitGC，即沒有屏蔽System.gc()觸發(fā)FullGC，那么可以通過排查GC日志中有System字樣判斷是否System.gc()觸發(fā)（日志樣本：558082.666: [Full GC (System) [PSYoungGen: 368K->0K(42112K)] [PSOldGen: 36485K->32282K(87424K)] 36853K->32282K(129536K) [PSPermGen: 34270K->34252K(196608K)], 0.2997530 secs] ）；或者通過jstat -gccause pid 2s pid判定，LGCC表示最近一次GC原因，如果為"System.gc"，表示由System.gc()觸發(fā)，GCC表示當前GC原因，如果當前沒有GC，那么就是No GC：

 [afei@aliyun~]$ jstat -gccause 23606 2s 5
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC                 
  0.00 100.00  37.50  83.17  93.31  84.35   5597   24.116     0    0.000   24.116 G1 Evacuation Pause  No GC               
  0.00 100.00  37.50  83.17  93.31  84.35   5597   24.116     0    0.000   24.116 G1 Evacuation Pause  No GC               
  0.00 100.00  37.50  83.17  93.31  84.35   5597   24.116     0    0.000   24.116 G1 Evacuation Pause  No GC               
  0.00 100.00  37.50  83.17  93.31  84.35   5597   24.116     0    0.000   24.116 G1 Evacuation Pause  No GC               
  0.00 100.00  37.50  83.17  93.31  84.35   5597   24.116     0    0.000   24.116 G1 Evacuation Pause  No GC

System.gc引起的FullGC.png