full gc頻繁的分析及解決案例
阿新 • • 發佈：2018-01-09
過大 heap times 正常的 出現 結構 lec 收集器 max
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
?
- full gc頻繁的分析及解決案例
- 2016-04-14 09:20:54 0個評論 來源：end‘s coding life
- 收藏 我要投稿
現象
?| 1 |
系統報警full gc次數過多，每2分鐘達到了5～6次，這是不正常的現象
|
| 1 |
在full gc報警時的gc.log如下：
|
| 1 |
?
| 1 |
在full gc報警時的jstat如下：
|
| 1 |
sudo -u admin -H /opt/taobao/java/bin/jstat -gcutil `pgrep java` 2000 100
|
| 1 |
?
| 1 |
此時的cpu如下（基本都是在做gc）：
|
| 1 |
?
| 1 |
將應用重啟後，問題解決
|
| 1 |
但是當後臺執行低價航線更新時，過大概十幾個小時後，又出現上述情況！
|
分析
?| 1 |
當頻繁full gc時，jstack打印出堆棧信息如下：
|
| 1 |
sudo -u admin -H /opt/taobao/java/bin/jstack `pgrep java` > #your file path# |
| 1 |
?
| 1 |
可以看到的確是在跑低價信息
|
| 1 |
另外在應用頻繁full gc時和應用正常時，也執行了如下2種命令：
|
| 1 |
sudo -u admin -H /opt/taobao/java/bin/jmap -histo `pgrep` > #your file path#
|
| 1 |
sudo -u admin -H /opt/taobao/java/bin/jmap -histo:live `pgrep` > #your file path#（live會產生full gc） |
| 1 |
目的是確認以下2種信息：
|
| 1 |
（1）是否存在某些引用的不正常，造成對象始終可達而無法回收（Java中的內存泄漏）
|
| 1 2 |
（2）是否真是由於在頻繁full gc時同時又有大量請求進入分配內存從而處理不過來，
造成concurrent mode failure？
|
| 1 |
下圖是在應用正常情況下，jmap不加live，產生的histo信息：
|
| 1 |
?
| 1 |
下圖是在應用正常情況下，jmap加live，產生的histo信息：
|
| 1 |
?
| 1 |
下圖是在應用頻繁full gc情況下，jmap不加live和加live，產生的histo信息：
|
| 1 |
?
| 1 |
從上述幾個圖中可以看到：
|
| 1 |
（1）在應用正常情況下，圖中標紅的對象是被回收的，因此不是內存泄漏問題
|
| 1 2 |
（2）在應用頻繁full gc時，標紅的對象即使加live也是未被回收的，因上就是在頻繁full gc時，
同時又有大量請求進入分配內存從而處理不過來的問題
|
先從解決問題的角度，看怎樣造成頻繁的full gc？
從分析CMS GC開始
?| 1 |
先給個CMS GC的概況：
|
| 1 |
（1）young gc
|
| 1 |
可以看到，當eden滿時，young gc使用的是ParNew收集器
|
| 1 |
ParNew: 2230361K->129028K(2403008K), 0.2363650 secs解釋：
|
| 1 |
1）2230361K->129028K，指回收前後eden+s1(或s2)大小
|
| 1 |
2）2403008K，指可用的young代的大小，即eden+s1（或s2）
|
| 1 |
3）0.2363650 secs，指消耗時間
|
| 1 |
2324774K->223451K(3975872K), 0.2366810 sec解釋：
|
| 1 2 |
1）2335109K->140198K，指整個堆大小的變化
（heap=(young+old)+perm；young=eden+s1+s2；s1=s2=young/(survivor ratio+2)）
|
| 1 |
2）0.2366810 sec，指消耗時間
|
| 1 |
[Times: user=0.60 sys=0.02, real=0.24 secs]解釋：指用戶時間，系統時間，真實時間
|
| 1 |
?
| 1 |
（2）cms gc
|
| 1 |
當使用CMS收集器時，當開始進行收集時，old代的收集過程如下所示：
|
| 1 2 |
a）首先jvm根據-XX:CMSInitiatingOccupancyFraction，-XX:+UseCMSInitiatingOccupancyOnly
來決定什麽時間開始垃圾收集
|
| 1 2 |
b）如果設置了-XX:+UseCMSInitiatingOccupancyOnly，那麽只有當old代占用確實達到了
-XX:CMSInitiatingOccupancyFraction參數所設定的比例時才會觸發cms gc
|
| 1 2 3 |
c）如果沒有設置-XX:+UseCMSInitiatingOccupancyOnly，那麽系統會根據統計數據自行決定什麽時候
觸發cms gc；因此有時會遇到設置了80%比例才cms gc，但是50%時就已經觸發了，就是因為這個參數
沒有設置的原因
|
| 1 2 |
d）當cms gc開始時，首先的階段是CMS-initial-mark，此階段是初始標記階段，是stop the world階段，
因此此階段標記的對象只是從root集最直接可達的對象
|
| 1 |
CMS-initial-mark：961330K（1572864K），指標記時，old代的已用空間和總空間
|
| 1 2 |
e）下一個階段是CMS-concurrent-mark，此階段是和應用線程並發執行的，所謂並發收集器指的就是這個，
主要作用是標記可達的對象
|
| 1 |
此階段會打印2條日誌：CMS-concurrent-mark-start，CMS-concurrent-mark
|
| 1 2 |
f）下一個階段是CMS-concurrent-preclean，此階段主要是進行一些預清理，因為標記和應用線程是並發執行的，
因此會有些對象的狀態在標記後會改變，此階段正是解決這個問題
|
| 1 2 |
因為之後的Rescan階段也會stop the world，為了使暫停的時間盡可能的小，也需要preclean階段先做一部分
工作以節省時間
|
| 1 |
此階段會打印2條日誌：CMS-concurrent-preclean-start，CMS-concurrent-preclean
|
| 1 2 |
g）下一階段是CMS-concurrent-abortable-preclean階段，加入此階段的目的是使cms gc更加可控一些，
作用也是執行一些預清理，以減少Rescan階段造成應用暫停的時間
|
| 1 |
此階段涉及幾個參數：
|
| 1 |
-XX:CMSMaxAbortablePrecleanTime：當abortable-preclean階段執行達到這個時間時才會結束
|
| 1 2 |
-XX:CMSScheduleRemarkEdenSizeThreshold（默認2m）：控制abortable-preclean階段什麽時候開始執行，
即當eden使用達到此值時，才會開始abortable-preclean階段
|
| 1 |
-XX:CMSScheduleRemarkEdenPenetratio（默認50%）：控制abortable-preclean階段什麽時候結束執行
|
| 1 |
此階段會打印一些日誌如下：
|
| 1 2 |
CMS-concurrent-abortable-preclean-start，CMS-concurrent-abortable-preclean，
CMS：abort preclean due to time XXX
|
| 1 2 |
h）再下一個階段是第二個stop the world階段了，即Rescan階段，此階段暫停應用線程，對對象進行重新掃描並
標記
|
| 1 |
YG occupancy：964861K（2403008K），指執行時young代的情況
|
| 1 |
CMS remark：961330K（1572864K），指執行時old代的情況
|
| 1 |
此外，還打印出了弱引用處理、類卸載等過程的耗時
|
| 1 |
i）再下一個階段是CMS-concurrent-sweep，進行並發的垃圾清理
|
| 1 |
j）最後是CMS-concurrent-reset，為下一次cms gc重置相關數據結構
|
| 1 |
?
| 1 |
（3）full gc：
|
| 1 |
有2種情況會觸發full gc，在full gc時，整個應用會暫停
|
| 1 |
a）concurrent-mode-failure：當cms gc正進行時，此時有新的對象要進行old代，但是old代空間不足造成的
|
| 1 2 |
b）promotion-failed：當進行young gc時，有部分young代對象仍然可用，但是S1或S2放不下，
因此需要放到old代，但此時old代空間無法容納此
|
| 1 |
頻繁full gc的原因
?| 1 2 |
從日誌中可以看出有大量的concurrent-mode-failure，因此正是當cms gc進行時，有新的對象要進行old代，
但是old代空間不足造成的full gc
|
| 1 |
進程的jvm參數如下所示：
|
| 1 |
?
| 1 |
影響cms gc時長及觸發的參數是以下2個：
|
| 1 |
-XX:CMSMaxAbortablePrecleanTime=5000
|
| 1 |
-XX:CMSInitiatingOccupancyFraction=80
|
| 1 |
解決也是針對這兩個參數來的
|
| 1 |
根本的原因是每次請求消耗的內存量過大
|
解決
?| 1 2 |
（1）針對cms gc的觸發階段，調整-XX:CMSInitiatingOccupancyFraction=50，提早觸發cms gc，就可以
緩解當old代達到80%，cms gc處理不完，從而造成concurrent mode failure引發full gc
|
| 1 2 |
（2）修改-XX:CMSMaxAbortablePrecleanTime=500，縮小CMS-concurrent-abortable-preclean階段
的時間
|
| 1 2 3 |
（3）考慮到cms gc時不會進行compact，因此加入-XX:+UseCMSCompactAtFullCollection
（cms gc後會進行內存的compact）和-XX:CMSFullGCsBeforeCompaction=4
（在full gc4次後會進行compact）參數
|
| 1 |
但是運行了一段時間後，只不過時間更長了，又會出現頻繁full gc
|
| 1 |
計算了一下heap各個代的大小（可以用jmap -heap查看）：
|
| 1 |
total heap=young+old=4096m
|
| 1 |
perm:256m
|
| 1 |
young=s1+s2+eden=2560m
|
| 1 |
young avail=eden+s1=2133.375+213.3125=2346.6875m
|
| 1 |
s1=2560/(10+1+1)=213.3125m
|
| 1 |
s2=s1
|
| 1 |
eden=2133.375m
|
| 1 |
old=1536m
|
| 1 2 |
可以看到eden大於old，在極端情況下（young區的所有對象全都要進入到old時，就會觸發full gc），
因此在應用頻繁full gc時，很有可能old代是不夠用的，因此想到將old代加大，young代減小
|
| 1 |
改成以下：
|
| 1 |
-Xmn1920m
|
| 1 |
新的各代大小：
|
| 1 |
total heap=young+old=4096m
|
| 1 |
perm:256m
|
| 1 |
young=s1+s2+eden=1920m
|
| 1 |
young avail=eden+s1=2133.375+213.3125=1760m
|
| 1 |
s1=1760/(10+1+1)=160m
|
| 1 |
s2=s1
|
| 1 |
eden=1600m
|
| 1 |
old=2176m
|
| 1 |
此時的eden小於old，可以緩解一些問題
|
| 1 |
| 1 |
改完之後，運行了2天，問題解決，未頻繁報full gc
|
full gc頻繁的分析及解決案例