在 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