Longda's Interesting World

Longda's Interesting World

监控工具 - java gc

监控工具 - java gc

背景

2013年的一篇文章，当时介绍的蛮不错的， 保留下来了。

现象

系统报警full gc次数过多，每2分钟达到了5～6次，这是不正常的现象
在full gc报警时的gc.log如下：
GC.LOG

在full gc报警时的jstat如下：

1
sudo -u admin -H /opt/taobao/java/bin/jstat -gcutil `pgrep java` 2000 100

gc jstat

此时的cpu如下（基本都是在做gc）：
gc cpu

将应用重启后，问题解决. 但是当后台执行低价航线更新时，过大概十几个小时后，又出现上述情况！

分析

当频繁full gc时，jstack打印出堆栈信息如下：

1
sudo -u admin -H /opt/taobao/java/bin/jstack `pgrep java` > #your file path#

gc jstat

另外在应用频繁full gc时和应用正常时，也执行了如下2种命令：

1
2
sudo -u admin -H /opt/taobao/java/bin/jmap -histo `pgrep` > #your file path#
sudo -u admin -H /opt/taobao/java/bin/jmap -histo:live `pgrep` > #your file path#（live会产生full gc）

目的是确认以下2种信息：

  1. 是否存在某些引用的不正常，造成对象始终可达而无法回收（Java中的内存泄漏）
  2. 是否真是由于在频繁full gc时同时又有大量请求进入分配内存从而处理不过来，造成concurrent mode failure？

下图是在应用正常情况下，jmap不加live，产生的histo信息：
gc jmap

下图是在应用正常情况下，jmap加live，产生的histo信息：
gc jmap live
下图是在应用频繁full gc情况下，jmap不加live和加live，产生的histo信息：
gc jmap live

从上述几个图中可以看到：

  1. 在应用正常情况下，图中标红的对象是被回收的，因此不是内存泄漏问题
  2. 在应用频繁full gc时，标红的对象即使加live也是未被回收的，因上就是在频繁full gc时，同时又有大量请求进入分配内存从而处理不过来的问题

先从解决问题的角度，看怎样造成频繁的full gc？

CMS GC

从分析CMS GC开始, 先给个CMS GC的概况

young gc

可以看到，当eden满时，young gc使用的是ParNew收集器

ParNew: 2230361K->129028K(2403008K), 0.2363650 secs解释：

  1. 2230361K->129028K，指回收前后eden+s1(或s2)大小
  2. 2403008K，指可用的young代的大小，即eden+s1（或s2）
  3. 0.2363650 secs，指消耗时间

2324774K->223451K(3975872K), 0.2366810 sec解释：

  1. 2335109K->140198K，指整个堆大小的变化 （heap=(young+old)+perm；young=eden+s1+s2；s1=s2=young/(survivor ratio+2)）
  2. 0.2366810 sec，指消耗时间 [Times: user=0.60 sys=0.02, real=0.24 secs]解释：指用户时间，系统时间，真实时间
    gc young gc

cms gc

当使用CMS收集器时，当开始进行收集时，old代的收集过程如下所示：

  1. 首先jvm根据-XX:CMSInitiatingOccupancyFraction，-XX:+UseCMSInitiatingOccupancyOnly 来决定什么时间开始垃圾收集
  2. 如果设置了-XX:+UseCMSInitiatingOccupancyOnly，那么只有当old代占用确实达到-XX:CMSInitiatingOccupancyFraction参数所设定的比例时才会触发cms gc
  3. 如果没有设置-XX:+UseCMSInitiatingOccupancyOnly，那么系统会根据统计数据自行决定什么时候触发cms gc；因此有时会遇到设置了80%比例才cms gc，但是50%时就已经触发了，就是因为这个参数没有设置的原因
  4. 当cms gc开始时，首先的阶段是CMS-initial-mark，此阶段是初始标记阶段，是stop the world阶段，因此此阶段标记的对象只是从root集最直接可达的对象CMS-initial-mark：961330K（1572864K），指标记时，old代的已用空间和总空间
  5. 下一个阶段是CMS-concurrent-mark，此阶段是和应用线程并发执行的，所谓并发收集器指的就是这个，主要作用是标记可达的对象. 此阶段会打印2条日志：CMS-concurrent-mark-start，CMS-concurrent-mark
  6. 下一个阶段是CMS-concurrent-preclean，此阶段主要是进行一些预清理，因为标记和应用线程是并发执行的，因此会有些对象的状态在标记后会改变，此阶段正是解决这个问题. 因为之后的Rescan阶段也会stop the world，为了使暂停的时间尽可能的小，也需要preclean阶段先做一部分工作以节省时间. 此阶段会打印2条日志：CMS-concurrent-preclean-start，CMS-concurrent-preclean
  7. 下一阶段是CMS-concurrent-abortable-preclean阶段，加入此阶段的目的是使cms gc更加可控一些，作用也是执行一些预清理，以减少Rescan阶段造成应用暂停的时间. 此阶段涉及几个参数：
    1
    2
    3
    -XX:CMSMaxAbortablePrecleanTime：当abortable-preclean阶段执行达到这个时间时才会结束
    -XX:CMSScheduleRemarkEdenSizeThreshold（默认2m）：控制abortable-preclean阶段什么时候开始执行，即当eden使用达到此值时，才会开始abortable-preclean阶段
    -XX:CMSScheduleRemarkEdenPenetratio（默认50%）：控制abortable-preclean阶段什么时候结束执行
    此阶段会打印一些日志如下：
    1
    2
    CMS-concurrent-abortable-preclean-start，CMS-concurrent-abortable-preclean，
    CMS：abort preclean due to time XXX
  8. 再下一个阶段是第二个stop the world阶段了，即Rescan阶段，此阶段暂停应用线程，对对象进行重新扫描并标记
    1
    2
    YG occupancy：964861K（2403008K），指执行时young代的情况
    CMS remark：961330K（1572864K），指执行时old代的情况
    此外，还打印出了弱引用处理、类卸载等过程的耗时
  9. 再下一个阶段是CMS-concurrent-sweep，进行并发的垃圾清理
  10. 最后是CMS-concurrent-reset，为下一次cms gc重置相关数据结构
    cms gc

full gc：

有2种情况会触发full gc，在full gc时，整个应用会暂停

  1. concurrent-mode-failure：当cms gc正进行时，此时有新的对象要进行old代，但是old代空间不足造成的
  2. promotion-failed：当进行young gc时，有部分young代对象仍然可用，但是S1或S2放不下，因此需要放到old代，但此时old代空间无法容纳此
    full gc

频繁full gc的原因

从日志中可以看出有大量的concurrent-mode-failure，因此正是当cms gc进行时，有新的对象要进行old代，但是old代空间不足造成的full gc

进程的jvm参数如下所示：
gc jvm parameter

影响cms gc时长及触发的参数是以下2个：

1
2
-XX:CMSMaxAbortablePrecleanTime=5000
-XX:CMSInitiatingOccupancyFraction=80

解决也是针对这两个参数来的

根本的原因是每次请求消耗的内存量过大

解决

  1. 针对cms gc的触发阶段，调整-XX:CMSInitiatingOccupancyFraction=50，提早触发cms gc，就可以缓解当old代达到80%，cms gc处理不完，从而造成concurrent mode failure引发full gc
  2. 修改-XX:CMSMaxAbortablePrecleanTime=500，缩小CMS-concurrent-abortable-preclean阶段的时间
  3. 考虑到cms gc时不会进行compact，因此加入-XX:+UseCMSCompactAtFullCollection（cms gc后会进行内存的compact）和-XX:CMSFullGCsBeforeCompaction=4（在full gc4次后会进行compact）参数

但是运行了一段时间后，只不过时间更长了，又会出现频繁full gc

计算了一下heap各个代的大小（可以用jmap -heap查看）：

1
2
3
4
5
6
7
8
total heap=young+old=4096m
perm:256m
young=s1+s2+eden=2560m
young avail=eden+s1=2133.375+213.3125=2346.6875m
s1=2560/(10+1+1)=213.3125m
s2=s1
eden=2133.375m
old=1536m

可以看到eden大于old，在极端情况下（young区的所有对象全都要进入到old时，就会触发full gc），因此在应用频繁full gc时，很有可能old代是不够用的，因此想到将old代加大，young代减小

改成以下： -Xmn1920m
新的各代大小：

1
2
3
4
5
6
7
8
total heap=young+old=4096m
perm:256m
young=s1+s2+eden=1920m
young avail=eden+s1=2133.375+213.3125=1760m
s1=1760/(10+1+1)=160m
s2=s1
eden=1600m
old=2176m

此时的eden小于old，可以缓解一些问题

改完之后，运行了2天，问题解决，未频繁报full gc