JVM垃圾回收(二)- Minor GC vs Major GC vs Full GC

Minor GC vs Major GC vs Full GC

垃圾回收的活动会清理对内存中的不同区域,这些事件一般被称为Minor,Major以及Full GC events。本章我们会讨论这些清理事件的不同之处,当然,这些差别对我们来说并不是最重要的。

通常来说,对我们更有意义的是:应用是否满足了它的SLA,因为用户会监控应用的latency以及throughput。也只有在这个时候,GC events才与此有了关联。而对于GC事件来说,其中最重要的部分是:它们是否将应用 stop了,以及这个stop持续的时间。

Minor,Major以及Full GC这些术语早已被广泛使用,但是暂时对它们没有一个合适的定义,我们首先从对这三种GC events的介绍入手:

Minor GC

从Young space 做垃圾回收,称为Minor GC。这个定义确实比较清晰并且被广泛接受,但如果进一步对此做解释的话,有以下几点值得注意:

  1. 当JVM无法为一个新对象分配空间时(例如,Eden区域快满了),Minor GC一定会被触发。所以如果分配(allocation)操作越频繁,则Minor GC也会越频繁
  2. 在Minor GC 阶段,Tenured Generally会被忽略掉。从Tenured Generation到Young Generation的引用会被认定为GC roots。从Young Generation 到Tenured Generation的引用在mark 阶段会直接被忽略。
  3. 与普遍观点不同的一点是,Minor GC实际上会触发 stop-the-world pauses,暂停application的线程。对大部分应用来说,如果在Eden中,大部分对象被认为是垃圾,并且不会被复制到Survivor 或 Old 空间的话,应用暂停时间的长度基本可以忽略不计。反之,如果大部分年轻的对象并不会被回收,则Minor GC的暂停会花费更多的时间

Major GC vs Full GC

其实对这些属于其实没有一个官方的定义(无论是JVM中还是GC的研究论文中),不过基于我们刚刚介绍的Minor GC来看的话,对Major GC以及Full GC的定义可以简单的描述为:

  1. Major GC:清理Old空间
  2. Full GC:清理整个堆空间(包括Young 以及 Old 空间)

当然,里面具体的过程会更为复杂,而且大部分Major GC是由Minor GC 触发的,所以在很多情况下也不会将它们分开单独讨论。不过相对于辨别一个GC是Major GC还是Full GC,我们更应该关注的是:当前的GC事件是否暂时停掉了应用的线程,还是说可以与应用中的线程同时并发执行?

这个疑问甚至可以被内建于JVM标准工具上,对此,我们来看一个例子以做进一步解释。我们会使用两个不同的工具来跟踪一个运行了Concurrent Mark and Sweep collector(使用参数 -XX:+UseConcMarkSweepGC)的JVM,并比较它们的输出。

首先我们通过jstat的输出查看一下内部情况:

java -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC com.test.MyApplication

JVM垃圾回收(二)- Minor GC vs Major GC vs Full GC

上面的片段是从一个运行了17s的JVM中获取的,我们可以看到12次Minor GC 后,发生了两次Full GC,持续大约一共50ms左右。你也可以通过基于GUI的工具如 jconsole 或 jvisualvm 查看这些输出。

然后我们看一下从同一个JVM里获取的GC输出日志。可以通过 -XX:+PrintGCDetails 开启GC日志:

java -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC com.test.MyApplication

日志内容可以提供更多相关信息:

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]

根据以上日志内容,我们可以看到在多次Minor GC后,一个与Minor GC不同的事件发生了。但是这里我们并没有看见两轮的Full GC 事件,而仅仅是一轮在Old 空间上发生的GC事件,由多个阶段组成:

  1. Initial Mark 阶段,耗时0.0041705,大约4ms。这个阶段是一个stop-the-world 事件,会暂时停止所有应用线程,以做初始的marking
  2. Markup and Preclean阶段与应用里的线程并行执行
  3. Final Remark 阶段,耗时0.00462010,大约46ms,这个阶段也是一个stop-the-world 事件
  4. Sweep 操作会被并行执行,不会停止应用的线程

所以从实际的垃圾回收日志来看,相对于之前jstat里查看到的两轮Full GC,其实真正发生的只有一次清理Old 空间的Major GC。

不过若单从jstat的输出来看,jstat其实已经将你引入了正确的(优化)决策方向,因为它完整的列出了两次stop-the-world事件(第一次4ms,第二次46ms),这两次事件对当时正在运行的线程产生了一共大约50ms的影响。并且jstat的输出已完全隐藏了并行任务的工作。

References:

https://plumbr.io/java-garbage-collection-handbook

上一篇:Minor GC、Major GC和Full GC之间的区别(转)


下一篇:Fiddler Composer 模拟post请求