GC实践

首先感谢阿宝同学的帮助，我才对这个gc算法的调整有了一定的认识，而不是停留在过去仅仅了解的阶段。在读过sun的文档和跟阿宝讨论之后，做个小小的总结。
    CMS，全称Concurrent Low Pause Collector，是jdk1.4后期版本开始引入的新gc算法，在jdk5和jdk6中得到了进一步改进，它的主要适合场景是对响应时间的重要性需求大于对吞吐量的要求，能够承受垃圾回收线程和应用线程共享处理器资源，并且应用中存在比较多的长生命周期的对象的应用。CMS是用于对tenured generation的回收，也就是年老代的回收，目标是尽量减少应用的暂停时间，减少full gc发生的几率，利用和应用程序线程并发的垃圾回收线程来标记清除年老代。在我们的应用中，因为有缓存的存在，并且对于响应时间也有比较高的要求，因此希望能尝试使用CMS来替代默认的server型JVM使用的并行收集器，以便获得更短的垃圾回收的暂停时间，提高程序的响应性。
    CMS并非没有暂停，而是用两次短暂停来替代串行标记整理算法的长暂停，它的收集周期是这样：
    初始标记(CMS-initial-mark) -> 并发标记(CMS-concurrent-mark) -> 重新标记(CMS-remark) -> 并发清除(CMS-concurrent-sweep) ->并发重设状态等待下次CMS的触发(CMS-concurrent-reset)。
    其中的1，3两个步骤需要暂停所有的应用程序线程的。第一次暂停从root对象开始标记存活的对象，这个阶段称为初始标记；第二次暂停是在并发标记之后，暂停所有应用程序线程，重新标记并发标记阶段遗漏的对象（在并发标记阶段结束后对象状态的更新导致）。第一次暂停会比较短，第二次暂停通常会比较长，并且remark这个阶段可以并行标记。

    而并发标记、并发清除、并发重设阶段的所谓并发，是指 一个或者多个垃圾回收线程和应用程序线程并发地运行，垃圾回收线程不会暂停应用程序的执行，如果你有多于一个处理器，那么并发收集线程将与应用线程在不同的处理器上运行，显然，这样的开销就是会降低应用的吞吐量。Remark阶段的 并行，是指暂停了所有应用程序后，启动一定数目的垃圾回收进程进行并行标记，此时的应用线程是暂停的。

    CMS的young generation的回收采用的仍然是并行复制收集器，这个跟Paralle gc算法是一致的。

    下面是参数介绍和遇到的问题总结，

1、启用CMS： -XX:+UseConcMarkSweepGC。 咳咳，这里犯过一个低级错误，竟然将+号写成了-号

2。CMS默认启动的回收线程数目是  (ParallelGCThreads + 3)/4) ，如果你需要明确设定，可以通过-XX: ParallelCMSThreads =20来设定,其中ParallelGCThreads是年轻代的并行收集线程数

3、CMS是不会整理堆碎片的，因此为了防止堆碎片引起full gc，通过会开启CMS阶段进行合并碎片选项： -XX:+UseCMSCompactAtFullCollection，开启这个选项一定程度上会影响性能，阿宝的blog里说也许可以通过配置适当的CMSFullGCsBeforeCompaction来调整性能，未实践。

4.为了减少第二次暂停的时间，开启并行remark: -XX:+CMSParallelRemarkEnabled，如果remark还是过长的话，可以开启 -XX:+CMSScavengeBeforeRemark选项，强制remark之前开始一次minor gc，减少remark的暂停时间，但是在remark之后也将立即开始又一次minor gc。

5.为了避免Perm区满引起的full gc，建议开启CMS回收Perm区选项：

+CMSPermGenSweepingEnabled -XX:+CMSClassUnloadingEnabled

6.默认CMS是在tenured generation沾满68%的时候开始进行CMS收集，如果你的年老代增长不是那么快，并且希望降低CMS次数的话，可以适当调高此值：
-XX:CMSInitiatingOccupancyFraction=80

这里修改成80%沾满的时候才开始CMS回收。

7.年轻代的并行收集线程数默认是 (ncpus <= 8) ? ncpus : 3 + ((ncpus * 5) / 8)，如果你希望设定这个线程数，可以通过 -XX:ParallelGCThreads= N 来调整。

8.进入重点，在初步设置了一些参数后，例如：

- server  - Xms1536m  - Xmx1536m  - XX:NewSize = 256m  - XX:MaxNewSize = 256m  - XX:PermSize = 64m
- XX:MaxPermSize = 64m  - XX: - UseConcMarkSweepGC  - XX: + UseCMSCompactAtFullCollection
- XX:CMSInitiatingOccupancyFraction = 80   - XX: + CMSParallelRemarkEnabled
- XX:SoftRefLRUPolicyMSPerMB = 0

需要在生产环境或者压测环境中测量这些参数下系统的表现，这时候需要打开GC日志查看具体的信息，因此加上参数：

-verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/home/test/logs/gc.log

在运行相当长一段时间内查看CMS的表现情况，CMS的日志输出类似这样：

4391.322 : [GC [ 1  CMS - initial - mark: 655374K(1310720K)] 662197K(1546688K),  0.0303050  secs] [Times: user = 0.02  sys = 0.02 , real = 0.03  secs]
4391.352 : [CMS - concurrent - mark - start]
4391.779 : [CMS - concurrent - mark:  0.427 / 0.427  secs] [Times: user = 1.24  sys = 0.31 , real = 0.42  secs]
4391.779 : [CMS - concurrent - preclean - start]
4391.821 : [CMS - concurrent - preclean:  0.040 / 0.042  secs] [Times: user = 0.13  sys = 0.03 , real = 0.05  secs]
4391.821 : [CMS - concurrent - abortable - preclean - start]
4392.511 : [CMS - concurrent - abortable - preclean:  0.349 / 0.690  secs] [Times: user = 2.02  sys = 0.51 , real = 0.69  secs]
4392.516 : [GC[YG occupancy:  111001  K ( 235968  K)] 4392.516 : [Rescan (parallel) ,  0.0309960  secs] 4392.547 : [weak refs processing,  0.0417710  secs] [ 1  CMS - remark: 655734K(1310720K)] 766736K(1546688K),  0.0932010  secs] [Times: user = 0.17  sys = 0.00 , real = 0.09  secs]
4392.609 : [CMS - concurrent - sweep - start]
4394.310 : [CMS - concurrent - sweep:  1.595 / 1.701  secs] [Times: user = 4.78  sys = 1.05 , real = 1.70  secs]
4394.310 : [CMS - concurrent - reset - start]
4394.364 : [CMS - concurrent - reset:  0.054 / 0.054  secs] [Times: user = 0.14  sys = 0.06 , real = 0.06  secs]

其中可以看到CMS-initial-mark阶段暂停了0.0303050秒，而CMS-remark阶段暂停了0.0932010秒，因此两次暂停的总共时间是0.123506秒，也就是123毫秒左右。两次短暂停的时间之和在200以下可以称为正常现象。

但是你很可能遇到 两种fail引起full gc：Prommotion failed和Concurrent mode failed。

Prommotion failed的日志输出大概是这样：

 [ParNew (promotion failed): 320138K -> 320138K(353920K),  0.2365970  secs] 42576.951 : [CMS: 1139969K -> 1120688K(
2166784K),  9.2214860  secs] 1458785K -> 1120688K(2520704K),  9.4584090  secs]

这个问题的产生是由于救助空间不够，从而向年老代转移对象，年老代没有足够的空间来容纳这些对象，导致一次full gc的产生。解决这个问题的办法有两种完全相反的倾向： 增大救助空间、增大年老代或者去掉救助空间。增大救助空间就是调整-XX:SurvivorRatio参数，这个参数是Eden区和Survivor区的大小比值，默认是32，也就是说Eden区是Survivor区的32倍大小，要注意Survivo是有两个区的，因此Surivivor其实占整个young genertation的1/34。调小这个参数将增大survivor区，让对象尽量在survitor区呆长一点，减少进入年老代的对象。去掉救助空间的想法是让大部分不能马上回收的数据尽快进入年老代，加快年老代的回收频率，减少年老代暴涨的可能性，这个是通过将-XX:SurvivorRatio 设置成比较大的值（比如65536)来做到。在我们的应用中，将young generation设置成256M，这个值相对来说比较大了，而救助空间设置成默认大小(1/34)，从压测情况来看，没有出现prommotion failed的现象，年轻代比较大，从GC日志来看，minor gc的时间也在5-20毫秒内，还可以接受，因此暂不调整。

Concurrent mode failed的产生是由于CMS回收年老代的速度太慢，导致年老代在CMS完成前就被沾满，引起full gc，避免这个现象的产生就是调小-XX:CMSInitiatingOccupancyFraction参数的值，让CMS更早更频繁的触发，降低年老代被沾满的可能。我们的应用暂时负载比较低，在生产环境上年老代的增长非常缓慢，因此暂时设置此参数为80。在压测环境下，这个参数的表现还可以，没有出现过Concurrent mode failed。

   

    在初步确定CMS参数后，系统运行了几天，今天尝试在线上打开了GC日志，按阿宝同学的说法是gc日志的开销比之jstat还小，打开之后发现确实影响很小。打开GC日志之后又发现几个隐藏的问题比较有价值，这里记录下。

   首先是系统在启动的时候有一次System.gc()调用引起的full gc，日志输出类似这样：

1.201 : [Full GC (System)  1.201 : [CMS: 0K -> 797K(1310720K),  0.1090540  secs] 29499K -> 797K(1546688K), [CMS Perm : 5550K -> 5547K(65536K)],  0.1091860  secs] [Times: user = 0.05  sys = 0.06 , real = 0.11  secs]

   可以确认的是我们系统里的代码绝对没有调用System.gc()方法，但是不保证第三方代码有调用，通过搜索代码引用，后来定位到了mina的ByteBuffer创建上面。 Mina 1.1封装的ByteBuffer的allocate()方法默认创建的是Direct ByteBuffer，而DirectByteBuffer的构造函数里调用了

Bits.reserveMemory(cap);

这个方法强制调用了System.gc():

static   void  reserveMemory( long  size) {

     synchronized  (Bits. class ) {
         if  ( ! memoryLimitSet  &&  VM.isBooted()) {
        maxMemory  =  VM.maxDirectMemory();
        memoryLimitSet  =   true ;
        }
         if  (size  <=  maxMemory  -  reservedMemory) {
        reservedMemory  +=  size;
         return ;
        }
    }

    System.gc();
     try  {
        Thread.sleep( 100 );
    }  catch  (InterruptedException x) {
         //  Restore interrupt status
        Thread.currentThread().interrupt();
    }
     synchronized  (Bits. class ) {
         if  (reservedMemory  +  size  >  maxMemory)
         throw   new  OutOfMemoryError( " Direct buffer memory " );
        reservedMemory  +=  size;
    }

    }

    调用这个方法是为了用户对Direct ByteBuffer的内存可控。而在我们系统中使用的通讯层初始化Decoder的时候通过Mina 1.1创建了一个Direct ByteBuffer，导致了这一次强制的full gc。这个Buffer因为是长期持有的，因此创建Direct类型也还可以接受。

    但是在这次GC后，又发现每隔一个小时就有一次System.gc()引起的full gc，这就太难以忍受了，日志大概是这样，注意间隔时间都是3600秒左右：

10570.672 : [Full GC (System)  10570.672 : [CMS: 779199K -> 107679K(1310720K),  1.2957430  secs] 872163K -> 107679K(1546688K), [CMS Perm : 23993K -> 15595K(65536K)],  1.2959630  secs] [Times: user = 1.27  sys = 0.02 , real = 1.30  secs] 
14171.971 : [Full GC (System)  14171.971 : [CMS: 680799K -> 83681K(1310720K),  1.0171580  secs] 836740K -> 83681K(1546688K), [CMS Perm : 20215K -> 15599K(65536K)],  1.0173850  secs] [Times: user = 0.97  sys = 0.01 , real = 1.02  secs] 
17774.020 : [Full GC (System)  17774.020 : [CMS: 676201K -> 79331K(1310720K),  0.9652670  secs] 817596K -> 79331K(1546688K), [CMS Perm : 22808K -> 15619K(65536K)],  0.9655150  secs] [Times: user = 0.93  sys = 0.02 , real = 0.97  secs] 
21374.989 : [Full GC (System)  21374.989 : [CMS: 677818K -> 78590K(1310720K),  0.9297080  secs] 822317K -> 78590K(1546688K), [CMS Perm : 16435K -> 15593K(65536K)],  0.9299620  secs] [Times: user = 0.89  sys = 0.01 , real = 0.93  secs] 
24976.948 : [Full GC (System)  24976.948 : [CMS: 659511K -> 77608K(1310720K),  0.9255360  secs] 794004K -> 77608K(1546688K), [CMS Perm : 22359K -> 15594K(65536K)],  0.9257760  secs] [Times: user = 0.88  sys = 0.02 , real = 0.93  secs] 
28578.892 : [Full GC (System)  28578.892 : [CMS: 562058K -> 77572K(1310720K),  0.8365500  secs] 735072K -> 77572K(1546688K), [CMS Perm : 15840K -> 15610K(65536K)],  0.8367990  secs] [Times: user = 0.82  sys = 0.00 , real = 0.84  secs] 
32179.731 : [Full GC (System)  32179.732 : [CMS: 549874K -> 77224K(1310720K),  0.7864400  secs] 561803K -> 77224K(1546688K), [CMS Perm : 16016K -> 15597K(65536K)],  0.7866540  secs] [Times: user = 0.75  sys = 0.01 , real = 0.79  secs]

    搜遍了源码和依赖库，没有再发现显式的gc调用，问题只能出在运行时上，突然想起我们的系统使用RMI暴露JMX给监控程序，监控程序通过RMI连接JMX监控系统和告警等，会不会是 RMI的分布式垃圾收集导致的？果然，一查资料，RMI的分布式收集会强制调用System.gc()来进行分布式GC，server端的间隔恰好是一个小时，这个参数可以通过：

- Dsun.rmi.dgc.server.gcInterval = 3600000

来调整。调长时间是一个解决办法，但是我们更希望能不出现显式的GC调用，禁止显式GC调用通过 -XX:+DisableExplicitGC是一个办法，但是禁止了分布式GC会导致什么问题却是心理没底，毕竟我们的JMX调用还是很频繁的，幸运的是JDK6还提供了另一个选项 -XX:+ExplicitGCInvokesConcurrent，允许System.gc()也并发运行，调整DGC时间间隔加上这个选项双管齐下彻底解决了full gc的隐患。

    打开GC日志后发现的另一个问题是remark的时间过长，已经启用了并行remark，但是时间还是经常超过200毫秒，这个可能的原因有两个：我们的年老代太大或者触发CMS的阀值太高了，CMS进行的时候年老代里的对象已经太多。初步的计划是调小-XX:SurvivorRatio增大救助空间并且降低-XX:CMSInitiatingOccupancyFraction这个阀值。此外，还找到另一个可选参数 -XX:+CMSScavengeBeforeRemark，启用这个选项后，强制remark之前开始一次minor gc，减少remark的暂停时间，但是在remark之后也将立即开始又一次相对较长时间minor gc，如果你的minor gc很快的话可以考虑下这个选项，暂未实验。

    本以为在上篇定稿的参数后应该能有比较好的表现，然后实际的表现大出我的意料，cms回收触发非常频繁，虽然每次都只是10-50毫秒，但是次数12个小时内能达到180多次，这显然不正常。通过gc日志和jstat可以看到，每次old区还在5%左右就开始进行CMS，此时的perm区也才30%，这两个数字有浮动并且CMS触发的时间上也没有规律，在测试环境和生产环境中都是如此。

    那么最后是怎么解决的呢？其实没有解决。我只是替换了一个参数就没再发生这个现象，上文提到为了避免System.gc()调用引起的full gc，使用了jdk6引入的新参数-XX:+ExplicitGCInvokesConcurrent来让System.gc()并发执行，但是测试表明恰恰是这个参数引起了CMS的频繁发生，去掉这个参数就没有那个奇特的现象。重复检查了代码，并且再次查看了GC日志，没有再发现有System.gc()的调用，我暂时将原因归结于使用了ExplicitGCInvokesConcurrent参数后其他方法触发了CMS，如果有知晓的朋友请留言告知，最后的方案还是彻底禁掉了显式GC调用。最终定稿的参数：

-server -Xms1536m -Xmx1536m -XX:NewSize=256m -XX:MaxNewSize=256m
-XX:PermSize=64m -XX:MaxPermSize=64m -XX:+UseConcMarkSweepGC
-XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=70
-XX:+CMSParallelRemarkEnabled -XX:SoftRefLRUPolicyMSPerMB=0
-XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC
-XX:SurvivorRatio=8

    删除了+CMSPermGenSweepingEnabled，这个参数在jdk6上跟-XX:+CMSClassUnloadingEnabled作用重叠了，如果你还跑在jdk5上面，那么应该使用这个参数。救助空间设置为NewSize的1/10，也就是25M左右，让年轻代尽量回收，防止年轻对象跑到年老代过早触发CMS甚至full gc。CMS的触发阀值下降到70%，因为年老代增长较慢，宁愿回收次数多一点，降低长暂停的可能。

    24小时内的某台生产机器的表现，通过jstat观察：

  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   
  39.70     0.00     5.59    15.15    28.99    20260    326.041      14      0.592    326.633
  39.70     0.00    65.49    15.15    28.99    20260    326.041      14      0.592    326.633
   0.00    36.93    19.37    15.16    29.01    20261    326.059      14      0.592    326.650
   0.00    36.93    93.23    15.16    29.01    20261    326.059      14      0.592    326.650
  34.04     0.00    59.62    15.17    29.01    20262    326.076      14      0.592    326.668
   0.00    38.55    12.76    15.19    29.01    20263    326.094      14      0.592    326.686
   0.00    38.55    65.48    15.19    29.01    20263    326.094      14      0.592    326.686

    CMS两次暂停时间总和在100ms以下，minor gc平均一次执行花了16ms，平均3-4秒发生一次。暂时来看还不错，也许还可以适当调小一下NewSize，加快以下minor gc。

    此次调整总共花了大概一周多的时间，由于经验不足，还是走了不少弯路，幸好最终的结果还可以，也让自己对cms gc有比较深入的了解。我们的系统在周4晚上已经全部更新上线，从内部测试、压测、日常测试、beta测试以来，每个阶段都发现几个隐蔽的问题，在上线后暂时没有再发现问题，证明这个流程还是很有意义的，我过去对流程充满偏见，现在看来是可笑的。总结我在淘宝5个月越来学习到的东西，几个关键词：认真、负责、细心、快乐。

参考资料：
《JDK5.0垃圾收集优化之--Don't Pause》 by 江南白衣
《记一次Java GC调整经历》1,2 by Arbow
Java SE 6 HotSpot[tm] Virtual Machine Garbage Collection Tuning
Tuning Garbage Collectionwith the 5.0 JavaTM Virtual Machine