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月左右發佈