聊聊JVM（四）深入理解Major GC, Full GC, CMS

深藏阁楼爱情的钟 2022-06-11 04:30 211阅读 0赞

[聊聊JVM（四）深入理解Major GC, Full GC, CMS][JVM_Major GC_ Full GC_ CMS]

很多人都分不清Major GC, Full GC的概念，事实上我查了下资料，也没有查到非常精确的Major GC和Full GC的概念定义。分不清这两个概念可能就会对这个问题疑惑：Full GC会引起Minor GC吗？

经过一系列的查找和对JVM表现的分析，基本可以给Full GC和Major GC下一个定义了，这篇说一说概念和理由。

这篇文章[Major GCs – Separating Myth from Reality][Major GCs _ Separating Myth from Reality] 基本讨论的也是这个问题，但是它没有给出实际的证明。

我们可以认为Major GC == Full GC，他们是一个概念，就是针对老年代/永久代进行GC。因为取名叫Full就会让人疑惑，到底会不会先Minor GC。事实上Full GC本身不会先进行Minor GC，我们可以配置，让Full GC之前先进行一次Minor GC，因为老年代很多对象都会引用到新生代的对象，先进行一次Minor GC可以提高老年代GC的速度。比如老年代使用CMS时，设置CMSScavengeBeforeRemark优化，让CMS remark之前先进行一次Minor GC。

弄清楚了Full GC本意单纯就是针对老年代了之后，我们再进一步深入理解Full GC的含义。因为CMS主要可以分为initial mark(stop the world), concurrent mark, remark(stop the world), concurrent sweep几个阶段，其中initial mark和remark会stop the world。

在这篇[聊聊JVM（二）说说GC的一些常见概念][JVM_GC] 我们说了一次CMS至少会给Full GC的次数 + 2，**因为Full GC的次数是按照老年代GC时stop the world的次数而定的**。

再来看**Full GC的Time的定义，可以理解它也指的是老年代GC时stop the world的时间**。我们看一个实例来证明一下。

这段日志是我从一个tomcat的JVM GC日志中抓取的，老年代使用了CMS收集器

**\[html\]**  [view plain][]   [copy][view plain]

1.  2014-12-08T17:24:18.514+0800: 77443.326: \[GC \[1 **<****strong****>****<****span** style="color:\#FF0000;"**>**CMS-initial-mark: 1382782K(1843200K)\] 1978934K(4710400K), 0.0702700 secs\] \[Times: user=0.07 sys=0.00, real=0.07 secs\]**</****span****>****</****strong****>**   
2.  2014-12-08T17:24:18.586+0800: 77443.398: \[CMS-concurrent-mark-start\]  
3.  2014-12-08T17:24:19.890+0800: 77444.702: \[CMS-concurrent-mark: 1.206/1.303 secs\] \[Times: user=2.80 sys=0.07, real=1.30 secs\]   
4.  2014-12-08T17:24:19.890+0800: 77444.702: \[CMS-concurrent-preclean-start\]  
5.  2014-12-08T17:24:19.906+0800: 77444.718: \[CMS-concurrent-preclean: 0.015/0.015 secs\] \[Times: user=0.02 sys=0.00, real=0.02 secs\]   
6.  2014-12-08T17:24:19.906+0800: 77444.718: \[CMS-concurrent-abortable-preclean-start\]  
7.   CMS: abort preclean due to time 2014-12-08T17:24:25.181+0800: 77449.993: \[CMS-concurrent-abortable-preclean: 5.241/5.275 secs\] \[Times: user=6.03 sys=0.09, real=5.27 secs\]   
8.  2014-12-08T17:24:25.187+0800: 77449.999: \[GC\[YG occupancy: 749244 K (2867200 K)\]77450.000: \[Rescan (parallel) , 0.0276780 secs\]77450.028: \[weak refs processing, 0.2029030 secs\]  
9.   \[**<****span** style="color:\#FF0000;"**>****<****strong****>**1 CMS-remark: 1382782K(1843200K)\] 2132027K(4710400K), 0.2340660 secs\] \[Times: user=0.43 sys=0.00, real=0.23 secs**</****strong****>****</****span****>**\]   
10. 2014-12-08T17:24:25.424+0800: 77450.236: \[CMS-concurrent-sweep-start\]  
11. 2014-12-08T17:24:27.420+0800: 77452.232: \[CMS-concurrent-sweep: 1.918/1.996 secs\] \[Times: user=2.61 sys=0.05, real=2.00 secs\]   
12. 2014-12-08T17:24:27.421+0800: 77452.233: \[CMS-concurrent-reset-start\]  
13. 2014-12-08T17:24:27.430+0800: 77452.242: \[CMS-concurrent-reset: 0.010/0.010 secs\] \[Times: user=0.01 sys=0.00, real=0.01 secs\]   
14. 2014-12-09T12:45:05.545+0800: 147090.358: \[GC \[**<****span** style="color:\#FF0000;"**>****<****strong****>**1 CMS-initial-mark: 1384080K(1843200K)\] 2013429K(4710400K), 0.0656230 secs\] \[Times: user=0.06 sys=0.00, real=0.07 secs**</****strong****>****</****span****>**\]   
15. 2014-12-09T12:45:05.613+0800: 147090.425: \[CMS-concurrent-mark-start\]  
16. 2014-12-09T12:45:06.848+0800: 147091.660: \[CMS-concurrent-mark: 1.196/1.235 secs\] \[Times: user=2.77 sys=0.03, real=1.23 secs\]   
17. 2014-12-09T12:45:06.849+0800: 147091.661: \[CMS-concurrent-preclean-start\]  
18. 2014-12-09T12:45:06.862+0800: 147091.674: \[CMS-concurrent-preclean: 0.013/0.013 secs\] \[Times: user=0.02 sys=0.00, real=0.02 secs\]   
19. 2014-12-09T12:45:06.862+0800: 147091.674: \[CMS-concurrent-abortable-preclean-start\]  
20.  CMS: abort preclean due to time 2014-12-09T12:45:11.874+0800: 147096.686: \[CMS-concurrent-abortable-preclean: 4.948/5.012 secs\] \[Times: user=6.04 sys=0.10, real=5.01 secs\]   
21. 2014-12-09T12:45:11.882+0800: 147096.694: \[GC\[YG occupancy: 815312 K (2867200 K)\]147096.695: \[Rescan (parallel) , 0.0476710 secs\]147096.743: \[weak refs processing, 0.1565260 secs\]   
22. \[1 **<****span** style="color:\#FF0000;"**>****<****strong****>**CMS-remark: 1384080K(1843200K)\] 2199393K(4710400K), 0.2064660 secs\] \[Times: user=0.48 sys=0.00, real=0.20 secs**</****strong****>****</****span****>**\]   
23. 2014-12-09T12:45:12.091+0800: 147096.903: \[CMS-concurrent-sweep-start\]  
24. 2014-12-09T12:45:14.078+0800: 147098.890: \[CMS-concurrent-sweep: 1.934/1.986 secs\] \[Times: user=2.43 sys=0.04, real=1.99 secs\]   
25. 2014-12-09T12:45:14.078+0800: 147098.890: \[CMS-concurrent-reset-start\]  
26. 2014-12-09T12:45:14.084+0800: 147098.896: \[CMS-concurrent-reset: 0.006/0.006 secs\] \[Times: user=0.00 sys=0.00, real=0.01 secs\]

我把CMS的initial mark和remark的日志都标记了。

我们可以看到总共发生了两次CMS，所以**Full GC的次数应该是4**

**Full GC的时间 = 0.07 secs(第一次initial mark)+ 0.23 secs(第一次remark) + 0.07 secs(第二次initial mark) + 0.20 secs(第二次remark) = 0.57s**

用jstat -gc 得到的时间Full GC的次数和时间也是吻合的。

![Center][]

所以jstat是[Java][]官方提供的工具，所以我们可以说得出的结论是和官方的一致的。

下面是Visual GC的截图，看Old Gen的统计数据： 4 collections, 576.421ms

![Center 1][]

再来看一个更加直接的例子，从OpenJDK里面找线索：

这段代码来自openjdk/hotspot/src/share/vm/services/memoryService.cpp，从代码中可以看到JVM使用了一个\_fullGC的布尔值来表示是否是Full GC

DefNew, ParNew, ASParNew都是新生代的收集器[算法][Link 1]，当使用它们时，\_fullGC = false

MarkSweepCompact(Serial Old收集器)， ConcurrentMarkSweep(CMS), ASConcurrentMarkSweep时\_fullGC = true。所以只有收集老年代的时候，才算Full GC

![Center 2][]

![Center 3][]

我们可以安全的说：

**1. Full GC == Major GC指的是对老年代/永久代的stop the world的GC**

**2. Full GC的次数 = 老年代GC时 stop the world的次数**

**3. Full GC的时间 = 老年代GC时 stop the world的总时间**

**4. CMS 不等于Full GC，我们可以看到CMS分为多个阶段，只有stop the world的阶段被计算到了Full GC的次数和时间，而和业务线程并发的GC的次数和时间则不被认为是Full GC**

我们可以看到正常的CMS的stop the world的时间很短，都是在几十到几百ms的级别，对Full GC的时间影响很小。但是有时候我们用jstat看到的Full GC的时间很长。比如下面这个例子，和上面的Tomcat是同一个应用，只是是我调优之前的数据。

![Center 4][]

我们看到调优之前的Full GC的评价时间 = 1188 / 223 = 5秒，也就是说单次Full GC的stop the world的时间达到了5s! 进一步分析日志，得到如下日志：

**\[html\]**  [view plain][]   [copy][view plain]

1.  54090.152: \[Full GC (System) 54090.153: \[CMS: 1211220K-**>**1428569K(4096000K), 5.4936890 secs\] 3483935K-**>**1428569K(7168000K),   
2.  \[CMS Perm : 148045K-**>**147921K(262144K)\], 5.4963160 secs\] \[Times: user=5.50 sys=0.00, real=5.50 secs\]   
3.  57696.218: \[Full GC (System) 57696.219: \[CMS: 1513461K-**>**1213731K(4096000K), 4.7293810 secs\] 3283076K-**>**1213731K(7168000K),   
4.  \[CMS Perm : 148019K-**>**147881K(262144K)\], 4.7317730 secs\] \[Times: user=4.73 sys=0.00, real=4.74 secs\]   
5.  61301.483: \[Full GC (System) 61301.484: \[CMS: 1288630K-**>**968887K(4096000K), 4.5720170 secs\] 2466308K-**>**968887K(7168000K),   
6.  \[CMS Perm : 147996K-**>**147835K(262144K)\], 4.5743720 secs\] \[Times: user=4.57 sys=0.00, real=4.57 secs\]   
7.  64906.588: \[Full GC (System) 64906.590: \[CMS: 1026456K-**>**1568407K(4096000K), 5.0347600 secs\] 3769961K-**>**1568407K(7168000K),   
8.  \[CMS Perm : 148004K-**>**147903K(262144K)\], 5.0373410 secs\] \[Times: user=5.02 sys=0.00, real=5.04 secs\]   
9.  68512.160: \[Full GC (System) 68512.161: \[CMS: 1631217K-**>**838700K(4096000K), 4.7239290 secs\] 2552874K-**>**838700K(7168000K),   
10. \[CMS Perm : 148017K-**>**147829K(262144K)\], 4.7261610 secs\] \[Times: user=4.72 sys=0.00, real=4.72 secs\]   
11. 72117.421: \[Full GC (System) 72117.423: \[CMS: 905025K-**>**1529502K(4096000K), 5.3562640 secs\] 3556285K-**>**1529502K(7168000K),   
12. \[CMS Perm : 148049K-**>**147945K(262144K)\], 5.3587790 secs\] \[Times: user=5.36 sys=0.00, real=5.36 secs\]

我们看到是System.gc引起的Full GC，而老年代的GC时间到达了5秒多，它显示的是CMS，但是实际上不是CMS并发的收集器，而是CMS发生了concurrent mode fail之后退化成了Serial Old收集器，它是单线程的标记-压缩收集器，所以耗时非常的长。

最后再次强调一下结论:

**1. Full GC == Major GC指的是对老年代/永久代的stop the world的GC**

**2. Full GC的次数 = 老年代GC时 stop the world的次数**

**3. Full GC的时间 = 老年代GC时 stop the world的总时间**

5. Full GC本身不会先进行Minor GC，我们可以配置，让Full GC之前先进行一次Minor GC，因为老年代很多对象都会引用到新生代的对象，先进行一次Minor GC可以提高老年代GC的速度。比如老年代使用CMS时，设置CMSScavengeBeforeRemark优化，让CMS remark之前先进行一次Minor GC。

[JVM_Major GC_ Full GC_ CMS]: http://blog.csdn.net/iter_zc/article/details/41825395
[Major GCs _ Separating Myth from Reality]: http://apmblog.compuware.com/2011/03/10/major-gcs-separating-myth-from-reality/
[JVM_GC]: http://blog.csdn.net/iter_zc/article/details/41802365
[view plain]: http://blog.csdn.net/iter_zc/article/details/41825395#
[Center]: /images/20220611/b866711475d94d9fbe463e02e2dd6222.png
[Java]: http://lib.csdn.net/base/java
[Center 1]: /images/20220611/9dd5a340e11b42a5b1ac660038f41260.png
[Link 1]: http://lib.csdn.net/base/datastructure
[Center 2]: /images/20220611/cac6f7ef41fe482bbdde1440dcc1b42b.png
[Center 3]: /images/20220611/c4848964ee9f4317ac14fbb48098be95.png
[Center 4]: /images/20220611/a6c9b1ce459b4d5b97a8cf845592d0d7.png