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