GC問題診斷

前言

最近上了個雙11的項目，因爲時間緊任務中，因此樓主也中間被拉進組裏進行支持，項目分爲了三期，第一期項目以前雖然寫完了可是隻是功能堆砌的上線了沒有流量因此係統有什麼問題反映不出來，徹底沒有技術評審和性能壓測，因此好很差用只能到放到雙11當天才知道，我以爲這個太冒險了。

我參與了二期的部分功能開發，一介入就有種「墨菲定律」的感受，總感受這個項目有「毒」。

由於明顯的感受到你們都在忙需求，甚至深陷需求中，而對於整個需求最熟悉的（由於原有老系統大部分人離職了，就剩下一個職級不高的同窗了）對於整個技術方案的把控能力也是不足的，形成整個設計方案存在比較大的問題，好比方案設計複雜：

• 引入的業務術語不統一，好比有的叫活動，有的的營銷券，形成大部分新介入的同窗在業務理解上存在比較大的壓力。
• 表設計不夠統一，好比有的表中完成狀態是1，有的完成狀態變爲了2了，1成了別的狀態。
• 表的設計過於瑣碎和複雜，變成了case by case的，每一個小功能都對應一個表，若是在一個相對聚合的功能表現上則須要維護N張表了。
• 代碼層次設計上沒有必定的抽象能力，好比公司有SOA平臺，理論上功能會有必定的歸檔到對應的服務裏面去，可是此次設計卻將一些非領域相關功能的東西又設計回來了，簡單點說就是將原本好好的微服務又設計成了大一體服務。
• 等。

這只是列的幾個在開發過程當中RD同窗反映和後續QA同窗（QA同窗在測試過程當中都會提出更好的設計方案）反映的幾個明顯的問題，若是光在技術角度看有更多的問題。

固然這還只是簡單的業務功能角度看設計有問題，考慮到技術角度，原本項目總體是爲雙11服務的，理論上是一個大的流量高峯，可是在整個設計和評審過程當中根本沒有人去討論性能，容量評估等問題，這樣確定是有必定的隱藏問題。

因而我第一時間向這個項目的技術負責人反映了相似的問題，說須要將這些問題在從新捋一下，可是項目技術負責人說，時間已經比較緊了，這期先這樣吧，問題在慢慢說，個人想法是「磨刀不誤砍柴工」，技術負責人的想法是「車到山前必有路」。

因而雙11這個項目就先上線了，上線第一天在雙11以前進行了必定的演練，而後就是各類FullGC了。

診斷須要對JVM有必定的瞭解，好比經常使用的垃圾回收器，Java堆模型。主要說下FullGC。

FullGC

Major GC一般和FullGC是等價的，都是收集整個GC堆。

FullGC觸發緣由：

沒有配置 -XX:+DisableExplicitGC狀況下System.gc()可能會觸發FullGC；

Promotion failed；

concurrent mode failure；

Metaspace Space使用達到MaxMetaspaceSize閾值；

執行jmap -histo:live或者jmap -dump:live；

判斷GC是否正常

主要依靠兩個維度：GC頻率和STW時間。

命令有：ps -p pid -o etime

[afei@ubuntu ~]$ ps -p 11864 -o etime
    ELAPSED
24-16:37:35
結果表示這個JVM運行了24天16個小時37分35秒，若是JVM運行時間沒有超過一天，執行結果相似這樣"16:37:35"。

什麼樣的GC頻率和STW時間纔算正常呢？ 舉個例子：JVM設置Xmx和Xms爲4G而且Xmn1G。 獲得的信息：

JVM運行總時間爲7293378秒（80*24*3600+9*3600+56*60+18）

YoungGC頻率爲2秒/次（7293378/3397184，jstat結果中YGC列的值）

CMS GC頻率爲9天/次（由於FGC列的值爲18，即最多發生9次CMS GC，因此CMS GC頻率爲80/9≈9天/次）

每次YoungGC的時間爲6ms（經過YGCT/YGC計算得出）

FullGC幾乎沒有（JVM總計運行80天，FGC才18，即便是18次FullGC，FullGC頻率也才4.5天/次，更況且實際上FGC=18確定包含了若干次CMS GC）

根據這個例子能夠獲得健康的GC狀況：

YoungGC頻率不超過2秒/次；

CMS GC頻率不超過1天/次；

每次YoungGC的時間不超過15ms；

FullGC頻率儘量徹底杜絕；

YGC

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

查看服務器SWAP&IO狀況，若是服務器發生SWAP，會嚴重拖慢GC效率，致使STW時間異常長，拉長接口響應時間，從而影響用戶體驗（推薦神器sar，yum install sysstat便可，想了解該命令，請搜索"linux sar"）；

查看StringTable狀況（請參考：探索StringTable提高YGC性能）

排查每次YGC後倖存對象大小（JVM模型基於分配的對象朝生夕死的假設設計，若是每次YGC後倖存對象較大，可能存在問題）

排查每次YGC後倖存對象大小可經過GC日誌中發生YGC的日誌計算得出，例以下面兩行GC日誌，第二次YGC相比第一次YGC，整個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日誌，第二次YGC相比第一次YGC，整個Heap從2707K增加到了4743K，說明回收效果不太理想，若是每次YGC時發現好幾十M甚至上百M的對象倖存，那麼可能須要着手排查了：

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情況給出建議YGC頻率不超過2秒/次，經驗值2秒~10秒/次都是比較合理的YGC頻率；

若是YGC頻率遠高於這個值，例如20秒/次，30秒/次，甚至60秒/次，這種狀況下，說明JVM至關空閒，處於基本上無事可作的狀態。建議縮容，減小服務器浪費；

若是YoungGC頻率遠低於這個值，例如1秒/次，甚至1秒/好屢次，這種狀況下，JVM至關繁忙，建議follow以下步驟進行初步症斷：

檢查Young區，Young區在整個堆佔比在25%~40%比較合理，若是Young區過小，建議擴大Xmn。

檢查SurvivorRatio，保持默認值8便可，Eden:S0:S1=8:1:1是一個比較合理的值；

OldGC

上面已經說起：到目前爲止HotSpot JVM虛擬機只單獨回收Old區的只有CMS GC。觸發CMS GC條件比較簡單，JVM有一個線程定時掃描Old區，時間間隔能夠經過參數-XX:CMSWaitDuration設置（默認就是2s），掃描發現Old區佔比超過參數-XX:CMSInitiatingOccupancyFraction設定值（CMS條件下默認爲68%），就會觸發CMS GC。 建議搭配-XX:+UseCMSInitiatingOccupancyOnly參數使用，簡化CMS GC觸發條件，只有在Old區佔比知足-XX:CMSInitiatingOccupancyFraction條件的狀況下才觸發CMS GC；

可參考的健康的GC情況給出建議CMS GC頻率不超過1天/次，若是CMS GC頻率1天發生數次，甚至上10次，說明你的GC狀況病的不輕了，建議follow以下步驟進行初步症斷：

檢查Young區與Old區比值，儘可能留60%以上的堆空間給Old區；

經過jstat查看每次YoungGC後晉升到Old區對象佔比，若是發現每次YoungGC後Old區漲好幾個百分點，甚至上10個點，說明有大對象，建議dump（參考jmap -dump:format=b,file=app.bin pid）後用MAT分析；

若是不停的CMS GC，Old區降不下去，建議先執行jmap -histo pid | head -n10 查看TOP10對象分佈，若是除了[B和[C，即byte[]和char[]，還有其餘佔比較大的實例，以下圖所示中排名第一的Object數組，也可經過dump後用MAT分析問題；

若是TOP10對象中有StandartSession對象，排查你的業務代碼中有沒有顯示使用HttpSession，例如String id = request.getSession().getId();，通常的OLTP系統都是無狀態的，幾乎不會使用HttpSession，且HttpSession的的生命週期很長，會加快Old區增加速度；
好比系統中是TOP對象中有StandartSession對象，而且佔比較大，後面讓他排查發如今接口中使用了HttpSession生成一個惟一ID，讓他改爲用UUID就解決了OldGC頻繁的問題。

FullGC

若是配置CMS，因爲CMS採用標記清理算法，會有內存碎片的問題，推薦配置一個查看內存碎片程度的JVM參數：PrintFLSStatistics。

若是配置ParallelOldGC，那麼每次Old區滿後，會觸發FullGC，若是FullGC頻率太高，也能夠經過上面OldGC說起的排查方法； 若是沒有配置-XX:+DisableExplicitGC，即沒有屏蔽System.gc()觸發FullGC，那麼能夠經過排查GC日誌中有System字樣判斷是否由System.gc()觸發，日誌樣本以下：

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()觸發，GCC表示當前GC緣由，若是當前沒有GC，那麼就是No GC：

System.gc引發的FullGC