生产问题（十八）FullGC排查

胖当当技术

于 2024-08-15 09:44:58 发布

阅读量716

点赞数 15

分类专栏： java jvm 架构文章标签： jvm java 算法架构

本文链接：https://blog.csdn.net/m0_69270256/article/details/141210734

版权

java 同时被 3 个专栏收录

35 篇文章 3 订阅

订阅专栏

架构

11 篇文章 2 订阅

订阅专栏

jvm

6 篇文章 0 订阅

订阅专栏

一、引言

最近服务发生fullgc，服务响应时长大幅增长

二、排查

1、监控

没有throttled，不是因为任务堆积导致gc线程暂停，内存得不到释放

young gc频率在瞬间大幅增长，说明内存迅速增长

内存有所上升，但是之前也有类似而且幅度更大，但是技术中心是一分钟采集一次，17-18那一分钟发生了full gc，所以会吧幅度拉拉下去

从监控来说得不到更多信息，转向gc日志

2、GC日志

从日志可以看到有一些问题：

1、16:20/17:12

[Eden: 3634.0M(3634.0M)->0.0B(3638.0M) Survivors: 53248.0K->49152.0K Heap: 5612.2M(6144.0M)→1631.2M(6144.0M)]

这时候young gc还是可以迅速降低内存的

2、17:54发生to-space exhausted，GC过程中，将存活对象从一个区域复制到另一个区域。这是因为目标空间太小或者有大量对象需要被复制。

Evacuation Failure: 788.1 ms，表明在young gc的过程中，对象的疏散（即从一个内存区域移动到另一个区域）失败了

从这里可以猜测内存空间满了，没有比较完整的区域存放移动的存活对象，所以会进行gc，Heap: 6078.3M(6144.0M)→4718.0M(6144.0M)]，这说明gc的效果不太好，接下来应该会准备mixed gc

3、17:55开始initial-mark，17:56，GC concurrent-mark-start，同时产生了多次G1 Humongous Allocation，大对象分配，会降低标记的速度，同时没有足够空间分配会导致young gc，导致mixed gc的准备工作更加缓慢

4、17:56发生Full GC (Allocation Failure)，同时GC concurrent-mark-abort，mixed gc的标记工作暂停，也就是mixed gc迟迟不执行导致了 full gc

2024-08-12T15:16:20.484+0800: 338522.682: [GC pause (G1 Evacuation Pause) (young), 0.0696164 secs]
   [Parallel Time: 64.9 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 338522682.2, Avg: 338522682.2, Max: 338522682.2, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 4.4, Avg: 4.8, Max: 5.6, Diff: 1.2, Sum: 19.2]
      [Update RS (ms): Min: 20.3, Avg: 21.0, Max: 21.3, Diff: 1.0, Sum: 84.2]
         [Processed Buffers: Min: 294, Avg: 306.8, Max: 317, Diff: 23, Sum: 1227]
      [Scan RS (ms): Min: 7.9, Avg: 8.0, Max: 8.0, Diff: 0.1, Sum: 31.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 30.8, Avg: 30.9, Max: 31.0, Diff: 0.2, Sum: 123.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 17.2, Max: 24, Diff: 23, Sum: 69]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Total (ms): Min: 64.7, Avg: 64.8, Max: 64.8, Diff: 0.1, Sum: 259.1]
      [GC Worker End (ms): Min: 338522746.9, Avg: 338522747.0, Max: 338522747.0, Diff: 0.1]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.7 ms]
   [Other: 4.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.4 ms]
      [Free CSet: 1.6 ms]
   [Eden: 3638.0M(3638.0M)->0.0B(3634.0M) Survivors: 49152.0K->53248.0K Heap: 5621.3M(6144.0M)->1633.8M(6144.0M)]
 [Times: user=0.26 sys=0.01, real=0.07 secs]
2024-08-12T15:17:12.565+0800: 338574.763: [GC pause (G1 Evacuation Pause) (young), 0.0564236 secs]
   [Parallel Time: 52.7 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 338574763.2, Avg: 338574763.2, Max: 338574763.2, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 4.1, Avg: 4.4, Max: 5.0, Diff: 0.8, Sum: 17.7]
      [Update RS (ms): Min: 17.6, Avg: 18.0, Max: 18.2, Diff: 0.6, Sum: 72.0]
         [Processed Buffers: Min: 289, Avg: 314.2, Max: 333, Diff: 44, Sum: 1257]
      [Scan RS (ms): Min: 6.5, Avg: 6.6, Max: 6.6, Diff: 0.1, Sum: 26.2]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 23.4, Avg: 23.5, Max: 23.6, Diff: 0.2, Sum: 94.1]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 7.0, Max: 10, Diff: 9, Sum: 28]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 52.5, Avg: 52.6, Max: 52.6, Diff: 0.1, Sum: 210.3]
      [GC Worker End (ms): Min: 338574815.7, Avg: 338574815.8, Max: 338574815.8, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 3.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.8 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.3 ms]
      [Free CSet: 1.2 ms]
   [Eden: 3634.0M(3634.0M)->0.0B(3638.0M) Survivors: 53248.0K->49152.0K Heap: 5612.2M(6144.0M)->1631.2M(6144.0M)]
 [Times: user=0.21 sys=0.00, real=0.06 secs]
2024-08-12T15:17:54.505+0800: 338616.703: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 1.1334198 secs]
   [Parallel Time: 342.4 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 338616703.0, Avg: 338616703.0, Max: 338616703.0, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 4.8, Avg: 4.8, Max: 5.0, Diff: 0.2, Sum: 19.3]
      [Update RS (ms): Min: 20.2, Avg: 20.3, Max: 20.3, Diff: 0.1, Sum: 81.2]
         [Processed Buffers: Min: 345, Avg: 354.2, Max: 368, Diff: 23, Sum: 1417]
      [Scan RS (ms): Min: 6.1, Avg: 6.1, Max: 6.2, Diff: 0.1, Sum: 24.5]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 310.9, Avg: 311.0, Max: 311.0, Diff: 0.2, Sum: 1244.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 2.8, Max: 4, Diff: 3, Sum: 11]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 342.3, Avg: 342.3, Max: 342.3, Diff: 0.0, Sum: 1369.3]
      [GC Worker End (ms): Min: 338617045.3, Avg: 338617045.3, Max: 338617045.3, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.7 ms]
   [Other: 790.2 ms]
      [Evacuation Failure: 788.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.7 ms]
      [Free CSet: 0.6 ms]
   [Eden: 3526.0M(3638.0M)->0.0B(792.0M) Survivors: 49152.0K->0.0B Heap: 6078.3M(6144.0M)->4718.0M(6144.0M)]
 [Times: user=3.37 sys=0.22, real=1.14 secs]
2024-08-12T15:17:55.973+0800: 338618.170: [GC pause (GCLocker Initiated GC) (young) (initial-mark), 0.0732743 secs]
   [Parallel Time: 72.0 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 338618171.4, Avg: 338618171.4, Max: 338618171.4, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 7.5, Avg: 7.6, Max: 7.7, Diff: 0.2, Sum: 30.3]
      [Update RS (ms): Min: 38.7, Avg: 38.7, Max: 38.8, Diff: 0.1, Sum: 154.9]
         [Processed Buffers: Min: 134, Avg: 157.0, Max: 179, Diff: 45, Sum: 628]
      [Scan RS (ms): Min: 0.0, 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: 24.8, Avg: 24.9, Max: 25.1, Diff: 0.2, Sum: 99.7]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 71.3, Avg: 71.3, Max: 71.3, Diff: 0.0, Sum: 285.3]
      [GC Worker End (ms): Min: 338618242.7, Avg: 338618242.7, Max: 338618242.7, 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.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.3 ms]
   [Eden: 450.0M(792.0M)->0.0B(206.0M) Survivors: 0.0B->100.0M Heap: 5167.0M(6144.0M)->5032.6M(6144.0M)]
 [Times: user=0.27 sys=0.01, real=0.07 secs]
2024-08-12T15:17:56.046+0800: 338618.244: [GC concurrent-root-region-scan-start]
2024-08-12T15:17:56.052+0800: 338618.250: [GC concurrent-root-region-scan-end, 0.0057279 secs]
2024-08-12T15:17:56.052+0800: 338618.250: [GC concurrent-mark-start]
2024-08-12T15:17:56.103+0800: 338618.301: [GC pause (G1 Humongous Allocation) (young), 0.0712680 secs]
   [Parallel Time: 61.7 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 338618309.9, Avg: 338618309.9, Max: 338618309.9, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 4.2, Avg: 4.4, Max: 5.0, Diff: 0.8, Sum: 17.6]
      [Update RS (ms): Min: 46.8, Avg: 47.2, Max: 47.4, Diff: 0.6, Sum: 188.9]
         [Processed Buffers: Min: 821, Avg: 846.2, Max: 893, Diff: 72, Sum: 3385]
      [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: 9.8, Avg: 9.9, Max: 10.0, Diff: 0.2, Sum: 39.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 61.6, Avg: 61.6, Max: 61.6, Diff: 0.0, Sum: 246.4]
      [GC Worker End (ms): Min: 338618371.5, Avg: 338618371.5, Max: 338618371.5, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 9.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.2 ms]
      [Free CSet: 0.1 ms]
   [Eden: 18432.0K(206.0M)->0.0B(296.0M) Survivors: 100.0M->10240.0K Heap: 5569.2M(6144.0M)->5455.2M(6144.0M)]
 [Times: user=0.24 sys=0.00, real=0.07 secs]
2024-08-12T15:17:56.209+0800: 338618.407: [GC pause (G1 Humongous Allocation) (young), 0.0468341 secs]
   [Parallel Time: 43.0 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 338618409.7, Avg: 338618409.7, Max: 338618409.7, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 4.5, Avg: 4.7, Max: 5.2, Diff: 0.7, Sum: 19.0]
      [Update RS (ms): Min: 36.6, Avg: 36.9, Max: 37.1, Diff: 0.6, Sum: 147.8]
         [Processed Buffers: Min: 624, Avg: 641.0, Max: 659, Diff: 35, Sum: 2564]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, 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: 1.0, Avg: 1.1, Max: 1.2, Diff: 0.2, Sum: 4.4]
      [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: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 42.9, Avg: 42.9, Max: 42.9, Diff: 0.0, Sum: 171.6]
      [GC Worker End (ms): Min: 338618452.6, Avg: 338618452.6, Max: 338618452.6, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 3.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.2 ms]
      [Free CSet: 0.1 ms]
   [Eden: 10240.0K(296.0M)->0.0B(300.0M) Survivors: 10240.0K->6144.0K Heap: 5672.1M(6144.0M)->5451.1M(6144.0M)]
 [Times: user=0.17 sys=0.00, real=0.04 secs]
2024-08-12T15:17:56.288+0800: 338618.486: [GC pause (G1 Humongous Allocation) (young), 0.0380202 secs]
   [Parallel Time: 30.4 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 338618491.3, Avg: 338618491.3, Max: 338618491.4, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 4.0, Avg: 4.3, Max: 4.8, Diff: 0.7, Sum: 17.0]
      [Update RS (ms): Min: 24.0, Avg: 24.3, Max: 24.5, Diff: 0.5, Sum: 97.3]
         [Processed Buffers: Min: 386, Avg: 419.8, Max: 440, Diff: 54, Sum: 1679]
      [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: 1.5, Avg: 1.6, Max: 1.7, Diff: 0.2, Sum: 6.5]
      [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: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 30.3, Avg: 30.3, Max: 30.3, Diff: 0.0, Sum: 121.1]
      [GC Worker End (ms): Min: 338618521.6, Avg: 338618521.6, Max: 338618521.6, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 7.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.1 ms]
   [Eden: 2048.0K(300.0M)->0.0B(302.0M) Survivors: 6144.0K->4096.0K Heap: 5660.3M(6144.0M)->5657.7M(6144.0M)]
 [Times: user=0.13 sys=0.00, real=0.04 secs]
2024-08-12T15:17:56.329+0800: 338618.526: [Full GC (Allocation Failure)  5657M->1068M(3686M), 2.0506688 secs]
   [Eden: 0.0B(302.0M)->0.0B(192.0M) Survivors: 4096.0K->0.0B Heap: 5657.7M(6144.0M)->1068.4M(3686.0M)], [Metaspace: 209132K->209128K(1261568K)]
 [Times: user=1.84 sys=0.48, real=2.05 secs]
2024-08-12T15:17:58.380+0800: 338620.578: [GC concurrent-mark-abort]

如果正常的执行了mixed gc，过程是什么样的呢

01:39 initial-mark，GC concurrent-mark-start， GC concurrent-mark-end，GC cleanup 880M->878M(4000M), 0.0047793 secs，GC concurrent-cleanup-start，GC concurrent-cleanup-end

02:17 [GC pause (GCLocker Initiated GC) (mixed)

经过：

标记：这通常与一个年轻代垃圾收集（Young GC）同时发生，标记从 GC 根直接可达的对象。
根区域扫描：在这个阶段，G1 处理所有的根区域，确保在并发标记阶段开始时，从年轻代可达的老年代对象都被标记。
并发标记：在这个阶段，G1 并发地遍历堆中的对象图，标记所有可达的对象。这个阶段是并发执行的，不会显著地中断应用程序的执行。
最终标记：这是并发标记周期的最后一个暂停阶段，它完成了剩余的标记工作，并处理了在并发标记阶段发生的变化。
清理：在这个阶段，G1 会识别出整个空闲的区域，并为即将到来的 Mixed GC 做准备。


2024-08-12T18:01:39.529+0800: 348441.727: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0626838 secs]
   [Parallel Time: 57.2 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 348441729.1, Avg: 348441729.2, Max: 348441729.2, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 6.3, Avg: 6.4, Max: 6.6, Diff: 0.3, Sum: 25.7]
      [Update RS (ms): Min: 21.0, Avg: 21.1, Max: 21.1, Diff: 0.1, Sum: 84.4]
         [Processed Buffers: Min: 302, Avg: 340.2, Max: 359, Diff: 57, Sum: 1361]
      [Scan RS (ms): Min: 7.3, Avg: 7.3, Max: 7.4, Diff: 0.1, Sum: 29.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 21.3, Avg: 21.5, Max: 21.6, Diff: 0.4, Sum: 85.9]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 11.8, Max: 18, Diff: 17, Sum: 47]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 56.4, Avg: 56.4, Max: 56.4, Diff: 0.0, Sum: 225.7]
      [GC Worker End (ms): Min: 348441785.6, Avg: 348441785.6, Max: 348441785.6, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 5.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 1.6 ms]
      [Free CSet: 1.5 ms]
   [Eden: 1838.0M(2270.0M)->0.0B(2354.0M) Survivors: 45056.0K->47104.0K Heap: 3627.2M(4000.0M)->765.2M(4000.0M)]
 [Times: user=0.23 sys=0.01, real=0.06 secs]
2024-08-12T18:01:39.592+0800: 348441.790: [GC concurrent-root-region-scan-start]
2024-08-12T18:01:39.604+0800: 348441.802: [GC concurrent-root-region-scan-end, 0.0113988 secs]
2024-08-12T18:01:39.604+0800: 348441.802: [GC concurrent-mark-start]
2024-08-12T18:01:39.792+0800: 348441.990: [GC concurrent-mark-end, 0.1885346 secs]
2024-08-12T18:01:39.794+0800: 348441.992: [GC remark 2024-08-12T18:01:39.794+0800: 348441.992: [Finalize Marking, 0.0006671 secs] 2024-08-12T18:01:39.795+0800: 348441.992: [GC ref-proc, 0.0091985 secs] 2024-08-12T18:01:39.804+0800: 348442.002: [Unloading, 0.0735985 secs], 0.0854489 secs]
 [Times: user=0.22 sys=0.07, real=0.09 secs]
2024-08-12T18:01:39.881+0800: 348442.079: [GC cleanup 880M->878M(4000M), 0.0047793 secs]
 [Times: user=0.01 sys=0.01, real=0.00 secs]
2024-08-12T18:01:39.886+0800: 348442.084: [GC concurrent-cleanup-start]
2024-08-12T18:01:39.886+0800: 348442.084: [GC concurrent-cleanup-end, 0.0000390 secs]
2024-08-12T18:02:13.778+0800: 348475.976: [GC pause (G1 Evacuation Pause) (young), 0.0393627 secs]
   [Parallel Time: 37.2 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 348475976.3, Avg: 348475976.4, Max: 348475976.4, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 3.7, Avg: 4.0, Max: 4.4, Diff: 0.7, Sum: 15.9]
      [Update RS (ms): Min: 16.2, Avg: 16.6, Max: 16.7, Diff: 0.5, Sum: 66.3]
         [Processed Buffers: Min: 207, Avg: 213.5, Max: 220, Diff: 13, Sum: 854]
      [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.2, 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: 16.2, Avg: 16.3, Max: 16.4, Diff: 0.2, Sum: 65.3]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.8, Max: 3, Diff: 2, Sum: 7]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 37.1, Avg: 37.1, Max: 37.1, Diff: 0.0, Sum: 148.4]
      [GC Worker End (ms): Min: 348476013.4, Avg: 348476013.5, Max: 348476013.5, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 1.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.2 ms]
      [Free CSet: 0.7 ms]
   [Eden: 2354.0M(2354.0M)->0.0B(158.0M) Survivors: 47104.0K->43008.0K Heap: 3190.5M(4000.0M)->693.4M(4000.0M)]
 [Times: user=0.14 sys=0.00, real=0.03 secs]
2024-08-12T18:02:17.300+0800: 348479.497: [GC pause (GCLocker Initiated GC) (mixed), 0.0322336 secs]

可以看出是之前的大对象分配失败让标记过程缓慢，mixed gc迟迟没有准备好，g1触发了full gc

三、解决

jvm调优

-XX:G1HeapRegionSize：用于设置 G1 收集器的堆区域大小。大对象通常会直接分配到超过一个区域大小的内存空间，因此调整区域大小可以影响大对象的分配情况。较大的区域大小可以减少大对象的碎片化，但也会增加内存浪费。可以根据应用程序的需求和性能表现进行调整，默认值为堆大小的 1/2000。
-XX:G1HeapWastePercent：用于设置 G1 收集器的目标区域浪费比例。目标区域是用于存放从一个区域复制的存活对象的空闲区域。调整该参数可以控制目标区域的浪费比例，从而影响大对象的分配情况。较低的浪费比例可以减少大对象的碎片化，但可能会增加垃圾回收的频率，默认 10。
-XX:G1MixedGCLiveThresholdPercent：该参数用于设置 G1 收集器的混合垃圾回收的存活对象阈值百分比。混合垃圾回收是 G1 收集器在执行部分垃圾回收时触发的过程。调整该参数可以控制在混合垃圾回收过程中，哪些对象被认为是存活对象。较高的阈值百分比可以增加大对象被认为是存活对象的概率，从而减少大对象的回收。默认 65。

4.-XX:G1HeapRegionSize：通常为堆大小的 1/2000，大对象的分配就是找连续的region。

从资料上来看，这些参数调整有利于减少大对象分配和mixed gc的执行，作者认为还是应该尝试G1HeapRegionSize，因为gc日志表明了在上升的时候准备了mixedgc，只不过大对象分配失败加上不断young gc，准备工作迟迟不完成，所以应该减少大对象分配失败

四、总结

后续的验证需要时间，也有一些同事有不同的意见，认为这不是根本原因，根本原因需要看程序代码哪里会导致大对象的出现阻塞mixedgc，还有为什么其他服务没有出现相同的情况，因为有的服务访问处理比这个频繁多了

但是这个服务没有改动，要么就是历史上一直这样，但是之前也没出现过

作者觉得查问题两个方面：

1、环境

环境涉及的多种多样，首先应该就事论事，根据出现的异常，对比正常的情况，分析怎么去解决。jvm调优就是一种常用的手段，既然是大对象分配阻塞了mixed gc的准备工作，那就应该避免这种情况，让mixed gc可以顺利进行

2、代码

通过code review，检查代码的不当之处，还有可能产生的大量对象的地方，结合dump文件进行分析，这种主要问题在于dump文件的时机，抓不到那个时间点，毕竟不可能一直盯着监控，很多时候一直盯着监控也没有用，有的时候内存升的比他高多了，需要满足准备mixed gc+大对象分配失败，mixed gc的准备工作正常都是ms级别的

所以作者觉得两个路子是可以一起走的，不能非说程序一定是有问题的，可能只是巧合的情况下正好碰上了，这个就要看后续问题的频率了