full gc頻繁的分析及解決案例

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