实践服务可用性的提高方式 -- JVM参数调优

背景

首先说明一下背景，需要调优的服务是一个需要较高吞吐和可用性的服务，吞吐量目前没有达到瓶颈，还可以通过增加服务器进行水平扩展，但是可用性亟需提高，而评价可用性的标准之一就是所有请求中响应时间在可用范围内的请求数量。

由于最初是按照部门内的默认jvm参数来配置，导致在压测过程中gc表现并不好，gc时间略长，次数也很频繁，影响到了部分请求的响应时间，导致可用性降低，具体的数据将在后文中提到。

所以此次调优，首要目标是降低单次gc的时间，提高服务可用性；其次是降低gc发生的频率，减少受到gc影响的请求占比。

过程

环境介绍

服务使用的是JDK8，因为参数调整需要不断重启服务，所以是在测试环境中进行，服务器选用的是和线上环境配置相同的8核16g内存的虚拟机，压测过程每次持续6分钟，单台服务器流量维持在1500tps左右。堆内存参数设置是-Xms8g -Xmx8g -Xmn6g，新生代使用ParNew，老年代使用CMS。

按照最初的参数先进行一次压测后的结果：几乎不会发生老年代full gc，新生代gc大概2-3s执行一次，单次耗时20ms左右

第一步：扩大新生代

根据新生代gc特性，对新生代空间进行增加；同时需要参考老年代稳定期间的空间占用，设置合适的空间比例。

调整后的内存分配参数为：-Xms8g -Xmx8g -Xmn6g

输出gc日志：

2020-12-17T16:00:36.483+0800: 1501.418: [GC (Allocation Failure) 2020-12-17T16:00:36.483+0800: 1501.418: [ParNew: 6206984K->44755K(6228544K), 0.0200515 secs] 6288205K->125976K(8325696K), 0.0201992 secs] [Times: user=0.12 sys=0.01, real=0.02 secs]
2020-12-17T16:00:46.803+0800: 1514.738: [GC (Allocation Failure) 2020-12-17T16:00:46.803+0800: 1514.738: [ParNew: 6210387K->41551K(6228544K), 0.0180538 secs] 6291608K->122771K(8325696K), 0.0181839 secs] [Times: user=0.11 sys=0.00, real=0.02 secs]

观察日志发现，gc的频率降低到10s左右一次，但是单次gc的耗时间并没有发生明显变化，仍然保持在20ms左右。

单次耗时变化不明显应该是和新生代复制回收算法有关，如果主要的耗时是由于堆存活对象的复制，那不管怎么调整新生代大小都是不会对这个时间造成太大影响的。

第二步：换用G1

经过对回收过程的分析，parnew在进行垃圾回收的标记和回收阶段都是STW的，而G1的并发标记阶段是不停顿的，所以感觉可能是ParNew这个垃圾收集器对回收时间造成的限制，于是计划对垃圾收集器进行替换，改用基于停顿预测模型的G1收集器。

修改相关参数为-XX:G1HeapRegionSize=8m -XX:+UseG1GC -XX:ParallelGCThreads=8 -XX:G1ReservePercent=10 -XX:MaxGCPauseMillis=20

这里就不再解释这些参数的具体含义了，g1的日志和parnew的日志差异很大，截取部分输出的日志：

2020-12-17T17:01:57.005+0800: 380.506: [GC pause (G1 Evacuation Pause) (young), 0.0124944 secs]
   [Parallel Time: 10.8 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 380506.2, Avg: 380506.2, Max: 380506.3, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.7, Avg: 1.1, Max: 2.1, Diff: 1.4, Sum: 7.5]
      [Update RS (ms): Min: 0.0, Avg: 0.6, Max: 1.0, Diff: 1.0, Sum: 4.0]
         [Processed Buffers: Min: 0, Avg: 7.7, Max: 22, Diff: 22, Sum: 54]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 8.5, Avg: 8.9, Max: 9.0, Diff: 0.5, Sum: 62.1]
      [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: 7]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Total (ms): Min: 10.6, Avg: 10.6, Max: 10.7, Diff: 0.1, Sum: 74.4]
      [GC Worker End (ms): Min: 380516.8, Avg: 380516.8, Max: 380516.9, Diff: 0.1]
   [Code Root Fixup: 0.2 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 1.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.5 ms]
   [Eden: 6080.0M(6080.0M)->0.0B(6096.0M) Survivors: 64.0M->48.0M Heap: 6228.4M(8192.0M)->135.9M(8192.0M)]
 [Times: user=0.08 sys=0.00, real=0.02 secs]

通过对日志的分析可以发现：

• 从频率上看：10s一次 频率不变；
• 从单次耗时上看，主要分布在12-15ms之间

从可用性上来看，是一次比较明显的提高。但是发现了两个新的问题，启动慢收集问题和回收时间波动问题。

把这两个问题先放置一下，在解决这两个问题之前，先做了一些与之无关的改动，测试了一下其他改动的影响：将堆的总大小扩展到12g，新生代通过Xmn参数分配10g内存

截取输出日志如下：

2020-12-25T10:54:38.827+0800: 257.354: [GC pause (G1 Evacuation Pause) (young), 0.0154331 secs]
   [Parallel Time: 11.5 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 257354.3, Avg: 257354.4, Max: 257354.4, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 1.1, Avg: 1.3, Max: 2.3, Diff: 1.2, Sum: 10.6]
      [Update RS (ms): Min: 0.0, Avg: 0.8, Max: 1.4, Diff: 1.4, Sum: 6.5]
         [Processed Buffers: Min: 0, Avg: 7.6, Max: 16, Diff: 16, Sum: 61]
      [Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 1.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 8.6, Avg: 8.8, Max: 8.9, Diff: 0.3, Sum: 70.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.4, Max: 3, Diff: 2, Sum: 11]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 1.1]
      [GC Worker Total (ms): Min: 11.2, Avg: 11.3, Max: 11.4, Diff: 0.3, Sum: 90.2]
      [GC Worker End (ms): Min: 257365.6, Avg: 257365.7, Max: 257365.8, Diff: 0.2]
   [Code Root Fixup: 0.2 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 1.9 ms]
   [Other: 1.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 1.1 ms]
   [Eden: 10176.0M(10176.0M)->0.0B(10176.0M) Survivors: 64.0M->64.0M Heap: 10.1G(12.0G)->155.3M(12.0G)]
 [Times: user=0.10 sys=0.00, real=0.02 secs]

待gc进入稳定期后，触发gc的时间间隔进一步拉长，达到了16s触发一次；单次gc的执行时间变化不明显。

第三步：解决问题

现在来探讨上面提到的两个问题

1、启动初期的收集耗时过长

在服务刚启动的前几次垃圾收集过程中，发现耗时甚至达到了60ms，而且MaxGCPauseMillis这个参数看起来是失效了。在经过数次垃圾回收之后gc暂停时间逐渐恢复稳定。

原因其实很简单，服务里应该是存在一部分生来生命周期就很长的对象，这部分必定是会进入老年代的，由于升代问题，需要在存活过几次垃圾回收后再升到老年代中。

通过修改MaxTenuringThreshold的大小，可以对这个问题的原因进行验证，随着这个参数的减小，持续的时间也在降低。不过虽然通过设置这个参数能够减少这一过程持续的时间，但是不解决根本问题。

之后从MaxGCPauseMillis这个参数的失效入手，了解了一下这个参数的失效原因，发现是MaxGCPauseMillis和Xmn两个参数之间是不兼容的，于是将手动指定Xmn的参数去掉，观察启动情况，发现问题得到了解决。

2、单次回收时间会出现一定的波动

观察在当前条件下单次垃圾回收的时间最短可以达到11ms，但是并不稳定，有时也会出现17ms左右的耗时。想要提高停顿时间的稳定性，避免一些偶发的波动情况。

以下是对两种耗时情况下部分日志的截取：

- 耗时：0.0167801 s
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.8, Max: 2.3, Diff: 2.3, Sum: 6.8]
[Object Copy (ms): Min: 0.0, Avg: 8.6, Max: 10.2, Diff: 10.2, Sum: 68.8]
[GC Worker Total (ms): Min: 0.1, Avg: 10.5, Max: 13.2, Diff: 13.1, Sum: 83.7]


- 耗时：0.0131570 secs
[Ext Root Scanning (ms): Min: 0.2, Avg: 1.0, Max: 2.4, Diff: 2.2, Sum: 7.6]
[Object Copy (ms): Min: 8.3, Avg: 8.7, Max: 8.9, Diff: 0.5, Sum: 69.7]
[GC Worker Total (ms): Min: 10.0, Avg: 10.6, Max: 10.8, Diff: 0.9, Sum: 84.7]

观察日志，发现是在复制对象的过程中出现了cpu耗时的不均衡，导致虽然总的时间相似，但是存在最大值偏大的情况。

最初怀疑是和region堆数量相关，但是去翻了翻深入理解java虚拟机里面的介绍，结合服务特点想了一下，可能是由于当前存活的对象集中分布在了部分region中，导致region分配给cpu时，不同cpu处理的复制对象数量不同。

根据这个猜想，打算把region调小一些，更小的粒度会使单个region的收集时间降低，也能够更平均地分散给不同的cpu进行处理。

因为g1最大是2048个region，根据目前的堆大小，每个region最小可以设置成8mb。之后再次进行压测，虽然还是存在这个问题，但是稳定性更高了，波动出现的频率和波动范围有明显的降低，gc的耗时最终稳定在了13-15ms之间。

弯路

这里有一条调优参数的错误使用范例。

为了达到最短停顿时间的效果，将MaxGCPauseMillis这个参数设置为了10，期望是能够提前触发gc，使单次停顿时间压缩到10ms以内。之后再次进行压测，发现效果不及预期：gc发生过于频繁，而且停顿时间不能保证在10ms以内。

追究原因是，当前的gc复制算法是存在极限的，如果想通过设置最大暂停时间把时间控制在10ms左右，因为存活对象不会减少太多，会导致gc触发非常频繁。如果在当前场景下还想继续压缩gc时间，可能需要改用更新的垃圾收集器例如ZGC了，但是由于需要升级到JDK11以上的版本，成本过高，遂放弃。

效果

对于gc优化的效果，实际上应该是能够有一种方式来进行量化分析的，这里找了美团一篇文章中提到的一个公式：时间T内发生N次GC，受GC影响请求占比=(接口响应时间+GC时间)×N/T来衡量效果。

在不受gc影响情况下，服务性能大概是单次请求6-7ms的平均rt，基于这个数据来进行优化效果的分析。

• 在改参数调优之前，3s触发一次gc，单次平均停顿20ms，根据计算，对请求的影响率大概在千分之九左右，平均每分钟的gc耗时是600ms

• 调整完之后，gc是大约每14s触发一次，单次平均停顿小于14ms，最终的影响率是小于千分之一点五，而每分钟的gc耗时是约60ms

结合文章开头定下的目标：一是要降低单次gc的时间，提高服务可用性；其二是要降低gc发生的频率，减少受到gc影响的请求占比。

最终结果可以总结为：单次gc停顿平均时间比之前减少6ms，降幅约30%；gc触发的间隔提高了11s，频率降低到原来的五分之一，对整体请求的影响占比从千分之九降低到千分之一点五，降低了83%。

这么一看，效果显著。不过这里的所有数据都是基于测试环境数据和压测结果的分析，并不表示线上也能有这样的效果，具体优化效果如何还是要根据线上的实际表现才能做出判断。

疑问

g1基于停顿预测模型，按照书上的介绍是会选择回收价值高的对象进行回收，但是为什么在新生代回收的过程中，看起来像是对全部region进行了垃圾回收？

这是因为G1提供了两种GC模式，Young GC和Mixed GC。

Young GC：选定所有年轻代里的Region。通过控制年轻代的region个数，即年轻代内存大小，来控制young GC的时间开销。
Mixed GC：选定所有年轻代里的Region，外加根据global concurrent marking统计得出收集收益高的若干老年代Region。在用户指定的开销目标范围内尽可能选择收益高的老年代Region。

这个说法也解释了我的另一个疑问，就是如果进行选择回收，那么新生代的对象年龄应该怎么计算，g1应该是逃避了这个问题。此外还有一点，G1不提供fullGC，MixedGC如果不够用，就会使用serial old。