一次线上的 G1 优化实践

e个人觉得想要优化一个系统首先就要对这个系统的特点有所了解。目前我们这个系统的特点是可能会出现短时间内对象产生速度过快，从而造成系统会在某段时间内 STW 时间过长，触发容器的健康检查从而导致容器重启。

注：该系统生产环境使用的机器配置为 4C16G。

我们最初将 CMS 换成 G1 后的参数如下：

-Xms11g -Xmx11g -Xmn8g -XX:+UseG1GC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/java_heapdump.hprof -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+PrintPromotionFailure -XX:+CMSDumpAtPromotionFailure -Xloggc:/home/gc.log

发现还是出现了不少 STW 时间大于 200ms 的情况：

平均 STW 时间也较长：

而且如我开头提到的，由于触发了容器的健康检查，造成容器重启，导致 GC 日志被覆盖了。所以第一次调整优化做了这么两件事：

1. GC 日志增加时间戳，避免容器重启后被覆盖；
2. 不要显示指定新生代大小，造成 G1 的动态调整失效；

优化后的参数为：

-Xms11g -Xmx11g -XX:+UseG1GC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/java_heapdump.hprof -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+PrintPromotionFailure -XX:+CMSDumpAtPromotionFailure -Xloggc:/home/gc.log

可以发现优化效果还是很明显的，吞吐量提高了一丢丢（虽然本身吞吐量就不是瓶颈），平均 STW 时间和最大的 STW 时间也降了不少。

但是过了一段时间后，又出现了问题，系统还是会出现偶发性暂停。

第一天的观察如下：

第二天观察如下：

发现一个明显的特点是并发标记的时间特别长，于是查看相关参数：

[www]# jinfo -flag ConcGCThreads 1
-XX:ConcGCThreads=1
[www]# jinfo -flag ParallelGCThreads 1
-XX:ParallelGCThreads=4

发现并发处理的线程数太少了。

部分 GC 日志：

{Heap before GC invocations=1331 (full 0):
 garbage-first heap   total 11534336K, used 10981195K [0x0000000500000000, 0x0000000500405800, 0x00000007c0000000)
  region size 4096K, 1505 young (6164480K), 4 survivors (16384K)
 Metaspace       used 232665K, capacity 272589K, committed 274096K, reserved 1290240K
  class space    used 26164K, capacity 32701K, committed 32944K, reserved 1048576K
2021-10-01T07:50:20.783+0800: 217581.971: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 2.0483611 secs]
   [Parallel Time: 155.9 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 217581975.3, Avg: 217581975.3, Max: 217581975.3, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 3.9, Avg: 4.4, Max: 5.2, Diff: 1.2, Sum: 17.7]
      [Update RS (ms): Min: 49.3, Avg: 49.6, Max: 49.8, Diff: 0.6, Sum: 198.4]
         [Processed Buffers: Min: 274, Avg: 294.2, Max: 305, Diff: 31, Sum: 1177]
      [Scan RS (ms): Min: 1.1, Avg: 1.2, Max: 1.3, Diff: 0.2, Sum: 4.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 100.1, Avg: 100.5, Max: 101.0, Diff: 0.9, Sum: 402.1]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.2]
         [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: 155.8, Avg: 155.9, Max: 155.9, Diff: 0.0, Sum: 623.5]
      [GC Worker End (ms): Min: 217582131.2, Avg: 217582131.2, Max: 217582131.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 1.2 ms]
   [Other: 1891.2 ms]
      [Evacuation Failure: 1856.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 27.5 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 0.3 ms]
      [Humongous Reclaim: 1.2 ms]
      [Free CSet: 1.1 ms]
   [Eden: 6004.0M(6076.0M)->0.0B(560.0M) Survivors: 16.0M->0.0B Heap: 10.5G(11.0G)->7544.0M(11.0G)]
Heap after GC invocations=1332 (full 0):
 garbage-first heap   total 11534336K, used 7725055K [0x0000000500000000, 0x0000000500405800, 0x00000007c0000000)
  region size 4096K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 232665K, capacity 272589K, committed 274096K, reserved 1290240K
  class space    used 26164K, capacity 32701K, committed 32944K, reserved 1048576K
}
 [Times: user=7.67 sys=0.00, real=2.05 secs]

可以看到已经出现了 to-space exhausted，而且花费了 2s 多。

整体得出了如下结论：

• 系统吞吐量还不错，大多数情况下 STW 时间很快；
• 还是会出现 STW 时间很长的情况；
• 并发标记时间特别长；
• 并发处理线程数量偏少；

优化后的参数为：

-Xms12g -Xmx12g -XX:ConcGCThreads=3 -XX:ParallelGCThreads=6 -XX:InitiatingHeapOccupancyPercent=35 -XX:G1ReservePercent=15 -XX:MaxMetaspaceSize=512m -XX:MetaspaceSize=512m -XX:+UseG1GC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/  -Xloggc:/home/gc_%t.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintCommandLineFlags -XX:+PrintHeapAtGC -XX:+UseFastAccessorMethods

优化点如下：

• 适当增加堆内存
• 增加并发线程数
• 提前触发标记（可能会造成更多的回收次数，但是相比更长的停顿时间，这个是可以接收的）
• 增加 s 区动态范围
• 减少因为 Metaspace 造成的 GC 次数；
• 可以考虑不固定设置堆内存大小（待定）；

优化后第二天观察：

可以发现整个系统的 STW 降低了很多，而且都在 G1 的控制范围之内。

而且 GC 的原因也很简单：

都在正常范围之内。

总体来看，是非常成功的。

但 G1 就是银弹吗，其实也不是，在对这个项目优化的同时，我们也把另一个项目改成了使用 G1，但是第二天发现线上频繁 502，不得已又赶紧换回了 CMS，换回 CMS 后运行了两天，一切正常。对于这个项目，根据观察，目前大致有这么几个结论：

• 频繁 502 的时候，其实整体来看流量并没有激增；
• 每秒产生 120M+ 对象（换成 G1 效果比较好的那个项目每秒产生 40M+ 对象），是否与这个有关，还待进一步观察分析；
• 502 期间系统有大量 Full GC，但是一定比例 Full GC 的原因是 System.gc()；可诡异的是切换成 CMS 后观察了一天一次 Full GC 都没有产生；
• Dump 文件来看有大量临时对象；

目前来看的话，还是很诡异的，但是是不是就说明在这个项目上 G1 就比 CMS 差呢，其实我内心觉得不是，觉得还需要再继续观察，毕竟这种活就需要不停的观察、分析、修改参数、观察…