gc java cms_Java CMS GC 361s引发的血案

2015-07-23T06:22:40.993-0400: [GC [ParNew: 943744K->60810K(943744K), 0.0665070 secs] 9064809K->8181875K(10380928K), 0.0665910 secs] [Times: user=0.25 sys=0.00, real=0.06 secs]

这里大部分Survivor不足以存放所有的存活对象，然而并不是所有的，如第一条就不是，对这个我一直很纳闷，在网上也没有找到非常可能的答案，但是大概这个答案看起来比较靠谱，简单来说，就是当时有很多page faults，这个也符合我们当时的情况，因为这台机器原本内存不是那么足，因而偶尔会出现内存swap，而且在这种情况下，所有的sys时间相对都比较长，也是一个佐证；另外也有人解释说ParNew在Stop-The-World之前要确保所有JNI线程都暂停下来，因而需要等待到达safepoint，这个貌似不太像我们遇到的情况，因为我们没有使用外部的JNI，如果内部自己的JNI应该不至于有那么大的影响(但是这个点正好说明我们使用JNI的时候要非常小心，如果有函数运行时间太长会影响JVM的稳定性，甚至让JVM没有响应，因为它在GC的时候要等这个长时间的JNI方法结束，或到达safepoint。更正：这里对safepoint有这样的解释：A point during program execution at which all GC roots are known and all heap object contents are consistent. From a global point of view, all threads must block at a safepoint before the GC can run. (As a special case, threads running JNI code can continue to run, because they use only handles. During a safepoint they must block instead of loading the contents of the handle.) From a local point of view, a safepoint is a distinguished point in a block of code where the executing thread may block for the GC. Most call sites qualify as safepoints. There are strong invariants which hold true at every safepoint, which may be disregarded at non-safepoints. Both compiled Java code and C/C++ code be optimized between safepoints, but less so across safepoints. The JIT compiler emits a GC map at each safepoint. C/C++ code in the VM uses stylized macro-based conventions (e.g., TRAPS) to mark potential safepoints.，所以看起来这个论断是有问题的)。ParNew暂停的时间都比较短，而且在大部分情况下，或者在其他内存够用的集群中我们没有遇到那么久的GC时间，因而基本不需要过多调节，所以其他都保持了它的默认值。

更正：前几天我们再次发现ParNew GC用去186.63s：

2015-08－07T14:57:22.317+0100: [GC[ParNew: 845794K->88289K(943744K), 186.6537260 secs] 6808480K->6087745K(10380928K), 186.6540490 secs][Times: user=1703.17 sys=194.13, real=186.63 secs]

通过一些系统工具，我们发现在问题发生的时候，当时那台机器有26%左右的Swap内存，并且有很高的page fault，因而我们基本能肯定这是内存数据被换出到Swap然后在GC的时候产生page fault引起的。并且在这里还提及到了swap中每4KB数据会增加10ms的GC时间：

A very high sys time suggests the OS is struggling with the application. I would make sure there is no chance the application has been partially swapped to disk as it must be completely in main memory for the GC to run is a reasonable time. Every 4 KB swapped to disk and add 10 ms to the GC time.

因而我们基本能肯定发生那么长的时间就是因为内存swap引起的，据说在Cassandra调优时有些直接把虚拟内存禁掉，以防出现类似的问题。

CMS收集器调节

重点当然是要调节CMS收集器，即要避免它在收集时停顿过长，更要避免产生promotion failed和concurrent mode failure的情况，因为这两种情况发生后都会引起CMS做Stop-The-World GC，其中第二中情况在做GC时还会做整理(Compact)，因而会有更久的停顿，而我们这次是两种情况同时遇到了。要避免这两种情况的发生需要先理解为什么会发生这两种情况。

首先，我们来看看promotion failed发生的情况：

我们知道当对象到一定的年龄，或者在某次回收过程中一个Survivor无法装下所有存活的对象，或者一个对象的大小超过-XX:PretenureSizeThreshold设置的值，就会被promote到Old Gen中，而在promote过程中如果Old Gen无法装下所有的内存时就会产生promotion failed(这里说CMS是根据预估的值：Modern CMS collector estimates size of objects to be promoted using statistics from previous collections. If old space does not have enough free bytes to hold estimated promotion amount, concurrent mode failure will be raise.但是我的理解是这是ParNew做的GC，为什么由CMS来预估？所以应该是ParNew把需要promote的对象传递给CMS，然后CMS做预估决定是否有足够多的内存存放这些新promote的对象)，此时就会先做一遍CMS GC，然后将新promote的对象存放到Old Gen中，由于这属于ParNew GC的范围，因而这次的CMS GC依然处于STW状态，因而这会花比较久的时间。如这次的ParNew GC，花费5.75s：

2015-07-20T08:23:00.028-0400: [GC [ParNew (promotion failed): 844305K->841244K(943744K), 0.2358120 secs][CMS: 6282619K->1891959K(9437184K), 5.5098940 secs] 7126660K->1891959K(10380928K), [CMS Perm : 67716K->66078K(112860K)], 5.7458460 secs] [Times: user=4.77 sys=0.02, real=5.75 secs]

2015-07-20T08:23:06.532-0400: [GC [ParNew: 838912K->7606K(943744K), 0.0063650 secs] 2730871K->1899566K(10380928K), 0.0065380 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

我们当前的设置：-XX:CMSInitiatingOccupancyFraction=79 -XX:+UseCMSInitiatingOccupancyOnly，也就是只有到Old Gen占用79%后才会触发CMS GC，这里只占66.57%，因而还没能触发CMS GC，然而此时ParNew GC只回收了3061K的对象，还有841244K的对象存活，而一个Survivor只有104857.6K大小，此时需要promote大概736386.4K大小的数据到Old Gen中，此时Old Gen还有(9437184K-6282619K=3154565K)大小的内存，虽然远远大于被promote的对象，但是我们知道CMS采用标记-清除(Mark-Sweep)算法，而不主动整理(Compact)，但是它在每次回收时会合并相邻的内存空间，然而跑久了难免会产生内存碎片，也就是说此时内存碎片已经很多了，无法容纳新promote的对象，要不就是新promote的对象大小太大，或者碎片太小，因而需要出发一次CMS GC来释放一些空间(此时发生的CMS是不是已经退化成Serial Old收集器算法了？即在收集的过程还是整理？)，以保证能存放下所有新promote出的对象。这里GC日志中并没有显示出什么这次ParNew GC后，Young Gen还剩下多少内存，但是根据下一次ParNew GC的初始大小是838912K，小于之前存活下来的对象(841244K)，因而我们可以确定这次GC的结果是把多余的对象promtoe到Old Gen中了。

所以根据分析，我们可以从两个方向调节参数：

1. 降低CMS GC的阈值。

2. 提前减少Old Gen中的碎片，即让CMS GC做整理。

对降低CMS GC阈值，我们可以调节参数：-XX:CMSInitiatingOccupancyFraction，默认大小68，我们可以将它设置成60。对提前减少Old Gen的碎片，这个比较麻烦，我们不想每次CMS GC都做整理(Compact)，因而这会比较浪费，会增加GC总体的时间以及停顿的时间，而且也比较危险，因为万一某次整理时间太长会引起集群的不稳定(可以设置-XX:UseCMSCompactAtFullCollection来实现这个功能)。还有一种办法是设置每经历N次CMS后做一次整理，通过-XX:CMSFullGCsBeforeCompaction=来设置，这个相对可以接受一些。当然如果能找到一个相对空闲的时间手动触发一次Full GC，并且确保让它能触发整理(这个目前还没有找到合适的方法，JConsole提供的GC按钮是一个可选项，但是不确定。我做了一下尝试：

2015-07-31T16:04:49.183+0800: [Full GC (System) [CMS: 3861443K->1072505K(9437184K), 2.9535440 secs] 4458634K->1072505K(10380928K), [CMS Perm : 68183K->67112K(112880K)], 2.9537000 secs] [Times: user=2.94 sys=0.00, real=2.95 secs]

看起来是减少了不少内存，按日志的格式，看起来像是Serial Old的算法？另外，使用这个功能要确保-XX:-DisableExplicitGC是关闭的，虽然这就是默认值)。

值得注意的是，promotion failed的情况也可以产生很长的停顿，这里我们看到总的时间是378.38s，user的时间只有5.56s，而sys的时间高达1.80s，看起来和ParNew长时间停顿的情况类似，即产生了对象换出到虚拟内存了？

2015-07-22T08:20:04.712-0400: [GC [ParNew (promotion failed): 842147K->839927K(943744K), 0.2343990 secs][CMS: 7382737K->1921345K(9437184K), 378.2061130 secs] 8224802K->1921345K(10380928K), [CMS Perm : 67406K->66061K(112260K)], 378.4406520 secs] [Times: user=5.56 sys=1.80, real=378.38 secs]

关于产生promotion failed，这里还有更详细的解释，如涉及到PLAB(Promotion Local Allocation Buffer)的介绍等，以及这里是对它的更正。值得注意的是，CMS在管理内存中使用空闲列表的方式，然而这种方式可能会存在某些问题，如这句话所说(具体就不展开了)：

CMS memory manager is using separate free lists for different size of chunks. Using these free lists, it can effectively fill small holes in fragmented memory space with objects of exact size. This technique is known to be fairly effective (and widely used in C/C++ memory managers). But, surprisingly, it doesn't seems to work well for JVM in many real live situations.

然后，再来看看concurrent mode failure的情况：

依然是这篇文章，作者说concurrent mode failure是在Young GC发生前，它会预估Old Gen是否有足够的空间存放从Young Gen中promote上来的对象，CMS收集器根据之前统计来预估这些对象的大小，如果Old Gen没有足够的空间存放这个预估的值，就会发生concurrent mode failure。此时不一定会产生Full GC，有些时候JVM只是等待当前并行收集完成，但是用户程序此时还是会STW直到这次收集技术。

At beginning  of each young GC, collector should ensure that there is enough free memory in old space to promote aged objects from young space. Modern CMS collector estimates size of objects to be promoted using statistics from previous collections. If old space does not have enough free bytes to hold estimated promotion amount,concurrent mode failurewill be raise. Concurrent mode failure doesn't necessary lead to Full GC, in certain cases JVM will just wait for concurrent collection cycle to finish, but application will remain in STW pause until young collection will be finished.

然而根据我的观察，concurrent mode failure都是发生在CMS已经开始，但是在中间阶段，出现ParNew的promotion failed。

如这是发生在CMS-concurrent-abortable-preclean阶段：

2015-07-19T06:17:04.919-0400: [GC [1 CMS-initial-mark: 7612366K(9437184K)] 7726317K(10380928K), 0.0208180 secs] [Times: user=0.02 sys=0.01, real=0.02 secs]

2015-07-19T06:17:05.275-0400: [CMS-concurrent-mark: 0.334/0.334 secs] [Times: user=1.62 sys=0.02, real=0.33 secs]

2015-07-19T06:17:05.294-0400: [CMS-concurrent-preclean: 0.019/0.019 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]

2015-07-19T06:17:05.936-0400: [GC [ParNew (promotion failed): 943744K->943744K(943744K), 0.2429280 secs][CMS2015-07-19T06:17:06.239-0400: [CMS-concurrent-abortable-preclean: 0.493/0.945 secs] [Times: user=1.54 sys=0.06, real=0.95 secs]

(concurrent mode failure): 7747387K->1603792K(9437184K), 5.4145810 secs] 8556110K->1603792K(10380928K), [CMS Perm : 65203K->63169K(108704K)], 5.6576200 secs] [Times: user=4.66 sys=0.01, real=5.66 secs]

这是ParNew发生时，CMS-concurrent-preclean结束不久，此时ParNew花费0.2429280s完成，想premote一些对象而失败，因而CMS在06:17:06.239完成步骤：CMS-concurrent-abortable-preclean，然而这个步骤结束后，依然无法容纳promote上来的对象，所以需要做一个Full GC，完成以后Old Gen内存从7747387K下降到1603792K，总内存从8556110K下降到1603792K，即将所有Young Gen中存活的对象放到了Old Gen中了。

这是发生在CMS-concurrent-sweep阶段：

2015-07-23T06:25:36.290-0400: [CMS-concurrent-preclean: 19.091/174.559 secs] [Times: user=53.37 sys=3.66, real=174.53 secs]

2015-07-23T06:25:36.525-0400: [CMS-concurrent-abortable-preclean: 0.133/0.235 secs] [Times: user=0.37 sys=0.00, real=0.24 secs]

2015-07-23T06:25:36.526-0400: [GC[YG occupancy: 719822 K (943744 K)][Rescan (parallel) , 0.0487460 secs][weak refs processing, 0.0002160 secs] [1 CMS-remark: 8636790K(9437184K)] 9356613K(10380928K), 0.0490460 secs] [Times: user=0.32 sys=0.00, real=0.05 secs]

2015-07-23T06:25:38.022-0400: [GC [ParNew: 942035K->104832K(943744K), 3.4626740 secs] 9571668K->8831757K(10380928K), 3.4627820 secs] [Times: user=0.35 sys=0.07, real=3.47 secs]

2015-07-23T06:25:43.548-0400: [GC [ParNew (promotion failed): 943744K->943744K(943744K), 3.9544520 secs][CMS2015-07-23T06:31:11.405-0400: [CMS-concurrent-sweep: 327.407/334.829 secs] [Times: user=8.42 sys=1.77, real=334.78 secs]

(concurrent mode failure): 8881917K->1234174K(9437184K), 357.1201510 secs] 9645662K->1234174K(10380928K), [CMS Perm : 67582K->63968K(111848K)], 361.0747320 secs] [Times: user=10.25 sys=1.59, real=361.02 secs]

这里基本和上面类似，ParNew在06:25:43.548结束，花费3.9544520s发现promotion failed，启动CMS GC，但在327.407s(从ParNew开始算起)完成CMS-concurrent-sweep后还是无法存放promote上来的对象，而发生concurrent mode failure，然后开始整理以容纳promote的对象，花费20s左右时间，最后做Perm GC，花费4s左右。这里CMS-concurrent-sweep之所以要花费327.407s的时间，应该还是和page faults相关吧？

这是发生在CMS-concurrent-mark阶段：

2015-07-17T03:21:28.701-0400: [GC [1 CMS-initial-mark: 7598316K(9437184K)] 7703150K(10380928K), 1.5896460 secs] [Times: user=0.02 sys=0.00, real=1.59 secs]

2015-07-17T03:22:16.910-0400: [GC [ParNew (promotion failed): 943744K->943744K(943744K), 7.5542170 secs][CMS2015-07-17T03:22:26.210-0400: [CMS-concurrent-mark: 32.098/55.919 secs] [Times: user=32.19 sys=1.54, real=55.91 secs]

(concurrent mode failure): 8270889K->1474450K(9437184K), 27.2265650 secs] 9074498K->1474450K(10380928K), [CMS Perm : 64992K->63114K(108020K)], 34.7809080 secs] [Times: user=6.10 sys=0.21, real=34.78 secs]

这里的问题类似，不赘述。这是另一种情况下发生在CMS-concurrent-abortable-preclean阶段：

2015-07-23T06:24:47.450-0400: [GC [1 CMS-initial-mark: 3938781K(5973632K)] 3998846K(6126976K), 0.0030340 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

2015-07-23T06:24:47.546-0400: [CMS-concurrent-mark: 0.093/0.093 secs] [Times: user=0.27 sys=0.01, real=0.09 secs]

2015-07-23T06:24:47.559-0400: [CMS-concurrent-preclean: 0.013/0.013 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]

2015-07-23T06:24:47.665-0400: [GC [ParNew2015-07-23T06:24:47.675-0400: [CMS-concurrent-abortable-preclean: 0.012/0.116 secs] [Times: user=0.16 sys=0.02, real=0.11 secs]

(promotion failed): 133502K->140562K(153344K), 0.0393600 secs][CMS (concurrent mode failure): 3948765K->479672K(5973632K), 1.9491860 secs] 4072283K->479672K(6126976K), [CMS Perm : 62974K->62509K(108776K)], 1.9886830 secs] [Times: user=0.62 sys=0.00, real=1.99 secs]

这里ParNew发生时正在执行CMS-concurrent-abortable-preclean，而在结束时发生promotion failed，同时因为碎片问题发生concurrent mode failure，因而出现Full GC。

concurrent mode failure除了和promotion failed同时发生，我在想会不会出现这样的场景：CMS整个生命周期分成多个步骤，在这个过程中由于有其他新增的内存需要分配，但是没有足够多的空间分配，因而产生concurrent mode failure的情况呢？这个在之前出现OOM的时候找到过一个类似的，虽然它之前是因为ParNew promotion failed，产生Full GC，然后在Full GC过程中发生的。即如果是这种情况，一般代表内存不够用，需要增加内存空间。

2015-07-30T11:12:38.469+0900: [GC [ParNew (promotion failed): 941415K->941415K(943744K), 0.0385590 secs] 9771224K->9867504K(10380928K), 0.0387350 secs] [Times: user=0.38 sys=0.00, real=0.04 secs]

GC locker: Trying a full collection because scavenge failed

2015-07-30T11:12:38.508+0900: [Full GC [CMS2015-07-30T11:12:38.685+0900: [CMS-concurrent-sweep: 0.863/0.911 secs] [Times: user=5.14 sys=0.32, real=0.91 secs]

(concurrent mode failure): 8926088K->8485034K(9437184K), 5.7188070 secs] 9867504K->8485034K(10380928K), [CMS Perm : 65574K->65559K(110780K)], 5.7189380 secs] [Times: user=5.70 sys=0.00, real=5.71 secs]

虽然分析了那么多，还有一个疑问没能解决，对这个问题的调节方法还是一样的：1. 降低CMS GC的阈值；2. 提前减少Old Gen中的碎片，即让CMS GC做整理。这里不再赘述。

最后，我们可以看看其他的调节方式：

1. 我们知道CMS收集器很多过程是并发进行的，因而我们可以控制并发线程的个数：-XX:ParallelCMSThreads=4，我们采用的值是4，和ParNew相同。CMS默认的回收线程数是(CPU个数+3)/4。

2. 在历史上还出现过增量式并发收集器(Incremental Concurrent Mark Sweep，i-CMS)。因为对少于4个CPU的时候，如果GC占用一般左右的CPU资源，会影响用户线程的吞吐量，因而增量式并发收集器的思想是在并发标记和并发清理时让用户线程和GC线程交替运行以减少GC占用太多的资源，特别是在只有一个CPU的情况下，即使在CMS并发阶段，还是会产生STW的现象，因而可以使用i-CMS来避免这种情况。然而i-CMS已经不再推荐使用，具体可以参考这里。大概的原因是现在已经很少只有一个CPU的硬件了，而且i-CMS在线程切换时会花费更多的资源和时间，它更加复杂，有更多的参数，难以调节，会产生更多的碎片。

3. 可以简单介绍一下CMS的整个过程(还可以参考这里，或者这里，虽然这里用的例子是1.4.2的版本，我用的是1.6.30，会有一些区别)。以一个正常的CMS为例：

2015-07-21T22:17:20.667-0400: [GC [1 CMS-initial-mark: 7462216K(9437184K)] 7583692K(10380928K), 0.0223830 secs] [Times: user=0.02 sys=0.00, real=0.03 secs]

2015-07-21T22:17:21.055-0400: [CMS-concurrent-mark: 0.365/0.365 secs] [Times: user=1.75 sys=0.03, real=0.36 secs]

2015-07-21T22:17:21.075-0400: [CMS-concurrent-preclean: 0.020/0.020 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]

2015-07-21T22:17:23.851-0400: [CMS-concurrent-abortable-preclean: 1.586/2.776 secs] [Times: user=5.60 sys=0.10, real=2.78 secs]

2015-07-21T22:17:23.852-0400: [GC[YG occupancy: 679011 K (943744 K)][Rescan (parallel) , 0.1319540 secs][weak refs processing, 0.0001560 secs] [1 CMS-remark: 7511697K(9437184K)] 8190709K(10380928K), 0.1321850 secs] [Times: user=0.46 sys=0.01, real=0.13 secs]

2015-07-21T22:17:30.242-0400: [CMS-concurrent-sweep: 6.004/6.258 secs] [Times: user=11.89 sys=0.17, real=6.26 secs]

2015-07-21T22:17:30.261-0400: [CMS-concurrent-reset: 0.018/0.018 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]

1 CMS-initial-mark：初始标记标记阶段，STW，CMS起始点，标记所有Root对象直接可达的对象，7462216K是CMS触发时Old Gen的内存大小，7583692K是Old Gen＋Young Gen的内存大小。

CMS-concurrent-mark：重新标记阶段，和用户线程同时处理，遍历初始标记出来的对象的所有直接或间接可达对象。CPU时间0.365s，总共0.365s(wall time)。这里times时间不是那么准确，因为起于该阶段的开始，但是中间可能包含其他的事情，如用户线程的执行影响等。

CMS-concurrent-preclean：preclean阶段，这个阶段依然和用户线程同时处理，它会继续查看在重新标记阶段新产生的对象：从Young Gen promote上来的对象，新分配的对象，或被修改的对象。这个阶段主要用于减少下一次重新标记(remark)的时间，因为重新标记会STW。CPU时间0.020s，总共0.020s(wall time)。

CMS-concurrent-abortable-preclean：可中断的preclean阶段，和用户线程同时处理，当preclean已经结束的时候就可以开始remark了，然而如果这样设计，由于CMS-concurrent-preclean和用户线程一起运行，当它结束的时候，Young Gen已经使用了很多了，但是这里面有很多是可以回收的，为了提升效率就可以先ParNew GC回收掉多余的对象，然后就会接着执行remark，就可以减少remark的时间；而如果Young Gen使用的很少，就可以立即启动remark过程；而如果介于之间，就可以先等待一会让eden占用一些空间后再启动remark，从而将ParNew GC的STW和remark的STW错分开。因而CMS的设计者就想出remark的执行时机还依赖于eden的使用情况(因为新对象总是先分配到eden空间)，即通过两个变量来控制：CMSScheduleRemarkEdenSize和CMSScheduleRemarkEdenPenetration，它们的默认值分别是2M和50%，表示在CMS-concurrent-preclean结束后，如果eden只使用了少于2M，则直接启动remark；如果超过2M，但没有超过50%，则先启动CMS-concurrent-abortable-preclean，直到eden的使用率超过了50%，然后启动remark过程，这样就保证了remark和ParNew GC中间会有一定的时间间隔；如果已经超过了50%，就等待下次ParNew GC完成，然后再做remark？貌似只有这样才能解释的通这些日志，当remark阶段准备好后它可以随时被中断，它的中断不是错。如这种日志：

2015-06-16T03:15:21.471-0400: [CMS-concurrent-preclean: 0.030/0.031 secs] [Times: user=0.05 sys=0.00, real=0.03 secs]

CMS: abort preclean due to time 2015-06-16T03:15:26.659-0400: [CMS-concurrent-abortable-preclean: 3.351/5.187 secs] [Times: user=3.50 sys=0.04, real=5.19 secs]

2015-06-16T03:15:26.659-0400: [GC[YG occupancy: 561249 K (943744 K)][Rescan (parallel) , 0.1650010 secs][weak refs processing, 0.0000680 secs] [1 CMS-remark: 7465008K(9437184K)] 8026257K(10380928K), 0.1651410 secs] [Times: user=0.52 sys=0.00, real=0.16 secs]

这个日志表示preclean结束后，eden的空间在2M和50%之间，因而启动abortable-preclean阶段，直到4.84s后才因为eden超过50%后中断CMS-concurrent-abortable-preclean，并开始remark，实际使用0.16s。

2015-07-03T08:15:21.840-0400: [CMS-concurrent-preclean: 0.019/0.019 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]

2015-07-03T08:15:22.605-0400: [GC [ParNew2015-07-03T08:15:22.636-0400: [CMS-concurrent-abortable-preclean: 0.693/0.795 secs] [Times: user=1.30 sys=0.06, real=0.79 secs]

: 943744K->104832K(943744K), 0.2089320 secs] 8446030K->7838840K(10380928K), 0.2090220 secs] [Times: user=0.60 sys=0.01, real=0.21 secs]

2015-07-03T08:15:22.815-0400: [GC[YG occupancy: 120239 K (943744 K)][Rescan (parallel) , 0.0289020 secs][weak refs processing, 0.0001000 secs] [1 CMS-remark: 7734008K(9437184K)] 7854247K(10380928K), 0.0290690 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]

这个日志表示在CMS-concurrent-preclean结束后，eden使用空间已经超过50%，所以启动abortable-preclean，并在155ms后启动ParNew GC，在ParNew停止31ms后停止CMS-concurrent-abortable-preclean，而remark随后开始，经历30ms结束。

2015-07-30T12:06:22.199+0900: [CMS-concurrent-preclean: 0.007/0.007 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

2015-07-30T12:06:22.199+0900: [GC[YG occupancy: 2534 K (19136 K)][Rescan (parallel) , 0.0016670 secs][weak refs processing, 0.0000110 secs] [1 CMS-remark: 1984060K(3050752K)] 1986594K(3069888K), 0.0017300 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]

这个日志表示preclean结束后eden使用少于2M，因而跳过abortable-preclean，直接开始remark阶段。

1 CMS-remark：重新标记阶段，STW，这里YG occupancy表示该阶段开始时Young Gen的大小，因为这个阶段的时间长短部分依赖于Young Gen的大小；Rescan用于多线程扫描程序停止时存活的对象，花费0.1319540s；weak refs processing用于处理weak reference的情况，花费0.0001s，如果这个阶段花费太长时间，可以打开开关：-XX:+ParallelRefProcEnabled来调节；然后开始重新标记，即重新从Root对象遍历标记存活对象。

CMS-concurrent-sweep：并发清理，和其他线程同时执行，做真正的清理工作，如把可以回收的内存放回空闲列表，合并相邻内存空间等。

CMS-concurrent-reset：重置CMS的状态用于下一次执行。