使用MAT分析GC问题心得
2019-08-16 11:09:04来源：博客园 阅读 ()
使用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的统计结果。
原文链接:https://www.cnblogs.com/mitu2019/p/11245842.html
如有疑问请与原作者联系
标签：
版权申明：本站文章部分自网络，如有侵权，请联系：west999com@outlook.com
特别注意：本站所有转载文章言论不代表本站观点，本站所提供的摄影照片，插画，设计作品，如需使用，请与原作者联系，版权归原作者所有
下一篇：win10下JDK8的安装与配置
相关文章
- 聊聊 OAuth 2.0 的 token expire_in 使用 2020-06-08
- 为什么阿里巴巴Java开发手册中强制要求接口返回值不允许使用 2020-06-06
- 学习笔记之方法引用 2020-06-06
- idea使用小技巧（一） 2020-06-05
- 用斗地主的实例学会使用java Collections工具类 2020-06-05
IDC资讯： 主机资讯 注册资讯 托管资讯 vps资讯 网站建设
网站运营： 建站经验 策划盈利 搜索优化 网站推广 免费资源
网络编程： Asp.Net编程 Asp编程 Php编程 Xml编程 Access Mssql Mysql 其它
服务器技术： Web服务器 Ftp服务器 Mail服务器 Dns服务器 安全防护
软件技巧： 其它软件 Word Excel Powerpoint Ghost Vista QQ空间 QQ FlashGet 迅雷
网页制作： FrontPages Dreamweaver Javascript css photoshop fireworks Flash
热门词条
最新资讯
热门关注
热门标签