G1大对象致Old区占用率高

java

背景

某日凌晨一点多点，值班同事call我说应用线上环境持续告警JVM的老年区空间使用率持续超过95%，于是去监控台查看该应用的JVM监控数据，果然集群下几乎所有的线上节点的老年区使用率突然飙升。挑选了一个节点的监控，如下图：

img

img

img

上图可见，该节点于1点半左右JVM老年区占用从原先很低的占用突然增长到几乎100%，然而其GC次数变化不大，从原先每分钟一两次增长到每分钟两三次，且无任何Full GC。

分析

初步猜测

我们应用使用的垃圾回收器是G1，显然老年区占用率波动是Mixed GC的功劳，但为何老年区占用如此之高。为了分析老年区的内存使用，通过平台工单对该节点的JVM生成了一份内存快照，并期间以秒级查看了JVM的内存使用情况，如下：

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
$ jstat -gcutil 655 1000
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00 100.00  69.95  99.96  95.89  92.06   3109  227.757     0    0.000  227.757
  0.00 100.00  70.82  99.98  95.89  92.06   3109  227.757     0    0.000  227.757
  0.00 100.00  74.11  99.98  95.89  92.06   3109  227.757     0    0.000  227.757
  0.00 100.00   3.05  85.35  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00   3.43  85.39  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00   4.57  86.40  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00   5.34  86.45  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00   6.73  87.44  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00   7.75  88.47  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00   9.40  88.57  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  10.80  88.75  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  10.80  88.75  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  11.31  89.02  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  12.58  90.05  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  16.01  92.01  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  17.15  92.93  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  17.79  92.98  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  18.30  93.98  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  20.97  95.33  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  21.22  95.33  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  23.38  97.24  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  24.27  98.23  95.89  92.06   3110  227.937     0    0.000  227.937
  0.00 100.00  24.27  98.23  95.89  92.06   3110  227.937     0    0.000  227.937

通过jstat -gcutil命令以秒级查看该JVM的内存使用情况，意外发现一个疑点：老年区的内存使用率在没GC时持续快速增长。

G1内存回收器的老年区使用率增长意味着有对象移入老年区，而G1只有以下情况会将对象分配至老年区:

  1. 新生代对象经过多次GC后存活，达到阈值年龄的对象移入老年区
  2. Survior区GC后对象存活率超过50%，该区中年龄超过平均值的对象移入老年区
  3. 大对象（内存占用超过Region分区的50%）直接分配到老年区

一二两种情况都是在GC时执行，也就是每次GC完成后才会出现对象移入老年区，导致老年区内存使用率增长的现象，这显然与现状不符合，那就剩情况三，即 JVM创建的大对象直接分配到老年区，导致老年区内存使用率持续增长的情况。

为了验证猜想，则需要一个内存快照分析当前的老年区所有对象，如果老年区中存在大量的大对象则能证明猜想正确，然后就可以根据这些大对象找到问题代码，然后修复该问题。

读取内存快照

此时刚刚提交工单创建的JVM内存快照已经生成完成，点击该内存快照执行内存分析却发现该内存快照中只有二百多兆的对象，与监控台上显示的近3G的内存使用严重不符。再去监控台查看该节点的JVM监控时，显示该节点刚刚触发一次Full GC，将老年区的使用率从原先近100%陡降至20%，由此得知老年区中的持有的绝大多数对象都是生命周期很短的对象，这很符合大对象的猜测。

但为何此时突然触发Full GC，而且整个集群唯独该节点发生过Full GC，显然是刚刚申请工单执行内存快照jmap命令指定了live参数即触发Full GC只保存存活的内存对象快照，查看工单执行详情果然如此。但实际上目前需要的恰恰是这些已经过期的对象，因此只能手动登录节点执行内存快照命令：jmap -dump:format=b,file=hprof 进程PID。

内存快照重新生成完后，下载到本地使用MAT工具执行JVM快照分析，如下图，但1G的内存快照文件分析后只显示有三百兆的对象和大量的Unreachable对象。Unreachable对象即可回收的对象，但由于MAT默认配置只分析内存快照中存活的对象，导致当前内存快照中有七百兆的可回收对象在MAT工具分析时被过滤掉了。

img

当前存活对象按内存排序结果如下图：

img

为了能够分析查看这些Unreachable对象，需要修改MAT的配置，打开Keep unreachable objects的选项，如下图。然后重新打开JVM内存快照文件执行MAT分析即可。

img

分析内存快照

img

开启MAT的Keep unreachable objects的选项后，重新分析内存快照后如上图，此时MAT显示快照中存在近1G的对象，结合Keep unreachable objects的选项开启前分析显示仅有三百兆对象，可得有七百兆的对象都是可回收的对象。当前所有对象按内存排序如果如下图，字符数组和比特数组对象合计占用近七百兆，对比上面存活对象的内存排序显示存活的字符数组和比特数组对象合计仅才九十兆，即这些字符数组和比特数组对象基本都是可回收对象。

img

继续为了验证上述猜测中大对象的问题，再对这两种对象做排序，结果如下图。显然都是数兆大小的字符数组对象，很符合大对象的定义，与上诉猜测一致，并且查看这些大对象的值，发现都是打印的查询接口返回报文的日志文本。

那么根据以上猜测和证据，可以发现是不知名原因导致查询接口返回的报文长度很大，以至于该接口的打印日志文本长度过长，该接口每一次日志打印生成一个大对象直接晋升到老年区，因而老年区使用率持续增长。另外与业务方沟通后得知，凌晨1点左右运营同学上线了一批文本长度很大的数据，这更验证了上述猜测。

img

G1大对象

G1将内存切分成一个个Region区，同时各个Region又分为新生代（Eden、Survior区）、老年代，如下图。Region的空间大小是按整个JVM内存大小计算的，G1最多可以有2048个Region，并且大小必须是2的倍数，即4G内存实际分配Region的是2M，8G内存实际分配Region的是4M。

img

当一个对象大小超过Region的一半时，则该对象定义为大对象，大对象不会在新生代分配空间，而是直接在老年代的Humongous区存放这些大对象，且当一个Humongous区的Region放不下大对象时，则G1会分配连续的Region作为Humongous区来存储大对象。

对于G1垃圾回收器的GC，Minor GC对完整的新生代空间执行扫描和对象回收，而Mixed GC则相对复杂一些，Mixed GC除了完整的新生代以外，还会对老年区少数Region区执行对象回收。为了让Mixed GC执行时选择老年区中垃圾回收率尽可能高的Region区从而提高GC效率，G1为此提供了并发标记。该并发标记也就是G1为人所熟知的初始标记、并发标记、最终标记、存活对象计数、收尾工作周期，并发标记本身不会执行对象回收，仅在收尾工作步骤对老年区中没有存活对象的Region执行清理释放。通过执行并发标记，G1可以获取到老年区每个Region的存活对象的比例，从而在Mixed GC时选择其中垃圾回收率高的Region。

另外，Mixed GC依赖并发标记，并发标记的触发时机受到以下条件限制：

  1. 并发标记结果已经使用完（默认一次并发标记后发生8次Mixed GC，参数G1MixedGCCountTarget指定）
  2. 老年区已使用空间/整个堆空间达到阈值（默认45%，由参数InitiatingHeapOccupancyPercent指定）

注意，对于条件二实际上是有坑的，官方文档中对于该条件的描述如下，当整个堆内存使用率达到阈值时触发并发标记周期，但实际上Oracle的Bug库中JDK-8151176描述实际上G1是以老年区空间/整个堆空间的使用率做阈值计算，当老年区已使用空间达到阈值时才触发并发标记周期。

这可能引起另一个问题，如果JVM设置新生代大小占整个堆的55%以上，那么哪怕老年区空间全部分配耗尽，老年区已使用空间/整个堆空间也达不到45%，导致永远无法触发并发标记，也就无法使用Mixed GC，只能通过Full GC来回收老年区。

G1文档

-XX:InitiatingHeapOccupancyPercent=45 - Percentage of the (entire) heap occupancy to start a concurrent GC cycle. It is used by G1 to trigger a concurrent GC cycle based on the occupancy of the entire heap, not just one of the generations. A value of 0 denotes ‘do constant GC cycles’. The default value is 45 (i.e., 45% full or occupied).

JDK-8151176

If static IHOP is selected, it may happen that concurrent marking will never be started.

The reason is that static IHOP starts if old gen occupancy exceeds a fixed percentage of the current heap capacity. If either the user or ergonomics decide that the old gen can not be larger than that fraction of the heap capacity that triggers concurrent mark, marking will never start.

E.g. current defaults allow a young gen size up to 60% of the heap capacity (G1MaxNewSizePercent). which means that only 40% can be occupied by old gen.

However, the default value of 45 for InitiatingHeapOccupancyPercent means that marking will only trigger if the old gen occupies more than 45% of the heap, which will not occur.

而当前线上告警的应用启动参数中，分配了4.5G的堆空间，参数InitiatingHeapOccupancyPercent指定40即当老年区使用超过1.8G时才触发并发标记为Mixed GC服务，与下图监控台中该应用老年区空间占用的折线图相符。

img

另外，在翻阅文档时意外发现G1一个有意思的Bug：JDK-8140597。当G1分配大对象前会检查当前是否满足并发标记触发条件，如果条件满足则触发并发标记周期，而该Bug导致由大对象分配引起的并发标记会中断Mixed GC操作。该场景下频繁地创建大对象会导致Mixed GC执行始终被中断，从而引起老年区空间耗尽而发生Full GC。

If an initial mark is caused by humongous allocations, the gc locker or the metadata threshold being surpassed, the mixed gc phase is interrupted.

This means that potentially no mixed gc will ever happen in many cases, running into full gcs all the time.

解决

由于是日志打印查询接口报文而导致的大对象创建，因此最根治的办法是缩减该查询接口的报文长度，但这涉及到调用方的改造，因此先通过临时解决办法解决大对象问题：将原先的长文本日志拆分成多条短文本日志，从而避免大对象的创建。代码改造并发布上线后，监控台显示JVM老年区使用率恢复正常，如下图。

img

>