While working with the GC pause detection functionality in Plumbr I was forced to work my way through loads of articles, books and presentations about the subject. Throughout the journey, I was repeatedly confused about the (mis)use of the Minor, Major and Full GC events. This led to this blog post where I hope I manage to clear some of this confusion.html
在 Plumbr 从事 GC 暂停检测相关功能的工做时,我被迫用本身的方式,经过大量文章、书籍和演讲来介绍我所作的工做。在整个过程当中,常常对 Minor、Major、和 Full GC 事件的使用感到困惑。这也是我写这篇博客的缘由,我但愿能清楚地解释这其中的一些疑惑。java
The post expects the reader to be familiar with generic garbage collection principles built into the JVM. Division of Heap into Eden, Survivor and Tenured/Old spaces, generational hypothesis and different GC algorithms are beyond the scope of this post.算法
文章要求读者熟悉 JVM 内置的通用垃圾回收原则。堆内存划分为 Eden、Survivor 和 Tenured/Old 空间,代假设和其余不一样的 GC 算法超出了本文讨论的范围。bash
Collecting garbage from Young space (consisting of Eden and Survivor spaces) is called a Minor GC. This definition is both clear and uniformly understood. But there are still some interesting take-aways you should be aware of when dealing with Minor Garbage Collection events:并发
从年轻代空间(包括 Eden 和 Survivor 区域)回收内存被称为 Minor GC。这必定义既清晰又易于理解。可是,当发生Minor GC事件的时候,有一些有趣的地方须要注意到:oracle
So with Minor GC the situation was rather clear – every Minor GC cleans the Young generation.app
因此 Minor GC 的状况就至关清楚了——每次 Minor GC 会清理年轻代的内存。ide
One should notice that there is no formal definitions present for those terms. Neither in JVM specification nor in the Garbage Collection research papers. But on the first glance, building these definitions on top of what we know to be true about Minor GC cleaning Young space should be simple:工具
你们应该注意到,目前,这些术语不管是在 JVM 规范仍是在垃圾收集研究论文中都没有正式的定义。可是咱们一看就知道这些在咱们已经知道的基础之上作出的定义是正确的,Minor GC 清理年轻带内存应该被设计得简单:post
Unfortunately it is a bit more complex and confusing. To start with – many Major GCs are triggered by Minor GCs, so separating the two is impossible in many cases. On the other hand – many modern garbage collections perform cleaning the Tenured space partially, so again, using the term “cleaning” is only partially correct.
不幸的是这些有点复杂,难于解释。首先,Minor GC触发Major GC,在不少情形下,将这二者分开是不可能的。另外一方面,许多现代垃圾收集平台倾向于清理Tenured区,所以,用“cleaning”术语仅仅是部分正确。
This leads us to the point where instead of worrying whether the GC is called Major or Full GC, you should focus to finding out whether the GC at hand stopped all the application threads or was it able to progress concurrently with the application threads.
这使得咱们不用去关心究竟是叫 Major GC 仍是 Full GC,你们应该关注当前的 GC 是否中止了全部应用程序的线程,仍是可以并发的处理而不用停掉应用程序的线程。
This confusion is even built right into the JVM standard tools. What I mean by that is best explained via an example. Lets compare the output of two different tools tracing the GC on a JVM running with Concurrent Mark and Sweep collector (-XX:+UseConcMarkSweepGC)
GC不管被称做Major GC仍是Full GC,你应该搞清楚不管GC中止全部的应用线程仍是它能够和应用线程同时进行。
First attempt is to get the insight via the jstat output:
第一次尝试经过 jstat 输出:
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
This snippet is extracted from the first 17 seconds after the JVM was launched. Based on this information we could conclude that after 12 Minor GC runs two Full GC runs were performed, spanning 50ms in total. You would get the same confirmation via GUI-based tools, such as thejconsole or jvisualvm.
这个片断是 JVM 启动后第17秒提取的。基于该信息,咱们能够得出这样的结果,运行了12次 Minor GC、2次 Full GC,时间总跨度为50毫秒。经过 jconsole 或者 jvisualvm 这样的基于GUI的工具你能获得一样的结果。
Before nodding to this conclusion, lets look at to the output of the garbage collection logs gathered from the same JVM launch. Apparently -XX:+PrintGCDetails tells us a different and more detailed story:
在点头赞成这个结论以前,让咱们看看来自同一个 JVM 启动收集的垃圾收集日志的输出。显然- 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]
Based on this information we can see that indeed after 12 Minor GC runs “something different” started happening. But instead two Full GC runs, this “different thing” was in reality just a single GC running in Tenured generation consisting of different phases:
基于这些信息,咱们能够看到12次 Minor GC 后开始有些和上面不同了。没有运行两次 Full GC,这不一样的地方在于单个 GC 在永久代中不一样阶段运行了两次:
So what we see from the actual garbage collection logs is that – instead two Full GC operations, just one Major GC cleaning Old space was actually executed.
因此,正如咱们从垃圾回收日志中所看到的那样,实际上只是执行了 Major GC 去清理老年代空间而已,而不是执行了两次 Full GC。
If you were after latency then making the decisions based upon the data revealed by jstat would have led you towards correct decisions. It correctly listed the two stop-the-world events totaling 50ms affecting the latency for all the active threads at that very moment. But if you were trying to optimize for throughput, you would have been misguided – listing just the stop-the-world initial mark and final remark phases, the jstat output completely hides the concurrent work being done.
若是你是后期作决 定的话,那么由 jstat 提供的数据会引导你作出正确的决策。它正确列出的两个暂停全部事件的状况,致使全部线程中止了共计50ms。可是若是你试图优化吞吐量,你会被误导的。清 单只列出了回收初始标记和最终 Remark 阶段,jstat的输出看不到那些并发完成的工做。
Considering the situation, it is best to even avoid thinking in terms of Minor, Major or Full GC. Instead, monitor your application for latency or throughput and link the GC events to the results.
考虑到这种状况,最好避免以 Minor、Major、Full GC 这种方式来思考问题。而应该监控应用延迟或者吞吐量,而后将 GC 事件和结果联系起来。
Along with these events, you need to have the information whether the particular GC event forced all the application threads to stop or was part of the event handled concurrently.
随着这些 GC 事件的发生,你须要额外的关注某些信息,GC 事件是强制全部应用程序线程中止了仍是并行的处理了部分事件。
If you enjoyed the content – this is the example chapter from our Garbage Collection Handbook. Entire handbook is about to release during March 2015.
若是你喜欢这篇咱们垃圾回收手册的示例篇,那么请关注一下,整个教程将在2015年3月左右发布