使用MAT分析GC问题心得
一直以来使用Eclipse Memory Analyzer分析线上服务器堆转储快照时，都有一个疑问：为什么MAT分析结果中饼状图中显示的堆空间占用的大小要远小于通过jstat命令输出结果中的堆空间占用大小？(jmap命令中并未加入live=true)
今天通过做实验，了解了其中的原因。
1.测试程序
1 /* 2 -XX:+UseG1GC 3 -Xms1000M 4 -Xmx1000M 5 -XX:MaxGCPauseMillis=10 6 -XX:ParallelGCThreads=4 7 -XX:G1HeapRegionSize=16m 8 -XX:G1ReservePercent=25 9 -XX:MaxTenuringThreshold=15 10 -XX:SurvivorRatio=8 11 -XX:+PrintTenuringDistribution 12 -XX:+PrintGCApplicationStoppedTime 13 -verbose:gc 14 -XX:+PrintGCDetails 15 -XX:+PrintHeapAtGC 16 -XX:+PrintPromotionFailure 17 -XX:+HeapDumpOnOutOfMemoryError 18 -XX:+PrintAdaptiveSizePolicy 19 */ 20 package com.shaou.thinkinjava; 21 22 import java.util.ArrayList; 23 import java.util.List; 24 25 public class TestFullGC { 26 public static void main(String[] args) throws InterruptedException { 27 List<Object> tmpList2 = new ArrayList<>(); 28 while(true) { 29 for (int i = 0; i < 10; i++) { 30 //tmpList1用于模拟生产环境中一些存活周期比较长，能晋升到老年代 31 //而且能被mixed gc回收的对象 32 List<Object> tmpList1 = new ArrayList<>(); 33 tmpList1.add(new _1M()); 34 tmpList1.add(new _1M()); 35 tmpList1.add(new _1M()); 36 tmpList1.add(new _1M()); 37 tmpList1.add(new _1M()); 38 tmpList1.add(new _1M()); 39 tmpList1.add(new _1M()); 40 tmpList1.add(new _1M()); 41 tmpList1.add(new _1M()); 42 tmpList1.add(new _1M()); 43 44 //tmpList2用于模拟生产环境中那些因为bug导致的不能被回收的对象 45 tmpList2.add(new _2M()); 46 tmpList2.add(new _2M()); 47 tmpList2.add(new _2M()); 48 tmpList2.add(new _2M()); 49 tmpList2.add(new _2M()); 50 tmpList2.add(new _2M()); 51 tmpList2.add(new _2M()); 52 tmpList2.add(new _2M()); 53 tmpList2.add(new _2M()); 54 tmpList2.add(new _2M()); 55 /* 56 每次循环，都会有30M的对象进入新生代，这些对象用于触发Young GC, 57 不考虑大对象直接进入老年代、空间分配担保和对象晋升年龄动态判断 58 等因素，15次Young GC之后，tmpList1和tmpList2会晋升到老年代。 59 这个循环用 60 */ 61 for (int j = 0; j < 1000; j++) { 62 new _1M(); 63 new _2M(); 64 new _1M(); 65 new _2M(); 66 new _1M(); 67 new _2M(); 68 new _1M(); 69 new _2M(); 70 new _1M(); 71 new _2M(); 72 new _1M(); 73 new _2M(); 74 new _1M(); 75 new _2M(); 76 new _1M(); 77 new _2M(); 78 new _1M(); 79 new _2M(); 80 new _1M(); 81 new _2M(); 82 Thread.sleep(2); 83 } 84 //释放tmpList1的强引用，让G1有机会回收 85 tmpList1 = null; 86 } 87 } 88 } 89 90 private static class _1M{ 91 private byte[] bytes = new byte[1024*1024]; 92 } 93 94 private static class _2M { 95 private byte[] bytes = new byte[2*1024*1024]; 96 } 97 }
上述就是我的测试程序，简单的模拟了生产环境中常见的场景：
- 有大量朝生夕死的新生代对象
- 有小部分生命周期较长的对象可以晋升到老年代，可以被回收
- 有小部分生命周期很长的对象，因为一直有强引用，不能被回收，堆积下来，直至OOM
我的测试方法是：一边调试运行程序观察GC日志，一边用jstat命令查看整个堆空间占用的情况。
由于我们没有配置InitiatingHeapOccupancyPercent，默认配置是45，代表触发并发标记周期的堆空间占用比例是45%。通过观察gc日志，在整个堆空间占用比例超过450M时，触发了第一次并发标记周期，这是符合预期的。就在这时，我断点暂停了程序的执行，让程序暂停在第77行，以便让堆空间占用的情况不再因为程序继续运行诱发G1的垃圾回收，这样得出的结果更加精确，也更有说服力。gc日志片段如下：
1 2019-07-25T15:48:37.677+0800: [GC pause (G1 Evacuation Pause) (young) 2 Desired survivor size 25165824 bytes, new threshold 15 (max 15) 3 - age 1: 16 bytes, 16 total 4 798.111: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 1, predicted base time: 1.70 ms, remaining time: 8.30 ms, target pause time: 10.00 ms] 5 798.111: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 18 regions, survivors: 1 regions, predicted young region time: 0.03 ms] 6 798.111: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 18 regions, survivors: 1 regions, old: 0 regions, predicted pause time: 1.74 ms, target pause time: 10.00 ms] 7 , 0.0085805 secs] 8 ... 9 [Eden: 288.0M(288.0M)->0.0B(48.0M) Survivors: 16.0M->48.0M Heap: 715.0M(1008.0M)->461.0M(1008.0M)] 10 Heap after GC invocations=908 (full 0): 11 garbage-first heap total 1032192K, used 472064K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 12 region size 16384K, 3 young (49152K), 3 survivors (49152K) 13 Metaspace used 3236K, capacity 4600K, committed 4864K, reserved 1056768K 14 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 15 } 16 [Times: user=0.00 sys=0.00, real=0.01 secs] 17 2019-07-25T15:48:37.686+0800: Total time for which application threads were stopped: 0.0088531 seconds, Stopping threads took: 0.0000196 seconds 18 {Heap before GC invocations=908 (full 0): 19 garbage-first heap total 1032192K, used 521216K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 20 region size 16384K, 6 young (98304K), 3 survivors (49152K) 21 Metaspace used 3236K, capacity 4600K, committed 4864K, reserved 1056768K 22 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 23 2019-07-25T15:48:37.695+0800: [GC pause (G1 Evacuation Pause) (young) 24 Desired survivor size 8388608 bytes, new threshold 1 (max 15) 25 - age 1: 31458016 bytes, 31458016 total 26 798.128: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 256, predicted base time: 2.44 ms, remaining time: 7.56 ms, target pause time: 10.00 ms] 27 798.128: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 3 regions, survivors: 3 regions, predicted young region time: 0.01 ms] 28 798.128: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 3 regions, survivors: 3 regions, old: 0 regions, predicted pause time: 2.46 ms, target pause time: 10.00 ms] 29 798.136: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: occupancy higher than threshold, occupancy: 486539264 bytes, allocation request: 0 bytes, threshold: 475634070 bytes (45.00 %), source: end of GC] 30 , 0.0077178 secs] 31 [Parallel Time: 6.1 ms, GC Workers: 4] 32 [GC Worker Start (ms): Min: 798128.5, Avg: 798128.6, Max: 798128.6, Diff: 0.0] 33 [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.5] 34 [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 35 [Processed Buffers: Min: 0, Avg: 0.5, Max: 1, Diff: 1, Sum: 2] 36 [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 37 [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 38 [Object Copy (ms): Min: 5.1, Avg: 5.5, Max: 5.8, Diff: 0.6, Sum: 22.1] 39 [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 1.1] 40 [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] 41 [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] 42 [GC Worker Total (ms): Min: 6.0, Avg: 6.0, Max: 6.0, Diff: 0.0, Sum: 23.9] 43 [GC Worker End (ms): Min: 798134.5, Avg: 798134.5, Max: 798134.6, Diff: 0.0] 44 [Code Root Fixup: 0.0 ms] 45 [Code Root Purge: 0.0 ms] 46 [Clear CT: 0.0 ms] 47 [Other: 1.6 ms] 48 [Choose CSet: 0.0 ms] 49 [Ref Proc: 1.4 ms] 50 [Ref Enq: 0.0 ms] 51 [Redirty Cards: 0.0 ms] 52 [Humongous Register: 0.0 ms] 53 [Humongous Reclaim: 0.0 ms] 54 [Free CSet: 0.0 ms] 55 [Eden: 48.0M(48.0M)->0.0B(48.0M) Survivors: 48.0M->16.0M Heap: 509.0M(1008.0M)->460.0M(1008.0M)] 56 Heap after GC invocations=909 (full 0): 57 garbage-first heap total 1032192K, used 471042K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 58 region size 16384K, 1 young (16384K), 1 survivors (16384K) 59 Metaspace used 3236K, capacity 4600K, committed 4864K, reserved 1056768K 60 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 61 } 62 [Times: user=0.02 sys=0.00, real=0.01 secs] 63 2019-07-25T15:48:37.703+0800: Total time for which application threads were stopped: 0.0080459 seconds, Stopping threads took: 0.0000189 seconds 64 {Heap before GC invocations=909 (full 0): 65 garbage-first heap total 1032192K, used 520194K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 66 region size 16384K, 4 young (65536K), 1 survivors (16384K) 67 Metaspace used 3236K, capacity 4600K, committed 4864K, reserved 1056768K 68 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 69 798.144: [G1Ergonomics (Concurrent Cycles) initiate concurrent cycle, reason: concurrent cycle initiation requested] 70 2019-07-25T15:48:37.710+0800: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 71 Desired survivor size 8388608 bytes, new threshold 15 (max 15) 72 - age 1: 16 bytes, 16 total 73 798.144: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 1024, predicted base time: 3.65 ms, remaining time: 6.35 ms, target pause time: 10.00 ms] 74 798.144: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 3 regions, survivors: 1 regions, predicted young region time: 0.01 ms] 75 798.144: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 3 regions, survivors: 1 regions, old: 0 regions, predicted pause time: 3.66 ms, target pause time: 10.00 ms] 76 , 0.0020582 secs] 77 ... 78 [Eden: 48.0M(48.0M)->0.0B(48.0M) Survivors: 16.0M->16.0M Heap: 508.0M(1008.0M)->460.0M(1008.0M)] 79 Heap after GC invocations=910 (full 0): 80 garbage-first heap total 1032192K, used 471042K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 81 region size 16384K, 1 young (16384K), 1 survivors (16384K) 82 Metaspace used 3236K, capacity 4600K, committed 4864K, reserved 1056768K 83 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 84 } 85 [Times: user=0.00 sys=0.00, real=0.00 secs] 86 2019-07-25T15:48:37.712+0800: Total time for which application threads were stopped: 0.0023429 seconds, Stopping threads took: 0.0000196 seconds 87 2019-07-25T15:48:37.713+0800: [GC concurrent-root-region-scan-start] 88 {Heap before GC invocations=910 (full 0): 89 garbage-first heap total 1032192K, used 520194K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 90 region size 16384K, 4 young (65536K), 1 survivors (16384K) 91 Metaspace used 3236K, capacity 4600K, committed 4864K, reserved 1056768K 92 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 93 2019-07-25T15:48:37.720+0800: [GC pause (G1 Evacuation Pause) (young) 94 Desired survivor size 8388608 bytes, new threshold 15 (max 15) 95 - age 1: 16 bytes, 16 total 96 2019-07-25T15:48:37.721+0800: [GC concurrent-root-region-scan-end, 0.0080727 secs] 97 2019-07-25T15:48:37.721+0800: 798.154: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 0, predicted base time: 1.94 ms, remaining time: 8.06 ms, target pause time: 10.00 ms] 98 [GC concurrent-mark-start] 99 798.154: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 3 regions, survivors: 1 regions, predicted young region time: 0.02 ms] 100 798.154: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 3 regions, survivors: 1 regions, old: 0 regions, predicted pause time: 1.96 ms, target pause time: 10.00 ms] 101 , 0.0018547 secs] 102 ... 103 [Eden: 48.0M(48.0M)->0.0B(48.0M) Survivors: 16.0M->16.0M Heap: 508.0M(1008.0M)->460.0M(1008.0M)] 104 Heap after GC invocations=911 (full 0): 105 garbage-first heap total 1032192K, used 471042K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 106 region size 16384K, 1 young (16384K), 1 survivors (16384K) 107 Metaspace used 3236K, capacity 4600K, committed 4864K, reserved 1056768K 108 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 109 } 110 [Times: user=0.00 sys=0.00, real=0.00 secs] 111 2019-07-25T15:48:37.722+0800: Total time for which application threads were stopped: 0.0021280 seconds, Stopping threads took: 0.0000189 seconds 112 2019-07-25T15:48:37.729+0800: [GC concurrent-mark-end, 0.0087463 secs] 113 2019-07-25T15:48:37.729+0800: [GC remark 2019-07-25T15:48:37.730+0800: [Finalize Marking, 0.0000725 secs] 2019-07-25T15:48:37.730+0800: [GC ref-proc, 0.0014597 secs] 2019-07-25T15:48:37.731+0800: [Unloading, 0.0007023 secs], 0.0037800 secs] 114 [Times: user=0.00 sys=0.00, real=0.00 secs] 115 2019-07-25T15:48:37.733+0800: Total time for which application threads were stopped: 0.0038536 seconds, Stopping threads took: 0.0000174 seconds 116 2019-07-25T15:48:37.733+0800: [GC cleanup 496M->496M(1008M), 0.0003444 secs] 117 [Times: user=0.00 sys=0.02, real=0.00 secs] 118 2019-07-25T15:48:37.734+0800: Total time for which application threads were stopped: 0.0004418 seconds, Stopping threads took: 0.0000623 seconds 119 {Heap before GC invocations=912 (full 0): 120 garbage-first heap total 1032192K, used 520194K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 121 region size 16384K, 4 young (65536K), 1 survivors (16384K) 122 Metaspace used 3237K, capacity 4600K, committed 4864K, reserved 1056768K 123 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 124 2019-07-25T15:48:37.736+0800: [GC pause (G1 Evacuation Pause) (young) 125 Desired survivor size 8388608 bytes, new threshold 15 (max 15) 126 - age 1: 16 bytes, 16 total 127 798.169: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 1, predicted base time: 1.91 ms, remaining time: 8.09 ms, target pause time: 10.00 ms] 128 798.169: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 3 regions, survivors: 1 regions, predicted young region time: 0.03 ms] 129 798.169: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 3 regions, survivors: 1 regions, old: 0 regions, predicted pause time: 1.94 ms, target pause time: 10.00 ms] 130 798.170: [G1Ergonomics (Mixed GCs) start mixed GCs, reason: candidate old regions available, candidate old regions: 26 regions, reclaimable: 174377608 bytes (16.50 %), threshold: 5.00 %] 131 , 0.0012774 secs] 132 ... 133 [Eden: 48.0M(48.0M)->0.0B(32.0M) Survivors: 16.0M->16.0M Heap: 508.0M(1008.0M)->460.0M(1008.0M)] 134 Heap after GC invocations=913 (full 0): 135 garbage-first heap total 1032192K, used 471042K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 136 region size 16384K, 1 young (16384K), 1 survivors (16384K) 137 Metaspace used 3237K, capacity 4600K, committed 4864K, reserved 1056768K 138 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 139 } 140 [Times: user=0.00 sys=0.00, real=0.00 secs] 141 2019-07-25T15:48:37.737+0800: Total time for which application threads were stopped: 0.0015326 seconds, Stopping threads took: 0.0000268 seconds 142 {Heap before GC invocations=913 (full 0): 143 garbage-first heap total 1032192K, used 503810K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 144 region size 16384K, 3 young (49152K), 1 survivors (16384K) 145 Metaspace used 3237K, capacity 4600K, committed 4864K, reserved 1056768K 146 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 147 2019-07-25T15:48:37.744+0800: [GC pause (G1 Evacuation Pause) (mixed) 148 Desired survivor size 8388608 bytes, new threshold 15 (max 15) 149 - age 1: 16 bytes, 16 total 150 798.177: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 0, predicted base time: 1.76 ms, remaining time: 8.24 ms, target pause time: 10.00 ms] 151 798.177: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2 regions, survivors: 1 regions, predicted young region time: 0.03 ms] 152 798.177: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: predicted time is too high, predicted time: 35.47 ms, remaining time: 0.00 ms, old: 4 regions, min: 4 regions] 153 798.177: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 4 regions, expensive: 4 regions, min: 4 regions, remaining time: 0.00 ms] 154 798.177: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2 regions, survivors: 1 regions, old: 4 regions, predicted pause time: 113.87 ms, target pause time: 10.00 ms] 155 798.184: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 22 regions, reclaimable: 133485128 bytes (12.63 %), threshold: 5.00 %] 156 , 0.0068890 secs] 157 ... 158 [Eden: 32.0M(32.0M)->0.0B(32.0M) Survivors: 16.0M->16.0M Heap: 492.0M(1008.0M)->425.0M(1008.0M)] 159 Heap after GC invocations=914 (full 0): 160 garbage-first heap total 1032192K, used 435202K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 161 region size 16384K, 1 young (16384K), 1 survivors (16384K) 162 Metaspace used 3237K, capacity 4600K, committed 4864K, reserved 1056768K 163 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 164 } 165 [Times: user=0.05 sys=0.00, real=0.01 secs] 166 2019-07-25T15:48:37.751+0800: Total time for which application threads were stopped: 0.0071620 seconds, Stopping threads took: 0.0000200 seconds 167 {Heap before GC invocations=914 (full 0): 168 garbage-first heap total 1032192K, used 467970K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 169 region size 16384K, 3 young (49152K), 1 survivors (16384K) 170 Metaspace used 3237K, capacity 4600K, committed 4864K, reserved 1056768K 171 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 172 2019-07-25T15:48:37.757+0800: [GC pause (G1 Evacuation Pause) (mixed) 173 Desired survivor size 8388608 bytes, new threshold 15 (max 15) 174 - age 1: 16 bytes, 16 total 175 798.190: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 1024, predicted base time: 11.64 ms, remaining time: 0.00 ms, target pause time: 10.00 ms] 176 798.190: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2 regions, survivors: 1 regions, predicted young region time: 0.03 ms] 177 798.190: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: predicted time is too high, predicted time: 27.76 ms, remaining time: 0.00 ms, old: 4 regions, min: 4 regions] 178 798.190: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 4 regions, expensive: 4 regions, min: 4 regions, remaining time: 0.00 ms] 179 798.190: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2 regions, survivors: 1 regions, old: 4 regions, predicted pause time: 122.40 ms, target pause time: 10.00 ms] 180 798.198: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 11.37 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)] 181 798.198: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 18 regions, reclaimable: 99931112 bytes (9.45 %), threshold: 5.00 %] 182 , 0.0080376 secs] 183 ... 184 [Eden: 32.0M(32.0M)->0.0B(32.0M) Survivors: 16.0M->16.0M Heap: 457.0M(1008.0M)->396.0M(1008.0M)] 185 Heap after GC invocations=915 (full 0): 186 garbage-first heap total 1032192K, used 405508K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 187 region size 16384K, 1 young (16384K), 1 survivors (16384K) 188 Metaspace used 3237K, capacity 4600K, committed 4864K, reserved 1056768K 189 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 190 } 191 [Times: user=0.02 sys=0.00, real=0.01 secs] 192 2019-07-25T15:48:37.765+0800: Total time for which application threads were stopped: 0.0083121 seconds, Stopping threads took: 0.0000185 seconds 193 {Heap before GC invocations=915 (full 0): 194 garbage-first heap total 1032192K, used 438276K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 195 region size 16384K, 3 young (49152K), 1 survivors (16384K) 196 Metaspace used 3237K, capacity 4600K, committed 4864K, reserved 1056768K 197 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 198 2019-07-25T15:48:37.768+0800: [GC pause (G1 Evacuation Pause) (mixed) 199 Desired survivor size 8388608 bytes, new threshold 15 (max 15) 200 - age 1: 16 bytes, 16 total 201 798.202: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 1024, predicted base time: 9.46 ms, remaining time: 0.54 ms, target pause time: 10.00 ms] 202 798.202: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2 regions, survivors: 1 regions, predicted young region time: 0.02 ms] 203 798.202: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: predicted time is too high, predicted time: 26.87 ms, remaining time: 0.00 ms, old: 4 regions, min: 4 regions] 204 798.202: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 4 regions, expensive: 4 regions, min: 4 regions, remaining time: 0.00 ms] 205 798.202: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2 regions, survivors: 1 regions, old: 4 regions, predicted pause time: 111.80 ms, target pause time: 10.00 ms] 206 798.210: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 15.03 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)] 207 798.210: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 14 regions, reclaimable: 72668584 bytes (6.88 %), threshold: 5.00 %] 208 , 0.0086066 secs] 209 ... 210 [Eden: 32.0M(32.0M)->0.0B(32.0M) Survivors: 16.0M->16.0M Heap: 428.0M(1008.0M)->376.0M(1008.0M)] 211 Heap after GC invocations=916 (full 0): 212 garbage-first heap total 1032192K, used 385026K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 213 region size 16384K, 1 young (16384K), 1 survivors (16384K) 214 Metaspace used 3237K, capacity 4600K, committed 4864K, reserved 1056768K 215 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 216 } 217 [Times: user=0.00 sys=0.00, real=0.01 secs] 218 2019-07-25T15:48:37.777+0800: Total time for which application threads were stopped: 0.0089955 seconds, Stopping threads took: 0.0000347 seconds 219 {Heap before GC invocations=916 (full 0): 220 garbage-first heap total 1032192K, used 417794K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 221 region size 16384K, 3 young (49152K), 1 survivors (16384K) 222 Metaspace used 3237K, capacity 4600K, committed 4864K, reserved 1056768K 223 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 224 2019-07-25T15:48:37.782+0800: [GC pause (G1 Evacuation Pause) (mixed) 225 Desired survivor size 8388608 bytes, new threshold 15 (max 15) 226 - age 1: 16 bytes, 16 total 227 798.215: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 1024, predicted base time: 7.61 ms, remaining time: 2.39 ms, target pause time: 10.00 ms] 228 798.215: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2 regions, survivors: 1 regions, predicted young region time: 0.02 ms] 229 798.215: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: reclaimable percentage not over threshold, old: 4 regions, max: 7 regions, reclaimable: 47503400 bytes (4.49 %), threshold: 5.00 %] 230 798.215: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 4 regions, expensive: 4 regions, min: 4 regions, remaining time: 0.00 ms] 231 798.215: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2 regions, survivors: 1 regions, old: 4 regions, predicted pause time: 92.36 ms, target pause time: 10.00 ms] 232 798.223: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 20.27 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)] 233 798.223: [G1Ergonomics (Mixed GCs) do not continue mixed GCs, reason: reclaimable percentage not over threshold, candidate old regions: 10 regions, reclaimable: 47503400 bytes (4.49 %), threshold: 5.00 %] 234 , 0.0085148 secs] 235 ... 236 [Eden: 32.0M(32.0M)->0.0B(48.0M) Survivors: 16.0M->16.0M Heap: 408.0M(1008.0M)->358.0M(1008.0M)] 237 Heap after GC invocations=917 (full 0): 238 garbage-first heap total 1032192K, used 366594K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 239 region size 16384K, 1 young (16384K), 1 survivors (16384K) 240 Metaspace used 3237K, capacity 4600K, committed 4864K, reserved 1056768K 241 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 242 } 243 [Times: user=0.00 sys=0.00, real=0.01 secs] 244 245 ... 246 ... 247 2019-07-25T15:48:39.096+0800: [GC pause (G1 Evacuation Pause) (young) 248 Desired survivor size 25165824 bytes, new threshold 15 (max 15) 249 - age 1: 16 bytes, 16 total 250 799.529: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 0, predicted base time: 1.74 ms, remaining time: 8.26 ms, target pause time: 10.00 ms] 251 799.529: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 22 regions, survivors: 1 regions, predicted young region time: 0.04 ms] 252 799.529: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 22 regions, survivors: 1 regions, old: 0 regions, predicted pause time: 1.77 ms, target pause time: 10.00 ms] 253 , 0.0016240 secs] 254 ... 255 [Eden: 352.0M(352.0M)->0.0B(352.0M) Survivors: 16.0M->16.0M Heap: 710.0M(1008.0M)->358.0M(1008.0M)] 256 Heap after GC invocations=946 (full 0): 257 garbage-first heap total 1032192K, used 366594K [0x00000000c1000000, 0x00000000c20001f8, 0x0000000100000000) 258 region size 16384K, 1 young (16384K), 1 survivors (16384K) 259 Metaspace used 3237K, capacity 4600K, committed 4864K, reserved 1056768K 260 class space used 349K, capacity 424K, committed 512K, reserved 1048576K 261 } 262 [Times: user=0.00 sys=0.00, real=0.00 secs]
可以看到，在日志第9行代表的那次Young GC之后，老年代对象和survivor中的对象加起来占用空间大小为461M，这461M的对象可以分为三类：
- survivor区，tmpList1对象。因为发生这次Young GC时，程序必定运行在62~82行中的某一行，外层循环中的tmpList1对象的强引用还存在。
- old区，晋升到old区的tmpList1对象，这部分对象绝大部分强引用已经不存在了，因为我们在外层循环中设置了tmpList1=null
- old区，tmpList2对象，还是存活的，并且随着程序的运行，这个对象占用的空间也在变大
这次Young GC之后，堆占用比例超过了默认的阈值，G1开始并发标记周期；并发标记周期开始后，接着发生了若干次mixed gc；由于有预期停顿时间的限制，这几次mixed gc并不一定能够把所有老年代中已死的tmpList1对象回收干净；gc日志第233行显示，G1统计到这次mixed gc之后，old区可被回收的对象已经很少了(47503400 bytes)，小于G1默认的old区回收的最低阈值5%(这个配置项由G1HeapWastePercent配置)，所以这次mixed gc完成之后，下次就是Young gc了。
日志255行显示，在我暂停程序运行之前，最后一次young gc之后，整个堆空间有358M的对象(注意这些对象有的是存活的，有的已经死了)。
然后，我们对比一下jstat命令的输出结果：
1 C:\Users\yinhao>jstat -gc 8836 5000 2 S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 3 0.0 16384.0 0.0 16384.0 49152.0 0.0 966656.0 15507.0 4864.0 3232.6 512.0 348.7 1 0.011 0 0.000 0.011 4 0.0 16384.0 0.0 16384.0 49152.0 0.0 966656.0 15507.0 4864.0 3232.6 512.0 348.7 1 0.011 0 0.000 0.011 5 0.0 16384.0 0.0 16384.0 49152.0 0.0 966656.0 15507.0 4864.0 3232.6 512.0 348.7 1 0.011 0 0.000 0.011 6 0.0 16384.0 0.0 16384.0 622592.0 376832.0 393216.0 15817.5 4864.0 3234.4 512.0 348.7 34 0.086 0 0.000 0.086 7 0.0 16384.0 0.0 16384.0 622592.0 507904.0 393216.0 48130.5 4864.0 3236.1 512.0 349.2 86 0.211 0 0.000 0.211 8 0.0 16384.0 0.0 16384.0 622592.0 163840.0 393216.0 83970.5 4864.0 3236.1 512.0 349.2 141 0.334 0 0.000 0.334 9 0.0 16384.0 0.0 16384.0 622592.0 360448.0 393216.0 117762.5 4864.0 3236.1 512.0 349.2 197 0.466 0 0.000 0.466 10 0.0 16384.0 0.0 16384.0 589824.0 475136.0 425984.0 150530.5 4864.0 3236.1 512.0 349.2 255 0.592 0 0.000 0.592 11 0.0 16384.0 0.0 16384.0 557056.0 49152.0 458752.0 184322.5 4864.0 3236.1 512.0 349.2 319 0.729 0 0.000 0.729 12 0.0 16384.0 0.0 16384.0 524288.0 98304.0 491520.0 219138.5 4864.0 3236.1 512.0 349.2 385 0.867 0 0.000 0.867 13 0.0 16384.0 0.0 16384.0 491520.0 81920.0 524288.0 251906.5 4864.0 3236.1 512.0 349.2 453 1.017 0 0.000 1.017 14 0.0 16384.0 0.0 16384.0 458752.0 0.0 557056.0 284674.5 4864.0 3236.1 512.0 349.2 528 1.176 0 0.000 1.176 15 0.0 16384.0 0.0 16384.0 425984.0 81920.0 589824.0 318466.5 4864.0 3236.1 512.0 349.2 610 1.335 0 0.000 1.335 16 0.0 16384.0 0.0 16384.0 393216.0 81920.0 622592.0 353282.5 4864.0 3237.0 512.0 349.2 698 1.517 0 0.000 1.517 17 0.0 16384.0 0.0 16384.0 360448.0 65536.0 655360.0 388098.5 4864.0 3237.0 512.0 349.2 794 1.706 0 0.000 1.706 18 0.0 16384.0 0.0 16384.0 311296.0 196608.0 704512.0 420866.5 4864.0 3237.0 512.0 349.2 902 1.926 0 0.000 1.926 19 0.0 16384.0 0.0 16384.0 393216.0 262144.0 622592.0 350210.5 4864.0 3237.1 512.0 349.2 945 2.048 0 0.000 2.048 20 0.0 16384.0 0.0 16384.0 393216.0 262144.0 622592.0 350210.5 4864.0 3237.1 512.0 349.2 945 2.048 0 0.000 2.048 21 0.0 16384.0 0.0 16384.0 393216.0 262144.0 622592.0 350210.5 4864.0 3237.1 512.0 349.2 945 2.048 0 0.000 2.048 22 0.0 16384.0 0.0 16384.0 393216.0 262144.0 622592.0 350210.5 4864.0 3237.1 512.0 349.2 945 2.048 0 0.000 2.048 23 0.0 16384.0 0.0 16384.0 393216.0 262144.0 622592.0 350210.5 4864.0 3237.1 512.0 349.2 945 2.048 0 0.000 2.048 24 0.0 16384.0 0.0 16384.0 393216.0 262144.0 622592.0 350210.5 4864.0 3237.1 512.0 349.2 945 2.048 0 0.000 2.048 25 0.0 16384.0 0.0 16384.0 393216.0 262144.0 622592.0 350210.5 4864.0 3237.1 512.0 349.2 945 2.048 0 0.000 2.048
可以看出jstat输出的统计结果第19行之后，堆空间占用情况就没有再变化，young gc次数也没有再增加，这说明第19行日志的输出结果对应程序暂停运行后整个堆占用的情况，也就是gc日志中最后一次young gc之后的堆占用情况。这时堆占用的情况如下：
- survivor:16384K
- eden:262144.0K,这部分不会体现在gc日志中，因为最后发生最后一次young gc时，eden区会清空。
- old区：350210.5K
- metaspace:3237.1K
这些空间加起来约有617M，去除eden区的256M之后，与gc日志显示的358M大约相同（因为可能在程序暂停前最后一次young gc和jstat输出第19行日志之间的这段时间内，有新分配的对象）。
OK，以上是我们为了验证mat的分析结果做的环境准备，mat分析结果应该和jstat输出结果体现的一致才是正确的。
此时，用jmap命令dump下堆内存快照，不要加live=true参数，加了的话，会触发G1的一次Full GC以达到统计存活对象的目的：
1 jmap -dump:format=b,file=d:/dump7_25.hprof 8836然后用MAT分析导出的堆转储文件，Leak Suspects的分析结果如下图：
结果显示290.6M大小的对象，远小于jstat命令输出的617M。(生产环境中，二者的差异更大)
这就是我以前迷惑的地方，不过这次实验之后都明白了。饼状图中的290.6M的对象指的是通过可达性分析判定为存活的对象，已死的对象不会被统计在这张图中，而是在Overview页中的Unreachable Objects Histogram中，如下图：
已死对象一共304129656b=290M，加上饼状图中的存活对象290M，一共580M，与jstat输出的617M差别不多。同时，我们可以在unreachable objects列表中看到，第一项byte[]就是我们用于测试而创建的byte数组。
通过这个实验，得出的结论是：
在jmap命令导出堆内存快照时，如果没有加live=true,则MAT内存泄漏分析结果也只统计堆内存中存活的对象，已死的对象在unreachable objects中可以找到，这就解释了为什么mat分析结果饼状图中的对象空间远小于jstat的统计结果。
相关文章