Poison

HeapDumpAfterFullGC

发表于

GC 日志：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
2022-01-17T13:39:14.399+0800: 920001.780: [GC pause (G1 Evacuation Pause) (young), 0.0109317 secs]
   [Parallel Time: 9.7 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 920001780.8, Avg: 920001781.0, Max: 920001781.3, Diff: 0.5]
      [Ext Root Scanning (ms): Min: 7.4, Avg: 7.9, Max: 8.4, Diff: 1.0, Sum: 15.8]
      [Update RS (ms): Min: 0.8, Avg: 0.9, Max: 1.0, Diff: 0.2, Sum: 1.8]
         [Processed Buffers: Min: 4, Avg: 4.5, Max: 5, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.2, Avg: 0.4, Max: 0.7, Diff: 0.5, Sum: 0.8]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 9.1, Avg: 9.4, Max: 9.6, Diff: 0.5, Sum: 18.7]
      [GC Worker End (ms): Min: 920001790.4, Avg: 920001790.4, Max: 920001790.4, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.1 ms]
   [Eden: 0.0B(102.0M)->0.0B(102.0M) Survivors: 0.0B->0.0B Heap: 2037.9M(2048.0M)->2037.9M(2048.0M)]
 [Times: user=0.02 sys=0.00, real=0.01 secs]
2022-01-17T13:39:14.416+0800: 920001.797: [Full GC (Allocation Failure)  2037M->1195M(2048M), 3.2218960 secs]
   [Eden: 0.0B(102.0M)->0.0B(605.0M) Survivors: 0.0B->0.0B Heap: 2037.9M(2048.0M)->1195.7M(2048.0M)], [Metaspace: 204152K->203357K(1247232K)]
 [Times: user=3.98 sys=0.00, real=3.22 secs]
2022-01-17T13:39:17.638+0800: 920005.020: [GC concurrent-mark-abort]
2022-01-17T13:39:18.323+0800: 920005.704: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.1329421 secs]
   [Parallel Time: 128.8 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 920005705.4, Avg: 920005705.4, Max: 920005705.4, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 8.6, Avg: 8.6, Max: 8.6, Diff: 0.0, Sum: 17.2]
      [Update RS (ms): Min: 47.3, Avg: 47.4, Max: 47.4, Diff: 0.1, Sum: 94.8]
         [Processed Buffers: Min: 227, Avg: 239.5, Max: 252, Diff: 25, Sum: 479]
      [Scan RS (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.2]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 71.8, Avg: 71.8, Max: 71.8, Diff: 0.1, Sum: 143.6]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 127.9, Avg: 127.9, Max: 127.9, Diff: 0.0, Sum: 255.8]
      [GC Worker End (ms): Min: 920005833.3, Avg: 920005833.3, Max: 920005833.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 3.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.5 ms]
   [Eden: 263.0M(605.0M)->0.0B(522.0M) Survivors: 0.0B->43.0M Heap: 1458.7M(2048.0M)->1238.3M(2048.0M)]
 [Times: user=0.26 sys=0.00, real=0.14 secs]


堆内内存使用突然增加，且 FullGC 后释放不多，如 GC 日志中 [Full GC (Allocation Failure) 2037M->1195M(2048M), 3.2218960 secs] 所描述，FullGC 后堆内内存为 1195MB，远大于平时 680MiB 的内存占用，持续一分钟后才恢复。今天先在线上这台实例启用 HeapDumpAfterFullGC 选项，以便线上复现该问题时能够自动发起堆转储，看看内存中具体是什么以及哪些线程在执行。

2022-02-18

今天探测到了该问题，由 Excel 解析导致，单个线程占用的 Retained Heap 为 972954224 字节，即 927MB，关键栈帧如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
http-nio-80-exec-78
  at com.sun.org.apache.xerces.internal.dom.DeferredDocumentImpl.getNodeObject(I)Lcom/sun/org/apache/xerces/internal/dom/DeferredNode; (DeferredDocumentImpl.java:982)
  at com.sun.org.apache.xerces.internal.dom.DeferredDocumentImpl.synchronizeChildren(Lcom/sun/org/apache/xerces/internal/dom/ParentNode;I)V (DeferredDocumentImpl.java:1720)
  at com.sun.org.apache.xerces.internal.dom.DeferredElementNSImpl.synchronizeChildren()V (DeferredElementNSImpl.java:159)
  at com.sun.org.apache.xerces.internal.dom.ParentNode.getFirstChild()Lorg/w3c/dom/Node; (ParentNode.java:228)
  at org.apache.xmlbeans.impl.store.Locale.loadNodeChildren(Lorg/w3c/dom/Node;Lorg/apache/xmlbeans/impl/store/Locale$LoadContext;)V (Locale.java:1402)
  at org.apache.xmlbeans.impl.store.Locale.loadNode(Lorg/w3c/dom/Node;Lorg/apache/xmlbeans/impl/store/Locale$LoadContext;)V (Locale.java:1445)
  at org.apache.xmlbeans.impl.store.Locale.loadNodeChildren(Lorg/w3c/dom/Node;Lorg/apache/xmlbeans/impl/store/Locale$LoadContext;)V (Locale.java:1403)
  at org.apache.xmlbeans.impl.store.Locale.loadNode(Lorg/w3c/dom/Node;Lorg/apache/xmlbeans/impl/store/Locale$LoadContext;)V (Locale.java:1445)
  at org.apache.xmlbeans.impl.store.Locale.loadNodeChildren(Lorg/w3c/dom/Node;Lorg/apache/xmlbeans/impl/store/Locale$LoadContext;)V (Locale.java:1403)
  at org.apache.xmlbeans.impl.store.Locale.loadNode(Lorg/w3c/dom/Node;Lorg/apache/xmlbeans/impl/store/Locale$LoadContext;)V (Locale.java:1445)
  at org.apache.xmlbeans.impl.store.Locale.parseToXmlObject(Lorg/w3c/dom/Node;Lorg/apache/xmlbeans/SchemaType;Lorg/apache/xmlbeans/XmlOptions;)Lorg/apache/xmlbeans/XmlObject; (Locale.java:1385)
  at org.apache.xmlbeans.impl.store.Locale.parseToXmlObject(Lorg/apache/xmlbeans/SchemaTypeLoader;Lorg/w3c/dom/Node;Lorg/apache/xmlbeans/SchemaType;Lorg/apache/xmlbeans/XmlOptions;)Lorg/apache/xmlbeans/XmlObject; (Locale.java:1370)
  at org.apache.xmlbeans.impl.schema.SchemaTypeLoaderBase.parse(Lorg/w3c/dom/Node;Lorg/apache/xmlbeans/SchemaType;Lorg/apache/xmlbeans/XmlOptions;)Lorg/apache/xmlbeans/XmlObject; (SchemaTypeLoaderBase.java:370)
  at org.apache.poi.POIXMLTypeLoader.parse(Ljava/io/InputStream;Lorg/apache/xmlbeans/SchemaType;Lorg/apache/xmlbeans/XmlOptions;)Lorg/apache/xmlbeans/XmlObject; (POIXMLTypeLoader.java:164)
  at org.openxmlformats.schemas.spreadsheetml.x2006.main.WorksheetDocument$Factory.parse(Ljava/io/InputStream;Lorg/apache/xmlbeans/XmlOptions;)Lorg/openxmlformats/schemas/spreadsheetml/x2006/main/WorksheetDocument; (Unknown Source)
  at org.apache.poi.xssf.usermodel.XSSFSheet.read(Ljava/io/InputStream;)V (XSSFSheet.java:226)
  at org.apache.poi.xssf.usermodel.XSSFSheet.onDocumentRead()V (XSSFSheet.java:218)
  at org.apache.poi.xssf.usermodel.XSSFWorkbook.parseSheet(Ljava/util/Map;Lorg/openxmlformats/schemas/spreadsheetml/x2006/main/CTSheet;)V (XSSFWorkbook.java:443)
  at org.apache.poi.xssf.usermodel.XSSFWorkbook.onDocumentRead()V (XSSFWorkbook.java:408)
  at org.apache.poi.POIXMLDocument.load(Lorg/apache/poi/POIXMLFactory;)V (POIXMLDocument.java:169)
  at org.apache.poi.xssf.usermodel.XSSFWorkbook.<init>(Ljava/io/InputStream;)V (XSSFWorkbook.java:300)
  at me.tianshuang.action.Action.batchImport(Ljavax/servlet/http/HttpServletRequest;Lorg/springframework/web/multipart/MultipartFile;)Ljava/lang/String; (Action.java:471)
  at sun.reflect.GeneratedMethodAccessor3808.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; (Unknown Source)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; (DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; (Method.java:498)
  at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke([Ljava/lang/Object;)Ljava/lang/Object; (InvocableHandlerMethod.java:221)
  at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(Lorg/springframework/web/context/request/NativeWebRequest;Lorg/springframework/web/method/support/ModelAndViewContainer;[Ljava/lang/Object;)Ljava/lang/Object; (InvocableHandlerMethod.java:136)
  at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(Lorg/springframework/web/context/request/ServletWebRequest;Lorg/springframework/web/method/support/ModelAndViewContainer;[Ljava/lang/Object;)V (ServletInvocableHandlerMethod.java:104)
  at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;Lorg/springframework/web/method/HandlerMethod;)Lorg/springframework/web/servlet/ModelAndView; (RequestMappingHandlerAdapter.java:743)
  at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;Lorg/springframework/web/method/HandlerMethod;)Lorg/springframework/web/servlet/ModelAndView; (RequestMappingHandlerAdapter.java:672)
  at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;Ljava/lang/Object;)Lorg/springframework/web/servlet/ModelAndView; (AbstractHandlerMethodAdapter.java:82)
  at org.springframework.web.servlet.DispatcherServlet.doDispatch(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V (DispatcherServlet.java:933)
  at org.springframework.web.servlet.DispatcherServlet.doService(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V (DispatcherServlet.java:867)
  at org.springframework.web.servlet.FrameworkServlet.processRequest(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V (FrameworkServlet.java:951)
  at org.springframework.web.servlet.FrameworkServlet.doPost(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V (FrameworkServlet.java:853)
  at javax.servlet.http.HttpServlet.service(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V (HttpServlet.java:652)
  at org.springframework.web.servlet.FrameworkServlet.service(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V (FrameworkServlet.java:827)
  at javax.servlet.http.HttpServlet.service(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V (HttpServlet.java:733)
  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V (ApplicationFilterChain.java:231)
  at org.apache.catalina.core.ApplicationFilterChain.doFilter(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V (ApplicationFilterChain.java:166)
  at org.apache.tomcat.websocket.server.WsFilter.doFilter(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;Ljavax/servlet/FilterChain;)V (WsFilter.java:52)
  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V (ApplicationFilterChain.java:193)
  at org.apache.catalina.core.ApplicationFilterChain.doFilter(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V (ApplicationFilterChain.java:166)
  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V (ApplicationFilterChain.java:193)
  at org.apache.catalina.core.ApplicationFilterChain.doFilter(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V (ApplicationFilterChain.java:166)
  at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;Ljavax/servlet/FilterChain;)V (CharacterEncodingFilter.java:88)
  at org.springframework.web.filter.OncePerRequestFilter.doFilter(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;Ljavax/servlet/FilterChain;)V (OncePerRequestFilter.java:106)
  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V (ApplicationFilterChain.java:193)
  at org.apache.catalina.core.ApplicationFilterChain.doFilter(Ljavax/servlet/ServletRequest;Ljavax/servlet/ServletResponse;)V (ApplicationFilterChain.java:166)
  at org.apache.catalina.core.StandardWrapperValve.invoke(Lorg/apache/catalina/connector/Request;Lorg/apache/catalina/connector/Response;)V (StandardWrapperValve.java:199)
  at org.apache.catalina.core.StandardContextValve.invoke(Lorg/apache/catalina/connector/Request;Lorg/apache/catalina/connector/Response;)V (StandardContextValve.java:97)
  at org.apache.catalina.authenticator.AuthenticatorBase.invoke(Lorg/apache/catalina/connector/Request;Lorg/apache/catalina/connector/Response;)V (AuthenticatorBase.java:544)
  at org.apache.catalina.core.StandardHostValve.invoke(Lorg/apache/catalina/connector/Request;Lorg/apache/catalina/connector/Response;)V (StandardHostValve.java:143)
  at org.apache.catalina.valves.ErrorReportValve.invoke(Lorg/apache/catalina/connector/Request;Lorg/apache/catalina/connector/Response;)V (ErrorReportValve.java:81)
  at org.apache.catalina.core.StandardEngineValve.invoke(Lorg/apache/catalina/connector/Request;Lorg/apache/catalina/connector/Response;)V (StandardEngineValve.java:78)
  at org.apache.catalina.connector.CoyoteAdapter.service(Lorg/apache/coyote/Request;Lorg/apache/coyote/Response;)V (CoyoteAdapter.java:343)
  at org.apache.coyote.http11.Http11Processor.service(Lorg/apache/tomcat/util/net/SocketWrapperBase;)Lorg/apache/tomcat/util/net/AbstractEndpoint$Handler$SocketState; (Http11Processor.java:616)
  at org.apache.coyote.AbstractProcessorLight.process(Lorg/apache/tomcat/util/net/SocketWrapperBase;Lorg/apache/tomcat/util/net/SocketEvent;)Lorg/apache/tomcat/util/net/AbstractEndpoint$Handler$SocketState; (AbstractProcessorLight.java:65)
  at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(Lorg/apache/tomcat/util/net/SocketWrapperBase;Lorg/apache/tomcat/util/net/SocketEvent;)Lorg/apache/tomcat/util/net/AbstractEndpoint$Handler$SocketState; (AbstractProtocol.java:818)
  at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun()V (NioEndpoint.java:1626)
  at org.apache.tomcat.util.net.SocketProcessorBase.run()V (SocketProcessorBase.java:49)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(Ljava/util/concurrent/ThreadPoolExecutor$Worker;)V (ThreadPoolExecutor.java:1149)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run()V (ThreadPoolExecutor.java:624)
  at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run()V (TaskThread.java:61)
  at java.lang.Thread.run()V (Thread.java:748)

GC 日志如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
2022-02-18T14:50:12.856+0800: 2503126.257: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 1.7350175 secs]
   [Parallel Time: 1397.1 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 2503126257.4, Avg: 2503126257.5, Max: 2503126257.5, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 7.7, Avg: 8.0, Max: 8.4, Diff: 0.8, Sum: 16.1]
      [Update RS (ms): Min: 27.0, Avg: 27.0, Max: 27.1, Diff: 0.1, Sum: 54.1]
         [Processed Buffers: Min: 307, Avg: 341.5, Max: 376, Diff: 69, Sum: 683]
      [Scan RS (ms): Min: 0.6, Avg: 0.7, Max: 0.7, Diff: 0.1, Sum: 1.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 1360.8, Avg: 1361.2, Max: 1361.5, Diff: 0.7, Sum: 2722.4]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 4, Avg: 4.0, Max: 4, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 1397.0, Avg: 1397.0, Max: 1397.0, Diff: 0.0, Sum: 2794.1]
      [GC Worker End (ms): Min: 2503127654.5, Avg: 2503127654.5, Max: 2503127654.5, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.7 ms]
   [Other: 337.2 ms]
      [Evacuation Failure: 321.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 12.1 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.9 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.2 ms]
      [Free CSet: 1.6 ms]
   [Eden: 1221.0M(1221.0M)->0.0B(398.0M) Survivors: 7168.0K->154.0M Heap: 1768.2M(2048.0M)->1290.2M(2048.0M)]
 [Times: user=2.33 sys=0.20, real=1.73 secs]
2022-02-18T14:50:15.406+0800: 2503128.807: [GC pause (G1 Evacuation Pause) (young) (initial-mark) (to-space exhausted), 1.8305528 secs]
   [Parallel Time: 1511.5 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 2503128808.1, Avg: 2503128808.1, Max: 2503128808.1, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 9.9, Avg: 9.9, Max: 10.0, Diff: 0.1, Sum: 19.9]
      [Update RS (ms): Min: 73.6, Avg: 73.8, Max: 73.9, Diff: 0.4, Sum: 147.5]
         [Processed Buffers: Min: 291, Avg: 291.5, Max: 292, Diff: 1, Sum: 583]
      [Scan RS (ms): Min: 5.1, Avg: 5.2, Max: 5.3, Diff: 0.2, Sum: 10.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 1421.4, Avg: 1421.5, Max: 1421.6, Diff: 0.1, Sum: 2843.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 1510.5, Avg: 1510.5, Max: 1510.5, Diff: 0.0, Sum: 3020.9]
      [GC Worker End (ms): Min: 2503130318.6, Avg: 2503130318.6, Max: 2503130318.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 318.6 ms]
      [Evacuation Failure: 313.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 2.8 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.8 ms]
   [Eden: 398.0M(398.0M)->0.0B(33.0M) Survivors: 154.0M->69.0M Heap: 1688.2M(2048.0M)->1818.2M(2048.0M)]
 [Times: user=2.53 sys=0.06, real=1.83 secs]
2022-02-18T14:50:17.237+0800: 2503130.637: [GC concurrent-root-region-scan-start]
2022-02-18T14:50:17.340+0800: 2503130.741: [GC pause (G1 Evacuation Pause) (young)2022-02-18T14:50:17.365+0800: 2503130.765: [GC concurrent-root-region-scan-end, 0.1280757 secs]
2022-02-18T14:50:17.365+0800: 2503130.765: [GC concurrent-mark-start]
, 0.6299259 secs]
   [Root Region Scan Waiting: 24.7 ms]
   [Parallel Time: 602.7 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 2503130765.7, Avg: 2503130765.7, Max: 2503130765.7, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 7.1, Avg: 7.4, Max: 7.7, Diff: 0.7, Sum: 14.8]
      [Update RS (ms): Min: 504.5, Avg: 504.5, Max: 504.6, Diff: 0.0, Sum: 1009.1]
         [Processed Buffers: Min: 1856, Avg: 1941.5, Max: 2027, Diff: 171, Sum: 3883]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 90.1, Avg: 90.5, Max: 90.9, Diff: 0.8, Sum: 180.9]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 602.6, Avg: 602.6, Max: 602.6, Diff: 0.0, Sum: 1205.2]
      [GC Worker End (ms): Min: 2503131368.3, Avg: 2503131368.3, Max: 2503131368.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 2.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.9 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.2 ms]
   [Eden: 33.0M(33.0M)->0.0B(89.0M) Survivors: 69.0M->13.0M Heap: 1851.2M(2048.0M)->1838.7M(2048.0M)]
 [Times: user=1.23 sys=0.00, real=0.63 secs]
2022-02-18T14:50:18.288+0800: 2503131.688: [GC pause (G1 Evacuation Pause) (young), 0.1529787 secs]
   [Parallel Time: 150.6 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 2503131688.7, Avg: 2503131688.7, Max: 2503131688.7, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 7.2, Avg: 7.3, Max: 7.3, Diff: 0.1, Sum: 14.6]
      [Update RS (ms): Min: 43.1, Avg: 43.3, Max: 43.4, Diff: 0.3, Sum: 86.6]
         [Processed Buffers: Min: 173, Avg: 182.0, Max: 191, Diff: 18, Sum: 364]
      [Scan RS (ms): Min: 0.3, Avg: 0.3, Max: 0.3, Diff: 0.0, Sum: 0.6]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 99.3, Avg: 99.3, Max: 99.4, Diff: 0.1, Sum: 198.7]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 150.4, Avg: 150.4, Max: 150.4, Diff: 0.0, Sum: 300.8]
      [GC Worker End (ms): Min: 2503131839.1, Avg: 2503131839.1, Max: 2503131839.1, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 2.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.6 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.3 ms]
   [Eden: 89.0M(89.0M)->0.0B(89.0M) Survivors: 13.0M->13.0M Heap: 1927.7M(2048.0M)->1920.7M(2048.0M)]
 [Times: user=0.31 sys=0.00, real=0.15 secs]
2022-02-18T14:50:18.668+0800: 2503132.068: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.5143611 secs]
   [Parallel Time: 408.8 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 2503132068.7, Avg: 2503132068.7, Max: 2503132068.8, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 7.1, Avg: 7.2, Max: 7.3, Diff: 0.2, Sum: 14.4]
      [Update RS (ms): Min: 41.1, Avg: 41.2, Max: 41.4, Diff: 0.3, Sum: 82.5]
         [Processed Buffers: Min: 142, Avg: 149.5, Max: 157, Diff: 15, Sum: 299]
      [Scan RS (ms): Min: 4.0, Avg: 4.2, Max: 4.5, Diff: 0.5, Sum: 8.5]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 355.9, Avg: 356.0, Max: 356.1, Diff: 0.2, Sum: 712.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 408.8, Avg: 408.8, Max: 408.8, Diff: 0.0, Sum: 817.5]
      [GC Worker End (ms): Min: 2503132477.5, Avg: 2503132477.5, Max: 2503132477.5, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 105.4 ms]
      [Evacuation Failure: 103.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.6 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.8 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.2 ms]
   [Eden: 89.0M(89.0M)->0.0B(89.0M) Survivors: 13.0M->13.0M Heap: 2009.7M(2048.0M)->2026.2M(2048.0M)]
 [Times: user=0.66 sys=0.00, real=0.51 secs]
2022-02-18T14:50:19.232+0800: 2503132.633: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.3310453 secs]
   [Parallel Time: 283.9 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 2503132633.0, Avg: 2503132633.0, Max: 2503132633.0, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 5.3, Avg: 6.8, Max: 8.3, Diff: 3.1, Sum: 13.6]
      [Update RS (ms): Min: 97.7, Avg: 97.8, Max: 97.9, Diff: 0.2, Sum: 195.6]
         [Processed Buffers: Min: 392, Avg: 414.5, Max: 437, Diff: 45, Sum: 829]
      [Scan RS (ms): Min: 0.8, Avg: 0.8, Max: 0.9, Diff: 0.1, Sum: 1.7]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 176.8, Avg: 178.3, Max: 179.8, Diff: 3.0, Sum: 356.6]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 283.8, Avg: 283.8, Max: 283.9, Diff: 0.0, Sum: 567.7]
      [GC Worker End (ms): Min: 2503132916.8, Avg: 2503132916.8, Max: 2503132916.8, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 47.0 ms]
      [Evacuation Failure: 45.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.8 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.1 ms]
   [Eden: 21.0M(89.0M)->0.0B(102.0M) Survivors: 13.0M->0.0B Heap: 2047.2M(2048.0M)->2047.2M(2048.0M)]
 [Times: user=0.48 sys=0.00, real=0.32 secs]
2022-02-18T14:50:19.566+0800: 2503132.967: [GC pause (G1 Evacuation Pause) (young), 0.0865602 secs]
   [Parallel Time: 85.2 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 2503132966.9, Avg: 2503132966.9, Max: 2503132966.9, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 6.6, Avg: 6.8, Max: 6.9, Diff: 0.3, Sum: 13.6]
      [Update RS (ms): Min: 77.7, Avg: 77.7, Max: 77.8, Diff: 0.1, Sum: 155.5]
         [Processed Buffers: Min: 425, Avg: 456.0, Max: 487, Diff: 62, Sum: 912]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.4, Avg: 0.5, Max: 0.7, Diff: 0.3, Sum: 1.0]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 85.2, Avg: 85.2, Max: 85.2, Diff: 0.0, Sum: 170.4]
      [GC Worker End (ms): Min: 2503133052.1, Avg: 2503133052.1, Max: 2503133052.1, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.1 ms]
   [Eden: 0.0B(102.0M)->0.0B(102.0M) Survivors: 0.0B->0.0B Heap: 2047.2M(2048.0M)->2047.2M(2048.0M)]
 [Times: user=0.17 sys=0.00, real=0.09 secs]
2022-02-18T14:50:19.657+0800: 2503133.058: [Full GC (Allocation Failure)  2047M->1158M(2048M), 2.9619961 secs]
   [Eden: 0.0B(102.0M)->0.0B(102.0M) Survivors: 0.0B->0.0B Heap: 2047.2M(2048.0M)->1158.7M(2048.0M)], [Metaspace: 202344K->200676K(1245184K)]
2022-02-18T14:50:22.620+0800: 2503136.020: [Heap Dump (after full gc): , 15.8497767 secs] [Times: user=16.50 sys=1.29, real=18.81 secs]

通知业务方将 POI 更换为 GitHub - alibaba/easyexcel: 快速、简洁、解决大文件内存溢出的java处理Excel工具 以解决该问题。

2022-09-05

最近使用该标记定位了类似的问题，代码执行过程中对比较大的对象进行了 JSON 序列化，单次调用内存占用数百兆，导致不定期的 FullGC，通知业务方优化相关数据后解决该问题。

Reference

Full GC analysis: Set Java VM parameters to automatically generate Dump before and after Full GC
Capturing heap dumps before FullGCs to troubleshoot memory problems | Jira | Atlassian Documentation
Universal JVM GC analyzer - Java Garbage collection log analysis made easy
jdk/collectedHeap.cpp at jdk8-b120 · openjdk/jdk · GitHub
jdk/heapDumper.cpp at jdk8-b120 · openjdk/jdk · GitHub
Shallow vs. Retained Heap