使用MAT分析GC问题心得

2019-08-09 00:00:00 mat 分析 心得

一直以来使用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 }

上述就是我的测试程序,简单的模拟了生产环境中常见的场景:

  1. 有大量朝生夕死的新生代对象
  2. 有小部分生命周期较长的对象可以晋升到老年代,可以被回收
  3. 有小部分生命周期很长的对象,因为一直有强引用,不能被回收,堆积下来,直至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的对象可以分为三类:

  1. survivor区,tmpList1对象。因为发生这次Young GC时,程序必定运行在62~82行中的某一行,外层循环中的tmpList1对象的强引用还存在。
  2. old区,晋升到old区的tmpList1对象,这部分对象绝大部分强引用已经不存在了,因为我们在外层循环中设置了tmpList1=null
  3. 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之后的堆占用情况。这时堆占用的情况如下:

  1. survivor:16384K
  2. eden:262144.0K,这部分不会体现在gc日志中,因为最后发生最后一次young gc时,eden区会清空。
  3. old区:350210.5K
  4. 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的分析结果如下图:

《使用MAT分析GC问题心得》

结果显示290.6M大小的对象,远小于jstat命令输出的617M。(生产环境中,二者的差异更大)
这就是我以前迷惑的地方,不过这次实验之后都明白了。饼状图中的290.6M的对象指的是通过可达性分析判定为存活的对象,已死的对象不会被统计在这张图中,而是在Overview页中的Unreachable Objects Histogram中,如下图:

《使用MAT分析GC问题心得》

已死对象一共304129656b=290M,加上饼状图中的存活对象290M,一共580M,与jstat输出的617M差别不多。同时,我们可以在unreachable objects列表中看到,第一项byte[]就是我们用于测试而创建的byte数组。

通过这个实验,得出的结论是:
在jmap命令导出堆内存快照时,如果没有加live=true,则MAT内存泄漏分析结果也只统计堆内存中存活的对象,已死的对象在unreachable objects中可以找到,这就解释了为什么mat分析结果饼状图中的对象空间远小于jstat的统计结果。

 

相关文章