### JVM系列筆記目錄 > - 虛擬機器的基礎概念 > - class檔案結構 > - class檔案載入過程 > - jvm記憶體模型 > - JVM常用指令 > - GC與調優 #### 主要內容 分析PS、CMS、G1的回收日誌，目標使大概能讀懂GC日誌。 #### 測試程式 java的版本是1.8，測試思路是用死迴圈中不停分配1M大小的陣列 ，這樣在啟動時候指定較小的您記憶體空間，很快就會產生GC。 ```java import java.util.LinkedList; import java.util.List; public class HelloGC { public static void main(String[] args) { System.out.println("HelloGC!"); List list = new LinkedList(); for(;;) { // 死迴圈中不停分配1M大小的陣列 byte[] b = new byte[1024*1024]; list.add(b); } } } ``` #### PS日誌分析 1. 啟動命令：`java -Xmn10M -Xms40M -Xmx60M -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+Us eParallelGC -XX:+PrintGCDetails HelloGC`。指定JVM醉倒記憶體為60M,初始記憶體為40M,年輕代的大小是10M,`-XX:+UseParallelGC`指定垃圾回收器為PS+PO，`-XX:+PrintGCDetails`打印出詳細的GC回收日誌。 2. 日誌 ``` D:\>java -Xmn10M -Xms40M -Xmx60M -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+UseParallelGC -XX:+PrintGCDetails HelloGC -XX:InitialHeapSize=41943040 -XX:MaxHeapSize=62914560 -XX:MaxNewSize=10485760 -XX:NewSize=10485760 -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCDetails -XX:+UseCompresse dClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC HelloGC! [GC (Allocation Failure) [PSYoungGen: 7292K->784K(9216K)] 7292K->6936K(39936K), 0.0035951 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC (Allocation Failure) [PSYoungGen: 8112K->840K(9216K)] 14264K->14160K(39936K), 0.0034203 secs] [Times: user=0.03 sys=0.06, real=0.00 secs] [GC (Allocation Failure) [PSYoungGen: 8160K->736K(9216K)] 21481K->21224K(39936K), 0.0038512 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC (Allocation Failure) [PSYoungGen: 8059K->832K(9216K)] 28547K->28488K(39936K), 0.0031367 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [Full GC (Ergonomics) [PSYoungGen: 832K->0K(9216K)] [ParOldGen: 27656K->28287K(46080K)] 28488K->28287K(55296K), [Metaspace: 2710K->2710K(1056 768K)], 0.0172805 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] [GC (Allocation Failure) [PSYoungGen: 7325K->224K(8704K)] 35612K->35679K(54784K), 0.0034935 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC (Allocation Failure) [PSYoungGen: 7542K->1248K(8704K)] 42997K->42847K(54784K), 0.0032856 secs] [Times: user=0.00 sys=0.00, real=0.00 secs ] [Full GC (Ergonomics) [PSYoungGen: 1248K->0K(8704K)] [ParOldGen: 41599K->42623K(51200K)] 42847K->42623K(59904K), [Metaspace: 2710K->2710K(105 6768K)], 0.0056374 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] [GC (Allocation Failure) [PSYoungGen: 6278K->1216K(8704K)] 48902K->48960K(59904K), 0.0034283 secs] [Times: user=0.00 sys=0.00, real=0.00 secs ] [Full GC (Ergonomics) [PSYoungGen: 1216K->0K(8704K)] [ParOldGen: 47744K->48768K(51200K)] 48960K->48768K(59904K), [Metaspace: 2710K->2710K(105 6768K)], 0.0044365 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [Full GC (Ergonomics) [PSYoungGen: 6272K->4096K(8704K)] [ParOldGen: 48768K->50816K(51200K)] 55040K->54912K(59904K), [Metaspace: 2710K->2710K( 1056768K)], 0.0060174 secs] [Times: user=0.09 sys=0.02, real=0.01 secs] [Full GC (Ergonomics) [PSYoungGen: 6268K->6144K(8704K)] [ParOldGen: 50816K->50816K(51200K)] 57084K->56960K(59904K), [Metaspace: 2710K->2710K( 1056768K)], 0.0043812 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [Full GC (Allocation Failure) [PSYoungGen: 6144K->6144K(8704K)] [ParOldGen: 50816K->50803K(51200K)] 56960K->56948K(59904K), [Metaspace: 2710K ->2710K(1056768K)], 0.0164153 secs] [Times: user=0.09 sys=0.00, real=0.02 secs] Exception in thread "main" java.lang.OutOfMemoryError: Java heap space at HelloGC.main(HelloGC.java:9) Heap PSYoungGen total 8704K, used 6385K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000) eden space 7168K, 89% used 0x00000000ff600000,0x00000000ffc3c518,0x00000000ffd00000) from space 1536K, 0% used [0x00000000ffd00000,0x00000000ffd00000,0x00000000ffe80000) to space 1536K, 0% used [0x00000000ffe80000,0x00000000ffe80000,0x0000000100000000) ParOldGen total 51200K, used 50803K [0x00000000fc400000, 0x00000000ff600000, 0x00000000ff600000) object space 51200K, 99% used [0x00000000fc400000,0x00000000ff59cfd0,0x00000000ff600000) Metaspace used 2739K, capacity 4486K, committed 4864K, reserved 1056768K class space used 304K, capacity 386K, committed 512K, reserved 1048576K ``` - YGC分析  - FGC分析  - 堆空間分析  #### CMS日誌 回顧一下CMS回收主要4個階段：初始標記、併發標記、最終標記、併發回收。 補充一個Card Table的概念 > 由於做YGC時，需要掃描整個OLD區，效率非常低，所以JVM設計了CardTable， 如果一個OLD區CardTable中某個Card有物件指向Y區，就將它設為Dirty，下次掃描時，只需要掃描Dirty Card。在結構上，Card Table用BitMap來實現。 1. 啟動命令`java -Xmn20M -Xmx20M -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC HelloGC`。引數` -XX:+UseConcMarkSweepGC`指定使用CMS垃圾回收器。 2. 日誌分析 - YGC [GC (Allocation Failure) [ParNew: 6144K->640K(6144K), 0.0265885 secs] 6585K->2770K(19840K), 0.0268035 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] > ParNew：年輕代收集器 > > 6144->640：收集前後的對比 > > （6144）：整個年輕代容量 > > 6585 -> 2770：整個堆的情況 > > （19840）：整個堆大小 - CMS的回收 ``` // 初始標記 //8511 (13696) : 老年代使用（最大） //9866 (19840) : 整個堆使用（最大） [GC (CMS Initial Mark) [1 CMS-initial-mark: 8511K(13696K)] 9866K(19840K), 0.0040321 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] //併發標記 這裡的時間意義不大，因為是併發執行 [CMS-concurrent-mark-start] [CMS-concurrent-mark: 0.018/0.018 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] // 標記Card為Dirty，也稱為Card Marking [CMS-concurrent-preclean-start] [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] //最終標記 STW階段 //YG occupancy:年輕代佔用及容量 //[Rescan (parallel)：STW下的存活物件標記 //weak refs processing: 弱引用處理 //class unloading: 解除安裝用不到的class //scrub symbol(string) table: 官方的解釋cleaning up symbol and string tables which //hold class-level metadata and internalized string respectively //CMS-remark: 8511K(13696K): 階段過後的老年代佔用及容量 //10108K(19840K): 階段過後的堆佔用及容量 [GC (CMS Final Remark) [YG occupancy: 1597 K (6144 K)][Rescan (parallel) , 0.0008396 secs][weak refs processing, 0.0000138 secs][class unloading, 0.0005404 secs][scrub symbol table, 0.0006169 secs][scrub string table, 0.0004903 secs][1 CMS-remark: 8511K(13696K)] 10108K(19840K), 0.0039567 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] // 最終標記 標記已經完成，進行併發清理 [CMS-concurrent-sweep-start] [CMS-concurrent-sweep: 0.005/0.005 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] //重置內部結構，為下次GC做準備 [CMS-concurrent-reset-start] [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] ``` #### G1日誌 回顧一下，G1是分region回收的，有YGC、MixedGC(類似CMS)、FGC。 官方提供了 [Garbage First Garbage Collector Tuning](https://www.oracle.com/technical-resources/articles/java/g1gc.html)， 可以參考。 1. 啟動命令`java -Xms20M -Xmx20M -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC HelloGC`，其中`-XX:+UseG1GC`指定使用G1。 2. 日誌分析 ``` //GC暫停 // (G1 Humongous Allocation) (young) 大物件分配 // initial-mark初始標記，這裡是YGC混合老年代回收MixedGC [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0026947 secs] //這是一個GC執行緒 多執行緒回收的 [Parallel Time: 2.1 ms, GC Workers: 8] [GC Worker Start (ms): Min: 137.2, Avg: 137.2, Max: 137.3, Diff: 0.1] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.4, Max: 0.6, Diff: 0.6, Sum: 3.5] // 更新Rset [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.2] //拷貝存活物件 [Object Copy (ms): Min: 1.1, Avg: 1.2, Max: 1.3, Diff: 0.2, Sum: 9.7] [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8] [GC Worker Other (ms): Min: 0.1, Avg: 0.3, Max: 0.7, Diff: 0.6, Sum: 2.1] [GC Worker Total (ms): Min: 2.0, Avg: 2.0, Max: 2.0, Diff: 0.1, Sum: 16.0] [GC Worker End (ms): Min: 139.2, Avg: 139.3, Max: 139.3, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 0.5 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.1 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.1 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 2048.0K(12.0M)->0.0B(4096.0K) Survivors: 0.0B->1024.0K Heap: 5122.1K(20.0M)->4880.1K(20.0M)] [Times: user=0.00 sys=0.00, real=0.01 secs] // 以下是MixedGC的其它階段 類似CMS [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0008043 secs] [GC concurrent-mark-start] [GC concurrent-mark-end, 0.0001578 secs] [GC remark [Finalize Marking, 0.0001140 secs] [GC ref-proc, 0.0001270 secs] // 解除安裝 [Unloading, 0.0011719 secs], 0.0017205 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] // 清理 [GC cleanup 8034K->8034K(20M), 0.0004763 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] //其它的GC執行緒類似 ...... //無法分配進行FGC [Full GC (Allocation Failure) 9855K->9842K(20M), 0.0029134 secs] [Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->0.0B Heap: 9855.3K(20.0M)->9843.0K(20.0M)], [Metaspace: 2710K->2710K(1056768K)] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC concurrent-mark-abort] Exception in thread "main" java.lang.OutOfMemoryError: Java heap space at HelloGC.main(HelloGC.java:9) // 堆空間的情況 Heap garbage-first heap total 20480K, used 9842K [0x00000000fec00000, 0x00000000fed000a0, 0x0000000100000000) region size 1024K, 1 young (1024K), 0 survivors (0K) Metaspace used 2739K, capacity 4486K, committed 4864K, reserved 1056768K class space used 304K, capacity 386K, committed 512K, reserved 1048576K ``` #### 總結 本篇對PS、CMS、G1的日誌進行了較為詳細的分析，基本可以參照著看懂垃圾回收的的過程。 > 知識分享，轉載請註明出處。學無先後，達者