关于gc:GC耗时高原因竟是服务流量小

原创：扣钉日记（微信公众号 ID：codelogs），欢送分享，转载请保留出处。

简介

最近，咱们系统配置了 GC 耗时的监控，但配置上之后，零碎会偶然呈现 GC 耗时大于 1s 的报警，排查花了一些力量，故在这里分享下。

发现问题

咱们零碎分多个环境部署，呈现 GC 长耗时的是俄罗斯环境，其它环境没有这个问题，这里比拟奇怪的是，俄罗斯环境是流量最低的一个环境，而且大多数 GC 长耗时产生在深夜。

发现报警后，我立马查看了 GC 日志，如下：

日志中呈现了 to-space exhausted，通过一番理解，呈现这个是因为 g1 在做 gc 时，都是先复制存活对象，再回收原 region，当没有闲暇空间复制存活对象时，就会呈现 to-space exhausted，而这种 GC 场景代价是十分大的。

同时，在这个 gc 产生之前，还发现了一些如下的日志。

这里能够看到，零碎在调配约 30M+ 的大对象，难道是有代码频繁调配大对象导致的 gc 问题。

定位大对象产生地位

jdk 在调配大对象时，会调用 G1CollectedHeap::humongous_obj_allocate 办法，而应用 async-profiler 能够很容易晓得哪里调用了这个办法，如下：

# 开启收集
./profiler.sh start --all-user -e G1CollectedHeap::humongous_obj_allocate -f ./humongous.jfr jps

# 进行收集
./profiler.sh stop -f ./humongous.jfr jps

将 humongous.jfr 文件用 jmc 关上，如下：

依据调用栈我发现，这是咱们的一个定时工作，它会定时调用一个接口获取配置信息并缓存它，而这个接口返回的数据量达 14M 之多。

难道是这个接口导致的 gc 问题？但这个定时工作调用也不频繁呀，5 分钟才调用一次，不至于让 gc 忙不过来吧！
另一个疑难是，这个定时工作在其它环境也会运行，而且其它环境的业务流量大得多，为什么其它环境没有问题？

至此，我也不确定是这个定时工作导致的问题，还是零碎本身特点导致偶然的高 gc 耗时。

因为咱们有固定的上线日，于是我打算先优化产生大对象的代码，而后在上线前的期间试着优化一下 jvm gc 参数。

优化产生大对象的代码

咱们应用的是 httpclient 调用接口，调用接口时，代码会先将接口返回数据读取成 String，而后再应用 jackson 把 String 转成 map 对象，简化如下：

rsp = httpClient.execute(request);
String result = IOUtils.toString(rsp.getEntity().getContent());
Map resultMap = JSONUtil.getMapper().readValue(result, Map.class);

要优化它也很简略，应用 jackson 的 readValue 有一个传入 InputStream 的重载办法，用它来读取 json 数据，而不是将其加载成一个大的 String 对象再读，如下：

rsp = httpClient.execute(request);
InputStream is = rsp.getEntity().getContent();
Map resultMap = JSONUtil.getMapper().readValue(is, Map.class);

注：这外面 map 从逻辑上来说是一个大对象，但对 jvm 来说，它只是很多个小对象而后用指针连接起来而已，大对象个别由大数组造成，大 String 之所以是大对象，是因为它外面有一个很大的 char[]数组。

优化 GC 参数

优化完代码后，我开始钻研优化 jvm gc 参数了，咱们应用的是 jdk8，垃圾收集器是 g1，为了了解 g1 的调优参数，又简略学习了下 g1 的要害概念。

1. g1 是分 region 收集的，但 region 也分年老代与老年代。
2. g1 的 gc 分 young gc 与mixed gc，young gc 用于收集年老代 region，mixed gc 会收集年老代与老年代 region。
3. 在 mixed gc 回收之前，须要先经验一个并发周期 (Concurrent Cycles)，用来标记各 region 的对象存活状况，让mixed gc 能够判断出须要回收哪些 region。
4. 并发周期分为如下 4 个子阶段：
   a. 初始标记 (initial marking)
   b. 并发标记(concurrent marking)
   c. 从新标记(remarking)
   d. 清理(clean up)
   须要留神的是，初始标记 (initial marking) 这一步是借助 young gc 实现的。

在 g1 中，young gc 简直没有什么可调参数，而 mixed gc 有一些，常见如下：

呈现 to-space exhausted 会不会是 mixed gc 太慢了呢？于是我调整了如下参数：

1. 让并发标记周期启动更早，运行得更快，将 -XX：InitiatingHeapOccupancyPercent 从默认值 45% 调整到 35%，-XX:ConcGCThreads从 1 调整为 3。
2. -XX:G1MixedGCLiveThresholdPercent与 -XX:G1HeapWastePercent 确定回收哪些 region，有多少比例垃圾才执行回收，我感觉它们的值原本就蛮激进，就没有调整。
3. -XX:G1MixedGCCountTarget与 -XX:G1OldCSetRegionThresholdPercent 管制 mixed gc 执行多少次，每次回收多少 region，我将 -XX:G1OldCSetRegionThresholdPercent 从 10% 调整到了 15%，让它一次多回收些 old region。
4. 减少保留空间，防止复制存活对象失败，将 -XX:G1ReservePercent 从 10% 调整到 20%。
5. 尽量避免产生大对象，将 -XX:G1HeapRegionSize 减少到 16m。

于是我依照下面调整了 jvm 参数，可是第二天我发现还是有 GC 长耗时，次数也没有缩小，看来问题根因和我调整的参数没有关系。

问题根因

就这样，到了上线日，于是我上线了后面优化大对象的代码，一天后，我发现偶然的 GC 长耗时居然没有了！

问题就这样解决了！！！

然而我心里还是有一个大大的问号，其它环境同样有这个定时工作，一样的运行频率，jvm 配置也全是一样的，为啥其它环境没有问题呢？其它环境业务流量还大一些！

为此，我搜寻了大量对于 g1 大对象的文章，我发现大对象的调配与回收过程有点非凡，如下：

1. 大于 region size 一半的对象是大对象，会间接调配在 old region，且 gc 时大对象不会被复制或挪动，而是间接回收。
2. 大对象回收产生在 2 个中央，一个是并发周期的 clean up 子阶段，另一个是 young gc(这个个性在 jdk8u60 才退出)。

我突然想到，莫非是俄罗斯环境流量太低，触发不了 young gc，且并发周期又因为什么起因没执行，但定时工作又缓缓生成大对象将 old region 占满，导致了 to-space exhausted？

于是，我打算写段代码试验一下，缓缓的只生成大对象，看 g1 会不会回收，如下：

这个一个命令行交互程序，应用如下 jvm 参数启动它：

# 1600m 的堆，16m 的 region size
# rlwrap 作用是使得这个命令行程序更好用
rlwrap java -server -Xms1600m -Xmx1600m -Xss1m -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=1g -Xloggc:/home/work/logs/applogs/gc-%t.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/work/logs/applogs/ -XX:+PrintClassHistogram -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintAdaptiveSizePolicy -XX:+UseG1GC -XX:G1LogLevel=finest -XX:G1HeapRegionSize=16m -XX:MaxGCPauseMillis=200 -jar command-cli.jar

应用了 1600M 的堆，16M 的 region size，所以总共有 100 个 region，jdk 版本是 1.8.0_222。
通过在这个交互程序中输出gc 9437184 20 0，能够生成 20 个 9M 的大对象。

当我输出 3 次 gc 9437184 20 0 后，如下：
我从 gc 日志中发现了一次由 initial marking 触发的 young gc，阐明 g1 启动了并发周期，之所以产生 young gc，是因为 initial marking 是借助 ygc 执行的。

紧接着，我发现了并发标记、从新标记与清理阶段的日志。

而后我在 jstat 中发现老年代使用率升高了，因为 young gc 会回收大对象，所以老年代使用率升高也是失常的。

当我又执行了 2 次 gc 9437184 20 0 后，使得堆占用率再次大于 45%，我发现 gc 日志中呈现如下内容：

看字面意思是，因为 mixed gc 正在执行，没有再次启动并发周期。

可是，我在这种状态下等了良久，也没有看到 mixed gc 的日志进去，不是说 mixed gc 正在执行嚒，它肯定是有什么问题！

于是，我又执行了好几次gc 9437184 20 0，我在 gc 日志中发现了 to-space exhausted！

1. 从下面 do not start mixed GCs, reason: candidate old regions not available 的日志中看到，mixed gc 日志之所以长时间没进去，是因为没有可回收的 region 导致 mixed gc 没有执行，因为咱们只创立了大对象，但 mixed gc 不回收大对象分区，所以的确是没有可回收的 region 的。

2. 从 Humongous Reclaimed: 98 能够发现，这次 young gc，回收了 98 个大对象分区，而咱们总共只有 100 个分区，阐明在 inital marking 之后创立的大对象，的确始终都没有回收。

   注：增加 -XX:G1LogLevel=finest 参数，能力输入 Humongous Reclaimed 这一项。

然而，大对象分区占了 98 个，堆占用率必定超过了 45%，为何始终没有再次启动并发周期呢？

感觉这可能是 jdk 的 bug，于是我别离下了最新的 jdk8u 与 jdk11u 验证，发现问题在最新的 jdk8u 中仍然存在，而 jdk11u 中则不存在，这应该就是 JDK 的 Bug！
于是我通过二分搜寻法屡次编译了不同版本的 JDK，最终确定问题 fix 在 jdk9_b93 与 jdk9_b94 之间。

并在 jdk 的 bug 库中，搜寻到了雷同形容的 bug 反馈，如下：

https://bugs.openjdk.org/brow…

Bug 改变代码如下：

大抵瞄了下代码，可能了解得不完全正确，改变逻辑如下：

1. G1 再次启动并发周期之前，至多须要执行过一次 mixed gc 或young gc，相似于Concurrent Cycles -> mixed gc|young gc -> Concurrent Cycles -> mixed gc|young gc。
2. 咱们的场景是，在并发周期完结之后，因为没有须要回收的分区，导致 mixed gc 理论没有执行，可是咱们只调配了大对象，且大对象又只调配在 old region，所以 young gc 也不可能被触发，而因为下面的条件，Concurrent Cycles也不会被触发，因而最终大对象将堆占满触发了 to-space exhausted。
3. 修复逻辑是，当并发周期完结后，没有须要回收的分区时，should_continue_with_reclaim=false，进而使得容许不执行纯 young gc 而间接启动并发周期，相似于Concurrent Cycles -> Concurrent Cycles。

所以在应用 JDK8 时，像那种零碎流量很小，新生代较大，又有定时工作一直产生大对象的场景，堆简直必然会被缓缓占满，要解决这个问题，可参考如下解决：

1. 优化代码，防止调配大对象。
2. 代码无奈优化时，可思考降级 jdk11。
3. 无奈降级 jdk11 时，可思考减小 -XX:G1MaxNewSizePercent 让新生代小一点，让 young gc 能执行得更频繁些，同时老年代更大，能缓冲更多大对象调配。

思考到咱们负责的其它零碎中，时不时就有一波大响应体的申请，也没法疾速批改代码，于是我对立将 -XX:G1MaxNewSizePercent 减小到 30%，通过察看，批改后 GC 频率有所增加，但暂停工夫有所降落，这是合乎冀望的。

总结

当我在 jdk 的 bug 库中搜寻问题时，发现不少和 G1 大对象相干的优化，晚期 JDK(如 JDK8)的 G1 实现可能在大对象回收上不太欠缺，所以写代码时要留神尽量少创立大对象，以回避这些隐性问题。

注：这之后又遇到了 Update RS (ms) 耗时高，竟也和大对象无关，增加 -XX:-ReduceInitialCardMarks 后解决，看来大对象是万恶之源啊😂