在 Plumbr 从事 GC 暂停检测相关功能的工做时,我被迫用本身的方式,经过大量文章、书籍和演讲来介绍我所作的工做。在整个过程当中,常常对 Minor、Major、和 Full GC 事件的使用感到困惑。这也是我写这篇博客的缘由,我但愿能清楚地解释这其中的一些疑惑。html
文章要求读者熟悉 JVM 内置的通用垃圾回收原则。堆内存划分为 Eden、Survivor 和 Tenured/Old 空间,代假设和其余不一样的 GC 算法超出了本文讨论的范围。java
从年轻代空间(包括 Eden 和 Survivor 区域)回收内存被称为 Minor GC。这必定义既清晰又易于理解。可是,当发生Minor GC事件的时候,有一些有趣的地方须要注意到:算法
因此 Minor GC 的状况就至关清楚了——每次 Minor GC 会清理年轻代的内存。shell
你们应该注意到,目前,这些术语不管是在 JVM 规范仍是在垃圾收集研究论文中都没有正式的定义。可是咱们一看就知道这些在咱们已经知道的基础之上作出的定义是正确的,Minor GC 清理年轻带内存应该被设计得简单:并发
很不幸,实际上它还有点复杂且使人困惑。首先,许多 Major GC 是由 Minor GC 触发的,因此不少状况下将这两种 GC 分离是不太可能的。另外一方面,许多现代垃圾收集机制会清理部分永久代空间,因此使用“cleaning”一词只是部分正确。oracle
这使得咱们不用去关心究竟是叫 Major GC 仍是 Full GC,你们应该关注当前的 GC 是否中止了全部应用程序的线程,仍是可以并发的处理而不用停掉应用程序的线程。ide
这种混乱甚至内置到 JVM 标准工具。下面一个例子很好的解释了个人意思。让咱们比较两个不一样的工具 Concurrent Mark 和 Sweep collector (-XX:+UseConcMarkSweepGC)在 JVM 中运行时输出的跟踪记录。工具
第一次尝试经过 jstat 输出:优化
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次 Minor GC、2次 Full GC,时间总跨度为50毫秒。经过 jconsole 或者 jvisualvm 这样的基于GUI的工具你能获得一样的结果。ui
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]
在点头赞成这个结论以前,让咱们看看来自同一个 JVM 启动收集的垃圾收集日志的输出。显然- XX : + PrintGCDetails 告诉咱们一个不一样且更详细的故事:
基于这些信息,咱们能够看到12次 Minor GC 后开始有些和上面不同了。没有运行两次 Full GC,这不一样的地方在于单个 GC 在永久代中不一样阶段运行了两次:
因此,正如咱们从垃圾回收日志中所看到的那样,实际上只是执行了 Major GC 去清理老年代空间而已,而不是执行了两次 Full GC。
若是你是后期作决 定的话,那么由 jstat 提供的数据会引导你作出正确的决策。它正确列出的两个暂停全部事件的状况,致使全部线程中止了共计50ms。可是若是你试图优化吞吐量,你会被误导的。清 单只列出了回收初始标记和最终 Remark 阶段,jstat的输出看不到那些并发完成的工做。
考虑到这种状况,最好避免以 Minor、Major、Full GC 这种方式来思考问题。而应该监控应用延迟或者吞吐量,而后将 GC 事件和结果联系起来。
随着这些 GC 事件的发生,你须要额外的关注某些信息,GC 事件是强制全部应用程序线程中止了仍是并行的处理了部分事件。
原文连接: javacodegeeks 翻译: ImportNew.com - 光光头去打酱油
译文连接: http://www.importnew.com/15820.html