G1回收的垃圾排查

define_us

已于 2024-05-23 21:51:17 修改

阅读量1.9k

点赞数

分类专栏： java 文章标签： java 开发语言

于 2022-09-30 14:40:03 首次发布

本文链接：https://blog.csdn.net/define_us/article/details/127123087

版权

java 专栏收录该内容

221 篇文章 0 订阅

订阅专栏

G1 GC的简单介绍

在这里插入图片描述如果一个对象超过region的50%，就是大对象。大对象是该region最后一个能分配进去的对象。如果大对象超过分区大小的50%，那么久必须要连续的大对象分区才能分配。

年轻代清理(一般称为Minor GC)

![在这里插入图片描述](https://img-blog.csdnimg.cn/7d336f6f3cf641f890e3f0539d9b65cf.png
总结，

年轻代清理是并行进行的
存活对象会被拷贝的老年代，或者作为suvivor区的年轻代块。
年轻代的清理是STW的。

老年代清理（实际上是Mix GC，一般称为FullGC）

在进行上述GC的同时，完成标记
在这里插入图片描述
进行并行标记，如果发现某个region完全都不需要了，直接清理。否则，计算每个区域的存活比率。

此时，空region已经被删除。存活比率也已经计算完毕

开始对存活比率最低的region进行清理。才用复制算法。
在这里插入图片描述

垃圾回收的问题排查

我们有问题的配置如下

-Xmx10240M -Xms10240M -XX:MaxMetaspaceSize=512M -XX:MetaspaceSize=512M -XX:+UseG1GC -XX:MaxGCPauseMillis=100

我们是一个4G16G的服务器。CPU利用率在35%左右。会出现2-3分钟的GC时间过长的情况
我们的GC日志如下

YGC是经常经常发生的。
一个ygc的日志如下

2022-09-30T15:20:42.441+0800: 16114.185: Total time for which application threads were stopped: 0.0461723 seconds, Stopping threads took: 0.0004525 seconds //前者是一共暂停的时间。后者是让线程暂停的时间。一般是等待线程到达safepoint
2022-09-30T15:20:43.441+0800: 16115.186: Application time: 1.0001127 seconds
2022-09-30T15:20:43.444+0800: 16115.189: Total time for which application threads were stopped: 0.0031014 seconds, Stopping threads took: 0.0005369 seconds
2022-09-30T15:20:43.806+0800: 16115.550: Application time: 0.3614641 seconds
{Heap before GC invocations=6265 (full 0)://开始的时候堆的情况
 garbage-first heap   total 10485760K, used 4079653K [0x0000000560800000, 0x0000000560c05000, 0x00000007e0800000)
  region size 4096K, 128 young (524288K), 7 survivors (28672K)
 Metaspace       used 152571K, capacity 158063K, committed 158848K, reserved 1189888K
  class space    used 17402K, capacity 18335K, committed 18560K, reserved 1048576K
2022-09-30T15:20:43.809+0800: 16115.553: [GC pause (G1 Evacuation Pause) (young)//当前发生的事疏散停顿，也就是copy对象。16115.553是java应用启动到现在的秒的数量。yong表示这是一个yonggc事件
Desired survivor size 33554432 bytes, new threshold 15 (max 15)
- age   1:   13263136 bytes,   13263136 total
- age   2:    4114864 bytes,   17378000 total
- age   3:    5199960 bytes,   22577960 total
- age   4:    4148608 bytes,   26726568 total
, 0.0446937 secs]
   [Parallel Time: 41.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 16115554.1, Avg: 16115554.1, Max: 16115554.1, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 3.8, Avg: 4.0, Max: 4.3, Diff: 0.5, Sum: 16.0]
      [Update RS (ms): Min: 12.4, Avg: 12.6, Max: 12.6, Diff: 0.2, Sum: 50.3]
         [Processed Buffers: Min: 138, Avg: 158.2, Max: 183, Diff: 45, Sum: 633]
      [Scan RS (ms): Min: 9.9, Avg: 10.0, Max: 10.0, Diff: 0.0, Sum: 39.8]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 14.4, Avg: 14.6, Max: 14.8, Diff: 0.4, Sum: 58.3]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.2, Max: 2, Diff: 1, Sum: 5]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Total (ms): Min: 41.2, Avg: 41.2, Max: 41.2, Diff: 0.0, Sum: 164.8]
      [GC Worker End (ms): Min: 16115595.3, Avg: 16115595.3, Max: 16115595.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 3.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.6 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.4 ms]
   [Eden: 484.0M(484.0M)->0.0B(472.0M) Survivors: 28.0M->40.0M Heap: 3984.0M(10.0G)->3512.0M(10.0G)]
Heap after GC invocations=6266 (full 0)://GC完成时堆的情况
 garbage-first heap   total 10485760K, used 3596325K [0x0000000560800000, 0x0000000560c05000, 0x00000007e0800000)//total表示总的堆空间。used表示已经占用的堆空间
  region size 4096K, 10 young (40960K), 10 survivors (40960K)
 Metaspace       used 152571K, capacity 158063K, committed 158848K, reserved 1189888K
  class space    used 17402K, capacity 18335K, committed 18560K, reserved 1048576K
}
 [Times: user=0.17 sys=0.01, real=0.05 secs]//GC实际花了50ms

一个mix gc的日志如下

2022-09-30T15:14:10.302+0800: 15087.904: Total time for which application threads were stopped: 1.3671091 seconds, Stopping threads took: 0.0005155 seconds
2022-09-30T15:14:10.580+0800: 15088.182: Application time: 0.2778824 seconds
{Heap before GC invocations=6106 (full 0):
 garbage-first heap   total 10485760K, used 3733074K [0x0000000560800000, 0x0000000560c05000, 0x00000007e0800000)
  region size 4096K, 128 young (524288K), 12 survivors (49152K)
 Metaspace       used 152429K, capacity 157897K, committed 158848K, reserved 1189888K
  class space    used 17380K, capacity 18288K, committed 18560K, reserved 1048576K
2022-09-30T15:14:10.583+0800: 15088.185: [GC pause (G1 Evacuation Pause) (mixed)
Desired survivor size 33554432 bytes, new threshold 2 (max 15) //threshold 2被晋升到老年代的阈值
- age   1:   25160888 bytes,   25160888 total //多少成功存活了1次GC。注意，新分配的对象的age是0.
- age   2:    8463896 bytes,   33624784 total //total = 25160888 + 8463896 。其是一个类价值，表示小于等于当前年龄分组的对象的总大小。
- age   3:   11708808 bytes,   45333592 total //total = 33624784 + 11708808 //年轻代的垃圾手机如果过多，可能就是发生了错误晋升
, 2.1177112 secs]
   [Parallel Time: 2096.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 15088194.2, Avg: 15088194.2, Max: 15088194.2, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 3.6, Avg: 3.8, Max: 4.1, Diff: 0.5, Sum: 15.3]
      [Update RS (ms): Min: 229.3, Avg: 229.4, Max: 229.4, Diff: 0.1, Sum: 917.5]
         [Processed Buffers: Min: 449, Avg: 482.2, Max: 524, Diff: 75, Sum: 1929]
      [Scan RS (ms): Min: 1774.7, Avg: 1774.8, Max: 1774.9, Diff: 0.2, Sum: 7099.2]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.3]
      [Object Copy (ms): Min: 88.2, Avg: 88.5, Max: 88.7, Diff: 0.4, Sum: 353.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: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [GC Worker Total (ms): Min: 2096.6, Avg: 2096.6, Max: 2096.6, Diff: 0.0, Sum: 8386.4]
      [GC Worker End (ms): Min: 15090290.8, Avg: 15090290.8, Max: 15090290.8, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.5 ms]
   [Other: 20.6 ms]
      [Choose CSet: 8.3 ms]
      [Ref Proc: 0.8 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.7 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 8.6 ms]
   [Eden: 464.0M(464.0M)->0.0B(468.0M) Survivors: 48.0M->44.0M Heap: 3645.6M(10.0G)->3015.6M(10.0G)]
Heap after GC invocations=6107 (full 0):
 garbage-first heap   total 10485760K, used 3087954K [0x0000000560800000, 0x0000000560c05000, 0x00000007e0800000)
  region size 4096K, 11 young (45056K), 11 survivors (45056K)
 Metaspace       used 152429K, capacity 157897K, committed 158848K, reserved 1189888K
  class space    used 17380K, capacity 18288K, committed 18560K, reserved 1048576K
}
 [Times: user=8.25 sys=0.17, real=2.12 secs]

我们的问题在于，mixgc实在太多了

2022-09-30T15:41:28.206+0800: 16725.808: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:41:29.424+0800: 16727.026: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:41:30.969+0800: 16728.571: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:41:32.130+0800: 16729.732: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:41:33.689+0800: 16731.291: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:41:35.004+0800: 16732.606: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:45:04.890+0800: 16942.491: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:45:05.737+0800: 16943.338: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:45:06.914+0800: 16944.516: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:45:08.283+0800: 16945.885: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:45:09.390+0800: 16946.992: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:45:11.356+0800: 16948.958: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:48:06.492+0800: 17124.094: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:48:07.920+0800: 17125.522: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:48:08.893+0800: 17126.495: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:48:10.051+0800: 17127.653: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:48:11.811+0800: 17129.413: [GC pause (G1 Evacuation Pause) (mixed)
2022-09-30T15:48:13.322+0800: 17130.923: [GC pause (G1 Evacuation Pause) (mixed)

平均间隔3分钟左右，就会出现六次长时间的mixgc，不出问题才怪。其实段时间内出现几次gc并不稀奇，但是不要出现这么长时间啊

一个典型的配置如下

-Xmx45G -Xms45G -XX:MaxDirectMemorySize=3072M -XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -XX:MaxGCPauseMillis=250 -XX:G1HeapRegionSize=32M -XX:ParallelGCThreads=14 -XX:G1RSetUpdatingPauseTimePercent=5 -XX:G1NewSizePercent=15 -XX:G1MaxNewSizePercent=50

配置的含义为

MaxGCPauseMillis G1的垃圾回收不需要制定年轻代的大小，JVM可以自行决定
G1HeapRegionSize 设置的 G1 区域的大小。值是 2 的幂，范围是 1 MB 到 32 MB 之间。目标是根据最小的 Java 堆大小划分出约 2048
ParallelGCThreads 一般而言，CPU数量小于8的时候，和CPU数量相等。其他适当减少。下列命令可以查看当前数字

      java -XX:+PrintFlagsFinal -version | grep ParallelGCThreads

G1RSetUpdatingPauseTimePercent
用于更新rset的时间占整体时间的比例

 This flag sets a percent target amount (defaults to 10 percent of the pause time goal) that G1 GC should spend in updating RSets during a GC evacuation pause.
 You can increase or decrease the percent value, so as to spend more or less (respectively) time in updating the RSets during the stop-the-world (STW) GC pause and let the concurrent refinement threads deal with the update buffers accordingly.
Keep in mind that by decreasing the percent value, you are pushing off the work to the concurrent refinement threads; hence, you will see an increase in concurrent work.

G1NewSizePercent
年轻代的最小值。默认这个数字是5%。

Sets the percentage of the heap to use as the minimum for the young generation size. The default value is 5 percent of your Java heap. This is an experimental flag.

G1MaxNewSizePercent
年轻代的最大值。一旦到达了这个数字，就会出发垃圾回收。默认情况下这个数字是60%

Sets the percentage of the heap size to use as the maximum for young generation size. The default value is 60 percent of your Java heap. This is an experimental flag

-XX:G1ReservePercent=10 Sets the percentage of reserve memory to keep free. The default is 10 percent. G1 Garbage collectors will try to keep 10% of the heap to be free always.这个是用来预防大对象分配造成的大GC的。

没有什么别的办法，上easyGC

首先排除大对象的影响
在这里插入图片描述可以pause时间太高了

我们可以看下对象的生成速度

我们可以看下正常应用的生成速度