转载

Full GC是否真的存在

Published: 03 Mar 2015 Category: GC

在Plumbr这和GC暂停检测打交道的这段日子里，我查阅了与这个主题相关的大量文章，书籍以及资料。在这当中，我经常会对新生代GC, 年老代GC以及Full GC的事件的使用（滥用）感到困惑。于是便有了这篇文章，希望能够清除一些困惑。

本文需要读者对JVM内建的GC相关的常用原理有一定的了解。像eden区，Survivor区以及年老区空间的划分，分代假设（generational hypothesis）以及不同的GC算法就不在本文的讨论范围之内了。

Full GC是否真的存在

新生代GC（Minor GC）

新生代垃圾的回收被称作 Minor GC 。这个定义非常清晰，理解起来也不会有什么歧义。不过当处理新生代GC事件时，还是有一些有意思的东西值得注意的：

只要JVM无法为新创建的对象分配空间，就肯定会触发新生代GC，比方说Eden区满了。因此对象创建得越频繁，新生代GC肯定也更频繁。
一旦内存池满了，它的所有内容就会被拷贝走，指针又将重新归零。因此和经典的标记(Mark)，清除(Sweep)，整理(Compact)的过程不同的是，Eden区和Survivor区的清理只涉及到标记和拷贝。在它们中是不会出现碎片的。写指针始终在当前使用区的顶部。
在一次新生代GC事件中，通常不涉及到年老代。年老代到年轻代的引用被认为是GC的根对象。而在标记阶段中，从年轻代到年老代的引用则会被忽略掉。
和通常所理解的不一样的是，所有的新生代GC都会触发“stop-the-world”暂停，这会中断应用程序的线程。对绝大多数应用而言，暂停的时间是可以忽略不计的。如果Eden区中的大多数对象都是垃圾对象并且永远不会被拷贝到Survivor区/年老代中的话，这么做是合理的。如果恰好相反的话，那么绝大多数的新生对象都不应该被回收，新生代GC的暂停时间就会变得相对较长了。

现在来看新生代GC还是很清晰的—— 每一次新生代GC都会对年轻代进行垃圾清除 。

年老代GC（ajor GC）与Full GC

你会发现关于这两种GC其实并没有明确的定义。JVM规范或者垃圾回收相关的论文中都没有提及。不过从直觉来说，根据新生代GC(Minor GC)清理的是年轻代空间的认识来看，不难得出以下推论（这里应当从英文出发来理解，Minor, Major与Full GC，翻译过来的名称已经带有明显的释义了）：

Major GC 清理的是年老代的空间。
Full GC 清理的是整个堆——包括年轻代与年老代空间

不幸的是这么理解会有一点复杂与困惑。首先——许多年老代GC其实是由新生代GC触发的，因此在很多情况下两者无法孤立来看待。另一方面——许多现代的垃圾回收器会对年老代进行部分清理，因此，使用“清理”这个术语则显得有点牵强。

那么问题就来了，先别再纠结某次GC到底是年老代GC还是Full GC了，你应该关注的是这次GC是否中断了应用线程还是能够和应用线程并发地执行。

即便是在JVM的官方工具中，也存在着这一困扰。通过一个例子来说明应该更容易理解一些。我们用两款工具来跟踪某个运行着CMS回收器的JVM，来比较下它们的输出有什么不同：

首先通过 jstat 的输出来查看下GC的信息：

my-precious: me$ jstat -gc -t 4235 1s

Time S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT     5.7 34048.0 34048.0  0.0   34048.0 272640.0 194699.7 1756416.0   181419.9  18304.0 17865.1 2688.0 2497.6      3    0.275   0      0.000    0.275  6.7 34048.0 34048.0 34048.0  0.0   272640.0 247555.4 1756416.0   263447.9  18816.0 18123.3 2688.0 2523.1      4    0.359   0      0.000    0.359  7.7 34048.0 34048.0  0.0   34048.0 272640.0 257729.3 1756416.0   345109.8  19072.0 18396.6 2688.0 2550.3      5    0.451   0      0.000    0.451  8.7 34048.0 34048.0 34048.0 34048.0 272640.0 272640.0 1756416.0  444982.5  19456.0 18681.3 2816.0 2575.8      7    0.550   0      0.000    0.550  9.7 34048.0 34048.0 34046.7  0.0   272640.0 16777.0  1756416.0   587906.3  20096.0 19235.1 2944.0 2631.8      8    0.720   0      0.000    0.720 10.7 34048.0 34048.0  0.0   34046.2 272640.0 80171.6  1756416.0   664913.4  20352.0 19495.9 2944.0 2657.4      9    0.810   0      0.000    0.810 11.7 34048.0 34048.0 34048.0  0.0   272640.0 129480.8 1756416.0   745100.2  20608.0 19704.5 2944.0 2678.4     10    0.896   0      0.000    0.896 12.7 34048.0 34048.0  0.0   34046.6 272640.0 164070.7 1756416.0   822073.7  20992.0 19937.1 3072.0 2702.8     11    0.978   0      0.000    0.978 13.7 34048.0 34048.0 34048.0  0.0   272640.0 211949.9 1756416.0   897364.4  21248.0 20179.6 3072.0 2728.1     12    1.087   1      0.004    1.091 14.7 34048.0 34048.0  0.0   34047.1 272640.0 245801.5 1756416.0   597362.6  21504.0 20390.6 3072.0 2750.3     13    1.183   2      0.050    1.233 15.7 34048.0 34048.0  0.0   34048.0 272640.0 21474.1  1756416.0   757347.0  22012.0 20792.0 3200.0 2791.0     15    1.336   2      0.050    1.386 16.7 34048.0 34048.0 34047.0  0.0   272640.0 48378.0  1756416.0   838594.4  22268.0 21003.5 3200.0 2813.2     16    1.433   2      0.050    1.484

这段输出是从JVM启动后第17秒开始截取的。从中可以看出，在经过了12次新生代GC后出现了两次Full GC，共耗时50ms。通过GUI的工具也可以获取到同样的信息，比如说 jsonsole 或者是 jvisualvm 。

在接受这一结论前，我们再来看下同样是这次JVM启动后所输出的GC日志。很明显-XX:+PrintGCDetails给我们讲述的是一段截然不同却更为详尽的故事：

java -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC eu.plumbr.demo.GarbageProducer

3.157: [GC (Allocation Failure) 3.157: [ParNew: 272640K->34048K(306688K), 0.0844702 secs] 272640K->69574K(2063104K), 0.0845560 secs] [Times: user=0.23 sys=0.03, real=0.09 secs]  4.092: [GC (Allocation Failure) 4.092: [ParNew: 306688K->34048K(306688K), 0.1013723 secs] 342214K->136584K(2063104K), 0.1014307 secs] [Times: user=0.25 sys=0.05, real=0.10 secs]  ... cut for brevity ... 11.292: [GC (Allocation Failure) 11.292: [ParNew: 306686K->34048K(306688K), 0.0857219 secs] 971599K->779148K(2063104K), 0.0857875 secs] [Times: user=0.26 sys=0.04, real=0.09 secs]  12.140: [GC (Allocation Failure) 12.140: [ParNew: 306688K->34046K(306688K), 0.0821774 secs] 1051788K->856120K(2063104K), 0.0822400 secs] [Times: user=0.25 sys=0.03, real=0.08 secs]  12.989: [GC (Allocation Failure) 12.989: [ParNew: 306686K->34048K(306688K), 0.1086667 secs] 1128760K->931412K(2063104K), 0.1087416 secs] [Times: user=0.24 sys=0.04, real=0.11 secs]  13.098: [GC (CMS Initial Mark) [1 CMS-initial-mark: 897364K(1756416K)] 936667K(2063104K), 0.0041705 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]  13.102: [CMS-concurrent-mark-start] 13.341: [CMS-concurrent-mark: 0.238/0.238 secs] [Times: user=0.36 sys=0.01, real=0.24 secs]  13.341: [CMS-concurrent-preclean-start] 13.350: [CMS-concurrent-preclean: 0.009/0.009 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]  13.350: [CMS-concurrent-abortable-preclean-start] 13.878: [GC (Allocation Failure) 13.878: [ParNew: 306688K->34047K(306688K), 0.0960456 secs] 1204052K->1010638K(2063104K), 0.0961542 secs] [Times: user=0.29 sys=0.04, real=0.09 secs]  14.366: [CMS-concurrent-abortable-preclean: 0.917/1.016 secs] [Times: user=2.22 sys=0.07, real=1.01 secs]  14.366: [GC (CMS Final Remark) [YG occupancy: 182593 K (306688 K)]14.366: [Rescan (parallel) , 0.0291598 secs]14.395: [weak refs processing, 0.0000232 secs]14.395: [class unloading, 0.0117661 secs]14.407: [scrub symbol table, 0.0015323 secs]14.409: [scrub string table, 0.0003221 secs][1 CMS-remark: 976591K(1756416K)] 1159184K(2063104K), 0.0462010 secs] [Times: user=0.14 sys=0.00, real=0.05 secs]  14.412: [CMS-concurrent-sweep-start] 14.633: [CMS-concurrent-sweep: 0.221/0.221 secs] [Times: user=0.37 sys=0.00, real=0.22 secs]  14.633: [CMS-concurrent-reset-start] 14.636: [CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

从以上能够看出，在运行了12次新生代GC后的确出现了一些“不太寻常”的事情。但并不是执行了两次Full GC，这个“不寻常”的事情其实只是在年老代中执行了一次包含了数个阶段的GC而已：

初始标记阶段，从0.0041705 秒或者说4ms的时候开始。这一阶段是一次“stop-the-world”事件，所有的应用线程都被暂停以便进行初始标记。
并发地执行标记和预清理(Preclean)的阶段。这是和应用线程一起并发执行的。
最终标记阶段，从0.0462010秒或者说46毫秒的时候开始。这一阶段也同样是“stop-the-world”的。
并发地进行清除操作。正如名字所说的，这一阶段也无需中断应用线程，可以并发地执行。

因此我们从实际的GC日志中所看到的是这样——其实没有什么两次所谓的Full GC,只有一次清理年老代空间的Major GC而已。

如果你再想想jstat所输出的结果再下结论的话，就能得出正确的结论了。它明确地列出了两次stop-the-world事件，总耗时50ms，这是影响到活跃线程的总的延迟时间。不过如果你想依据这来优化吞吐量的话，你可能就被误导了——jstat只列出了两次stop-the-world的初始标记和最终标记的阶段，它把并发执行的那部分工作给隐藏掉了。