<pre class=“language-java”><code>2022-04-25T13:33:04.376+0800: 313962.460: [GC concurrent-root-region-scan-start]
2022-04-25T13:33:04.376+0800: 313962.461: [GC concurrent-root-region-scan-end, 0.0002366 secs]
2022-04-25T13:33:04.376+0800: 313962.461: [GC concurrent-mark-start]
2022-04-25T13:33:04.378+0800: 313962.463: [GC pause (G1 Evacuation Pause) (young), 0.0059898 secs]
[Parallel Time: 3.6 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 313962463.0, Avg: 313962463.1, Max: 313962463.7, Diff: 0.7]
[Ext Root Scanning (ms): Min: 0.8, Avg: 1.8, Max: 3.5, Diff: 2.8, Sum: 14.2]
[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.4, Diff: 0.4, Sum: 0.5]
[Processed Buffers: Min: 0, Avg: 0.4, Max: 1, Diff: 1, Sum: 3]
[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.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.8]
[Termination (ms): Min: 0.0, Avg: 1.5, Max: 1.9, Diff: 1.9, Sum: 12.1]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 2.9, Avg: 3.5, Max: 3.6, Diff: 0.7, Sum: 27.6]
[GC Worker End (ms): Min: 313962466.6, Avg: 313962466.6, Max: 313962466.6, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[String Dedup Fixup: 1.5 ms, GC Workers: 8]
[Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Table Fixup (ms): Min: 0.0, Avg: 1.2, Max: 1.4, Diff: 1.4, Sum: 9.5]
[Clear CT: 0.1 ms]
[Other: 0.8 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
[Eden: 0.0B(204.0M)->0.0B(204.0M) Survivors: 0.0B->0.0B Heap: 3701.6M(4096.0M)->3701.6M(4096.0M)]
[Times: user=0.04 sys=0.00, real=0.01 secs]
2022-04-25T13:33:04.388+0800: 313962.473: [GC pause (G1 Evacuation Pause) (young), 0.0054690 secs]
[Parallel Time: 3.1 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 313962473.6, Avg: 313962473.6, Max: 313962473.7, Diff: 0.1]
[Ext Root Scanning (ms): Min: 2.0, Avg: 2.5, Max: 2.9, Diff: 0.9, Sum: 19.8]
[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.0]
[Processed Buffers: Min: 0, Avg: 2.1, Max: 9, Diff: 9, Sum: 17]
[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.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 0.7]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.8]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Total (ms): Min: 2.9, Avg: 2.9, Max: 3.0, Diff: 0.1, Sum: 23.4]
[GC Worker End (ms): Min: 313962476.5, Avg: 313962476.6, Max: 313962476.6, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[String Dedup Fixup: 1.5 ms, GC Workers: 8]
[Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Table Fixup (ms): Min: 0.4, Avg: 1.2, Max: 1.4, Diff: 1.1, Sum: 9.2]
[Clear CT: 0.1 ms]
[Other: 0.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
[Eden: 0.0B(204.0M)->0.0B(204.0M) Survivors: 0.0B->0.0B Heap: 3701.6M(4096.0M)->3701.6M(4096.0M)]
[Times: user=0.02 sys=0.00, real=0.01 secs]
2022-04-25T13:33:04.396+0800: 313962.481: [GC pause (G1 Evacuation Pause) (young), 0.0059906 secs]
[Parallel Time: 3.5 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 313962481.3, Avg: 313962481.3, Max: 313962481.4, Diff: 0.1]
[Ext Root Scanning (ms): Min: 2.1, Avg: 2.5, Max: 3.3, Diff: 1.2, Sum: 20.4]
[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 0.5]
[Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 2]
[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.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
[Termination (ms): Min: 0.0, Avg: 0.7, Max: 1.1, Diff: 1.1, Sum: 5.3]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Total (ms): Min: 3.3, Avg: 3.4, Max: 3.4, Diff: 0.1, Sum: 27.0]
[GC Worker End (ms): Min: 313962484.7, Avg: 313962484.7, Max: 313962484.7, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[String Dedup Fixup: 1.5 ms, GC Workers: 8]
[Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Table Fixup (ms): Min: 0.0, Avg: 1.2, Max: 1.4, Diff: 1.4, Sum: 9.5]
[Clear CT: 0.1 ms]
[Other: 0.9 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.0 ms]
[Free CSet: 0.0 ms]
[Eden: 0.0B(204.0M)->0.0B(204.0M) Survivors: 0.0B->0.0B Heap: 3701.6M(4096.0M)->3701.6M(4096.0M)]
[Times: user=0.03 sys=0.00, real=0.01 secs]
2022-04-25T13:33:04.404+0800: 313962.489: [Full GC (Allocation Failure) 3701M->683M(4096M), 0.9926569 secs]
[Eden: 0.0B(204.0M)->0.0B(2456.0M) Survivors: 0.0B->0.0B Heap: 3701.6M(4096.0M)->683.9M(4096.0M)], [Metaspace: 191737K->191737K(1228800K)]
[Times: user=1.46 sys=0.00, real=0.99 secs]
2022-04-25T13:33:05.398+0800: 313963.482: [GC concurrent-mark-abort]
2022-04-25T13:33:09.748+0800: 313967.833: [GC pause (G1 Evacuation Pause) (young), 0.0174053 secs]
[Parallel Time: 12.5 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 313967833.7, Avg: 313967833.8, Max: 313967833.9, Diff: 0.2]
[Ext Root Scanning (ms): Min: 3.8, Avg: 5.2, Max: 9.1, Diff: 5.3, Sum: 41.3]
[Update RS (ms): Min: 0.0, Avg: 3.3, Max: 4.3, Diff: 4.3, Sum: 26.0]
[Processed Buffers: Min: 0, Avg: 38.1, Max: 53, Diff: 53, Sum: 305]
[Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.3]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 3.0, Avg: 3.6, Max: 4.0, Diff: 1.0, Sum: 28.9]
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[GC Worker Total (ms): Min: 12.2, Avg: 12.3, Max: 12.4, Diff: 0.2, Sum: 98.5]
[GC Worker End (ms): Min: 313967846.1, Avg: 313967846.1, Max: 313967846.1, Diff: 0.1]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.4 ms]
[String Dedup Fixup: 2.0 ms, GC Workers: 8]
[Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Table Fixup (ms): Min: 0.0, Avg: 1.7, Max: 2.0, Diff: 2.0, Sum: 13.3]
[Clear CT: 0.3 ms]
[Other: 2.2 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.4 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.8 ms]</code></pre>
<p> </p>
<p>业务场景：最近7天无大的变更，最近7天未发生过Allocation Failure，最近大区别就是今天业务峰值比以往高了30%左右，怀疑是业务QPS上来了导致查询量变大导致发生Allocation Failure，但无明显的日志来证明，请各位专家帮分析下情况。谢谢！</p>
<p>从上面是日志，可以看到Allocation Failure且耗时0.9s：</p>
<p>2022-04-25T13:33:04.404+0800: 313962.489: [Full GC (Allocation Failure)  3701M->683M(4096M), 0.9926569 secs]<br />   [Eden: 0.0B(204.0M)->0.0B(2456.0M) Survivors: 0.0B->0.0B Heap: 3701.6M(4096.0M)->683.9M(4096.0M)], [Metaspace: 191737K->191737K(1228800K)]<br /> [Times: user=1.46 sys=0.00, real=0.99 secs] </p>
<p> </p>
<p> </p>