使用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的统计结果。
标签：MAT,0.0,regions,CSet,GC,ms,time,心得 来源： https://www.cnblogs.com/mitu2019/p/11245842.html