一次CMS GC问题排查过程（理解原理+读懂GC日志）

桃扇骨 2022-02-21 16:54 286阅读 0赞

# 一次CMS GC问题排查过程（理解原理+读懂GC日志） #

这个是之前处理过的一个线上问题，处理过程断断续续，经历了两周多的时间，中间各种尝试，总结如下。这篇文章分三部分：

1、问题的场景和处理过程；2、GC的一些理论东西；3、看懂GC的日志

**先说一下问题吧**

**问题场景：**线上机器在半夜会推送一个700M左右的数据，这个时候有个数据置换的过程，也就是说有700M\*2的数据在heap区域中，线上系统超时比较多，导致了很严重（严重程度就不说了）的问题。

**问题原因：**看日志，系统接口超时的时候，系统出现了FullGC，这个时候stop-the-world了，也就停机了。分析gc的日志，发现有promotion failed，根据FullGC触发的条件，这个时候就会出现FullGC了。日志如下：

<table> 
 <tbody> 
  <tr> 
   <td> <p>1</p> <p>2</p> </td> 
   <td> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T03:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>53.638</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>35333.562</code>&nbsp;<code>: [GC&nbsp;</code>&nbsp;<code>35333.562</code>&nbsp;<code>: [ParNew (promotion failed): 1877376K-&gt;1877376K(1877376K),&nbsp;</code>&nbsp;<code>15.7989680</code>&nbsp;&nbsp;<code>secs]</code>&nbsp;<code>35349.361</code>&nbsp;<code>: [CMS: 2144171K-&gt;2129287K(2146304K),&nbsp;</code>&nbsp;<code>10.4200280</code>&nbsp;&nbsp;<code>sec</code></p> <p><code>s] 3514052K-&gt;2129287K(4023680K), [CMS Perm : 119979K-&gt;118652K(190132K)],&nbsp;</code>&nbsp;<code>26.2193500</code>&nbsp;&nbsp;<code>secs] [Times: user=</code>&nbsp;<code>30.35</code>&nbsp;&nbsp;<code>sys=</code><code>5.19</code>&nbsp;<code>, real=</code>&nbsp;<code>26.22</code>&nbsp;&nbsp;<code>secs]</code></p> </td> 
  </tr> 
 </tbody> 
</table>

**问题解决：**中间调整过几次，先搞了几台机器做了验证，后来逐步推广的。

1、调大heap区，由原来的4g，调整到5g，young区的大小不变，还是2g，这时候old区就由2g变为3g了（这样保证old区有足够的空间）；

2、设置-XX：UseCMSInitiatingOccupancyOnly，其实这个不关这个问题，只是发现半夜CMS进行的有点频繁，就禁止掉了悲观策略；

3、设置CMS区回收的比例，从80%调整到75%，让old区尽早的进行，有足够的空间剩余；

**为什么要有GC（垃圾回收）？ **

JVM通过GC来回收堆和方法区中的内存，GC的基本原理就是找到程序中不再被使用的对象，然后回收掉这些对象占用的内存。

**主要的收集器有哪些？**

引用计数器和跟踪计数器两种。

引用计数器记录对象是否被引用，当计数器为零时，说明对象已经不再被使用，可以进行回收。java中的对象有复杂的引用关系，不是很适合引用计数器，所以sun jdk中并没有实现这种GC方式。

跟踪收集器，全局记录数据的引用状态，基于一定的条件触发。执行的时候，从根集合开始扫描对象的引用关系，主要有复制（copying）、标记-清除（Mark-Sweep）、标记-压缩(Mark-Compact)那种算法。

**跟踪计数器的三种算法简介？**

复制：从根集合搜扫描出存活的对象，然后将存活的对象复制到一块新的未使用的空间中，当要回收的空间中存活的对象较少时，比较高效；

标记清除：从根集合开始扫描，对存活的对象进行标记，比较完毕后，再扫描整个空间中未标记的对象，然后进行回收，不需要对对象进行移动；

标记压缩：标记形式和“标记清除”一样，但是回收不存活的对象后，会把所有存活的对象在内存空间中进行移动，好处是减少了内存碎片，缺点是成本比较高；

**java内存区域的形式是啥样的？**

这里就不再介绍了，之前有一篇文章中专门介绍这个的（ [http://iamzhongyong.iteye.com/blog/1333100][http_iamzhongyong.iteye.com_blog_1333100]）。

**新生代可用的GC？**

新生代中对象存活的时间比较短，因此给予Copying算法实现，Eden区域存放新创建的对象，S0和S1区其中一块用于存放在Minor GC的时候作为复制存活对象的目标空间，另外一块清空。

**串行GC（Serial GC）**比较适合单CPU的情况，可以通过-XX：UseSerialGC来强行制定；

**并行回收GC（Parallel Scavenge）**，启动的时候按照设置的参数来划定Eden/S0/S1区域的大小，但是在运行时，会根据Minor GC的频率、消耗时间来动态调整三个区域的大小，可以用过-XX：UseAdaptiveSizePolicy来固定大小，不进行动态调整；

**并行GC（ParNew）**划分Eden、S1、S0的区域上和串行GC一样。并行GC需要配合旧生代使用CMS GC（这是他和并行回收GC的不同）（如果配置了CMS GC的方式，那么新生代默认采取的就是并行GC的方式）；

**啥时候会触发Minor GC？**

当Eden区域分配内存时，发现空间不足，JVM就会触发Minor GC，程序中System.gc()也可以来触发。

**旧生代可用的GC方式有哪几种？**

串行GC（Serial MSC）、并行GC（Parallel MSC）、并发GC（CMS）；

**关于CMS？**

采用CMS时候，新生代必须使用Serial GC或者ParNew GC两种。CMS共有七个步骤，只有Initial Marking和Final Marking两个阶段是stop-the-world的，其他步骤均和应用并行进行。持久代的GC也采用CMS，通过-XX：CMSPermGenSweepingEnabled -XX：CMSClassUnloadingEnabled来制定。在采用cms gc的情况下，ygc变慢的原因通常是由于old gen出现了大量的碎片。

**为啥CMS会有内存碎片，如何避免？**

由于在CMS的回收步骤中，没有对内存进行压缩，所以会有内存碎片出现，CMS提供了一个整理碎片的功能，通过-XX：UseCompactAtFullCollection来启动此功能，启动这个功能后，默认每次执行Full GC的时候会进行整理（也可以通过-XX：CMSFullGCsBeforeCompaction=n来制定多少次Full GC之后来执行整理），整理碎片会stop-the-world.

**啥时候会触发CMS GC？**

1、旧生代或者持久代已经使用的空间达到设定的百分比时（CMSInitiatingOccupancyFraction这个设置old区，perm区也可以设置）；

2、JVM自动触发(JVM的动态策略，也就是悲观策略)（基于之前GC的频率以及旧生代的增长趋势来评估决定什么时候开始执行），如果不希望JVM自行决定，可以通过-XX：UseCMSInitiatingOccupancyOnly=true来制定；

3、设置了 -XX：CMSClassUnloadingE考虑nabled 这个则考虑Perm区；

**啥时候会触发Full GC？**

一、旧生代空间不足：java.lang.outOfMemoryError：java heap space；

二、Perm空间满：java.lang.outOfMemoryError：PermGen space；

三、CMS GC时出现promotion failed  和concurrent  mode failure（Concurrent mode failure发生的原因一般是CMS正在进行，但是由于old区内存不足，需要尽快回收old区里面的死的java对象，这个时候foreground gc需要被触发，停止所有的java线程，同时终止CMS，直接进行MSC。）；

四、统计得到的minor GC晋升到旧生代的平均大小大于旧生代的剩余空间；

五、主动触发Full GC（执行jmap -histo:live \[pid\]）来避免碎片问题；

**为啥heap小于3g不建议使用CMS GC这种方式？**

[http://hellojava.info/?p=142][http_hellojava.info_p_142] 毕大师的这篇文章讲的很清楚。

1、触发比例不好设置，设置大了，那么剩余的空间就少了很多，设置小了，那old区还没放置多少东西，就要进行回收了；

2、CMS进行的时候，是并行的，也就意味着如果过于频繁的话，会和应用的强占CPU；

3、CMS会有内存 碎片问题；

4、YGC的速率变慢（由于CMS GC的实现原理，导致对象从新生代晋升到旧生代时，寻找哪里能放下的这个步骤比ParallelOld GC是慢一些的，因此就导致了YGC速度会有一定程度的下降。）；

**JVM的悲观策略是啥？**

所谓的悲观策略（ [http://tmalltesting.com/archives/663][http_tmalltesting.com_archives_663] 我们性能测试团队一个同学分析的案例），就是JVM不按照JVM指定的参数来进行CMS GC，而是根据内存情况以及之前回收的方式动态调整，自行进行GC。旧生代剩余的空间（available）大于新生代中使用的空间（max\_promotion\_in\_bytes），或者大于之前平均晋升的old的大小（av\_promo），返回false。cms gc是每隔一个周期（默认2s）就会做一次这个检查，如果为false，则不执行YGC，而触发cms gc。

**我们经常使用的是啥GC方式？**

针对目前线上机器的情况（8G的物流内存），heap区一般设置在4g或者5g左右，一般是使用CMS GC，这时候：

young区使用ParNew（并行GC），Old+Perm(需要单独设置)使用CMS，整个堆（young+old+perm）使用MSC（（Mark Sweep Compact）是CMS GC算法的Full GC算法,单线程回收整个堆，回收过程有严格的步骤。压缩，所以回收完理论上任何Generation都不会有内存碎片）压缩回收的方式。

**读懂GC日志？**

**基本上都是这种格式：回收前区域占用的大小->回收后区域占用的大小（区域设置的大小），占用的时间**

** **

**1、promotion failed的一段日志**

解释如下：

<table> 
 <tbody> 
  <tr> 
   <td> <p>1</p> <p>2</p> <p>3</p> <p>4</p> <p>5</p> </td> 
   <td> <p><code>1877376K-&gt;1877376K(1877376K),&nbsp;</code>&nbsp;<code>15.7989680</code>&nbsp;&nbsp;<code>secs&nbsp;&nbsp; young区</code></p> <p><code>2144171K-&gt;2129287K(2146304K),&nbsp;</code>&nbsp;<code>10.4200280</code>&nbsp;&nbsp;<code>sec&nbsp;&nbsp;&nbsp;&nbsp; old区情况</code></p> <p><code>3514052K-&gt;2129287K(4023680K)&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; heap区情况</code></p> <p><code>119979K-&gt;118652K(190132K)],&nbsp;</code>&nbsp;<code>26.2193500</code>&nbsp;&nbsp;<code>secs&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; perm区情况&nbsp;</code></p> <p><code>[Times: user=</code>&nbsp;<code>30.35</code>&nbsp;&nbsp;<code>sys=</code>&nbsp;<code>5.19</code>&nbsp;<code>, real=</code>&nbsp;<code>26.22</code>&nbsp;&nbsp;<code>secs]&nbsp;&nbsp;&nbsp; 整个过程的时间消耗</code></p> </td> 
  </tr> 
 </tbody> 
</table>

**2、一段正常的CMS的日志**

<table> 
 <tbody> 
  <tr> 
   <td> <p>1</p> <p>2</p> <p>3</p> <p>4</p> <p>5</p> <p>6</p> <p>7</p> <p>8</p> <p>9</p> <p>10</p> <p>11</p> <p>12</p> <p>13</p> <p>14</p> </td> 
   <td> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>12.819</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38892.743</code>&nbsp;<code>: [GC [</code>&nbsp;<code>1</code>&nbsp;&nbsp;<code>CMS-initial-mark: 1547313K(2146304K)] 1734957K(4023680K),&nbsp;</code>&nbsp;<code>0.1390860</code>&nbsp;&nbsp;<code>secs] [Times: user=</code>&nbsp;<code>0.14</code>&nbsp;&nbsp;<code>sys=</code>&nbsp;<code>0.00</code>&nbsp;<code>, real=</code>&nbsp;<code>0.14</code>&nbsp;&nbsp;<code>secs]</code></p> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>12.958</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38892.883</code>&nbsp;<code>: [CMS-concurrent-mark-start]</code></p> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>19.231</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38899.155</code>&nbsp;<code>: [CMS-concurrent-mark:&nbsp;</code>&nbsp;<code>6.255</code>&nbsp;<code>/</code>&nbsp;<code>6.272</code>&nbsp;&nbsp;<code>secs] [Times: user=</code>&nbsp;<code>8.49</code>&nbsp;&nbsp;<code>sys=</code>&nbsp;<code>1.57</code><code>, real=</code>&nbsp;<code>6.27</code>&nbsp;&nbsp;<code>secs]</code></p> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>19.231</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38899.155</code>&nbsp;<code>: [CMS-concurrent-preclean-start]</code></p> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>19.250</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38899.175</code>&nbsp;<code>: [CMS-concurrent-preclean:&nbsp;</code>&nbsp;<code>0.018</code>&nbsp;<code>/</code>&nbsp;<code>0.019</code>&nbsp;&nbsp;<code>secs] [Times: user=</code>&nbsp;<code>0.02</code>&nbsp;&nbsp;<code>sys=</code><code>0.00</code>&nbsp;<code>, real=</code>&nbsp;<code>0.02</code>&nbsp;&nbsp;<code>secs]</code></p> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>19.250</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38899.175</code>&nbsp;<code>: [CMS-concurrent-abortable-preclean-start]</code></p> <p><code>&nbsp;</code>&nbsp;<code>CMS: abort preclean due to time&nbsp;</code>&nbsp;<code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>25.252</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38905.176</code>&nbsp;<code>: [CMS-concurrent-abortable-preclean:&nbsp;</code>&nbsp;<code>5.993</code>&nbsp;<code>/</code>&nbsp;<code>6.002</code>&nbsp;&nbsp;<code>secs] [Times: user=</code>&nbsp;<code>6.97</code>&nbsp;&nbsp;<code>sys=</code>&nbsp;<code>2.16</code>&nbsp;<code>, real=</code><code>6.00</code>&nbsp;&nbsp;<code>secs]</code></p> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>25.253</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38905.177</code>&nbsp;<code>: [GC[YG occupancy:&nbsp;</code>&nbsp;<code>573705</code>&nbsp;&nbsp;<code>K (</code>&nbsp;<code>1877376</code>&nbsp;&nbsp;<code>K)]</code>&nbsp;<code>38905.177</code>&nbsp;<code>: [Rescan (parallel) ,&nbsp;</code>&nbsp;<code>0.3685690</code>&nbsp;&nbsp;<code>secs]</code>&nbsp;<code>38905.546</code>&nbsp;<code>: [weak refs processing,&nbsp;</code>&nbsp;<code>0.0024100</code>&nbsp;&nbsp;<code>secs]</code>&nbsp;<code>38905.548</code>&nbsp;<code>: [cla</code></p> <p><code>ss unloading,&nbsp;</code>&nbsp;<code>0.0177600</code>&nbsp;&nbsp;<code>secs]</code>&nbsp;<code>38905.566</code>&nbsp;<code>: [scrub symbol &amp; string tables,&nbsp;</code>&nbsp;<code>0.0154090</code>&nbsp;&nbsp;<code>secs] [</code>&nbsp;<code>1</code>&nbsp;&nbsp;<code>CMS-remark: 1547313K(2146304K)] 2121018K(4023680K),&nbsp;</code>&nbsp;<code>0.4229380</code>&nbsp;&nbsp;<code>secs] [Times: user=</code>&nbsp;<code>1.41</code>&nbsp;&nbsp;<code>sys=</code>&nbsp;<code>0.01</code>&nbsp;<code>, real=</code></p> <p><code>0.43</code>&nbsp;&nbsp;<code>secs]</code></p> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>25.676</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38905.601</code>&nbsp;<code>: [CMS-concurrent-sweep-start]</code></p> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>26.436</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38906.360</code>&nbsp;<code>: [CMS-concurrent-sweep:&nbsp;</code>&nbsp;<code>0.759</code>&nbsp;<code>/</code>&nbsp;<code>0.760</code>&nbsp;&nbsp;<code>secs] [Times: user=</code>&nbsp;<code>1.06</code>&nbsp;&nbsp;<code>sys=</code>&nbsp;<code>0.48</code>&nbsp;<code>, real=</code>&nbsp;<code>0.76</code>&nbsp;&nbsp;<code>secs]</code></p> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>26.436</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38906.360</code>&nbsp;<code>: [CMS-concurrent-reset-start]</code></p> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>26.441</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38906.365</code>&nbsp;<code>: [CMS-concurrent-reset:&nbsp;</code>&nbsp;<code>0.005</code>&nbsp;<code>/</code>&nbsp;<code>0.005</code>&nbsp;&nbsp;<code>secs] [Times: user=</code>&nbsp;<code>0.00</code>&nbsp;&nbsp;<code>sys=</code>&nbsp;<code>0.00</code>&nbsp;<code>, real=</code>&nbsp;<code>0.00</code>&nbsp;&nbsp;<code>secs]</code></p> </td> 
  </tr> 
 </tbody> 
</table>

**这个是一个正常的CMS的日志，共分为七个步骤，重点关注initial-mark和remark这两个阶段，因为这两个是停机的。**

A、\[GC \[1 CMS-initial-mark: 1547313K(2146304K)\] 1734957K(4023680K), 0.1390860 secs\] \[Times: user=0.14 sys=0.00, real=0.14 secs\]

各个数据依次表示标记前后old区的所有对象占内存大小和old的capacity，整个JavaHeap（不包括perm）所有对象占内存总的大小和JavaHeap的capacity。

B、2013-11-27T04:00:25.253+0800: 38905.177: \[GC\[YG occupancy: 573705 K (1877376 K)\]38905.177: \[Rescan (parallel) , 0.3685690 secs\]38905.546: \[weak refs processing, 0.0024100 secs\]38905.548: \[class unloading, 0.0177600 secs\]38905.566: \[scrub symbol & string tables, 0.0154090 secs\] \[1 CMS-remark: 1547313K(2146304K)\] 2121018K(4023680K), 0.4229380 secs\] \[Times: user=1.41 sys=0.01, real=0.43 secs\]

Rescan (parallel)表示的是多线程处理young区和多线程扫描old+perm的卡表的总时间， parallel 表示多GC线程并行。

weak refs processing 处理old区的弱引用的总时间，用于回收native memory。

class unloading 回收SystemDictionary消耗的总时间。

**3、一段正常的Young GC的日志**

<table> 
 <tbody> 
  <tr> 
   <td> <p>1</p> <p>2</p> </td> 
   <td> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>11</code>&nbsp;<code>-27T04:</code>&nbsp;<code>00</code>&nbsp;<code>:</code>&nbsp;<code>07.345</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>38887.270</code>&nbsp;<code>: [GC&nbsp;</code>&nbsp;<code>38887.270</code>&nbsp;<code>: [ParNew: 1791076K-&gt;170624K(1877376K),&nbsp;</code>&nbsp;<code>0.2324440</code>&nbsp;&nbsp;<code>secs] 2988366K-&gt;1413629K(4023680K),&nbsp;</code>&nbsp;<code>0.2326470</code>&nbsp;&nbsp;<code>secs] [Times: user=</code>&nbsp;<code>0.80</code>&nbsp;&nbsp;<code>sys=</code>&nbsp;<code>0.00</code>&nbsp;<code>, real=</code>&nbsp;<code>0</code>&nbsp;<code>.</code></p> <p><code>23</code>&nbsp;&nbsp;<code>secs]</code></p> </td> 
  </tr> 
 </tbody> 
</table>

ParNew这个表明是并行的回收方式，具体的分别是young区、整个heap区的情况；

**4、一段通过system.gc产生的FullGC日志**

<table> 
 <tbody> 
  <tr> 
   <td> <p>1</p> </td> 
   <td> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>07</code>&nbsp;<code>-21T17:</code>&nbsp;<code>44</code>&nbsp;<code>:</code>&nbsp;<code>01.554</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>50.568</code>&nbsp;<code>: [Full GC (System)&nbsp;</code>&nbsp;<code>50.568</code>&nbsp;<code>: [CMS: 943772K-&gt;220K(2596864K),&nbsp;</code>&nbsp;<code>2.3424070</code>&nbsp;&nbsp;<code>secs] 1477000K-&gt;220K(4061184K), [CMS Perm : 3361K-&gt;3361K(98304K)],&nbsp;</code>&nbsp;<code>2.3425410</code>&nbsp;&nbsp;<code>secs] [Times: user=</code>&nbsp;<code>2.33</code>&nbsp;&nbsp;<code>sys=</code>&nbsp;<code>0.01</code>&nbsp;<code>, real=</code><code>2.34</code>&nbsp;&nbsp;<code>secs]</code></p> </td> 
  </tr> 
 </tbody> 
</table>

解释如下：

Full GC (System)意味着这是个system.gc调用产生的MSC。

“943772K->220K(2596864K), 2.3424070 secs”表示：这次MSC前后old区内总对象大小，old的capacity及这次MSC耗时。

“1477000K->220K(4061184K)”表示：这次MSC前后JavaHeap内总对象大小，JavaHeap的capacity。

“3361K->3361K(98304K)\], 2.3425410 secs”表示：这次MSC前后Perm区内总对象大小，Perm区的capacity。

**5、一个特殊的GC日志，根据动态计算直接进行的FullGC（MSC的方式）**

<table> 
 <tbody> 
  <tr> 
   <td> <p>1</p> </td> 
   <td> <p><code>2013</code>&nbsp;<code>-</code>&nbsp;<code>03</code>&nbsp;<code>-13T13:</code>&nbsp;<code>48</code>&nbsp;<code>:</code>&nbsp;<code>06.349</code>&nbsp;<code>+</code>&nbsp;<code>0800</code>&nbsp;<code>:&nbsp;</code>&nbsp;<code>7.092</code>&nbsp;<code>: [GC&nbsp;</code>&nbsp;<code>7.092</code>&nbsp;<code>: [ParNew: 471872K-&gt;471872K(471872K),&nbsp;</code>&nbsp;<code>0.0000420</code>&nbsp;&nbsp;<code>secs]</code>&nbsp;<code>7.092</code>&nbsp;<code>: [CMS: 366666K-&gt;524287K(524288K),&nbsp;</code>&nbsp;<code>27.0023450</code>&nbsp;&nbsp;<code>secs] 838538K-&gt;829914K(996160K), [CMS Perm : 3196K-&gt;3195K(131072K)],&nbsp;</code>&nbsp;<code>27.0025170</code>&nbsp;&nbsp;<code>secs]</code></p> </td> 
  </tr> 
 </tbody> 
</table>

ParNew的时间特别短，jvm在minor gc前会首先确认old是不是足够大，如果不够大，这次young gc直接返回，进行MSC。

**参考文章：**

[http://kenwublog.com/docs/java6-jvm-options-chinese-edition.htm][http_kenwublog.com_docs_java6-jvm-options-chinese-edition.htm]   JVM参数大全

[http://tmalltesting.com/archives/663][http_tmalltesting.com_archives_663] 悲观策略

[http://hellojava.info/?p=142][http_hellojava.info_p_142] CMS GC不建议3G的原因

毕玄的《分布式java基础》

[http_iamzhongyong.iteye.com_blog_1333100]: http://www.iteye.com/blog/1333100
[http_hellojava.info_p_142]: http://hellojava.info/?p=142
[http_tmalltesting.com_archives_663]: http://tmalltesting.com/archives/663
[http_kenwublog.com_docs_java6-jvm-options-chinese-edition.htm]: http://kenwublog.com/docs/java6-jvm-options-chinese-edition.htm