YGC导致吞吐量降低

YGC导致吞吐量降低

背景

MUSIC-RPC(网易云音乐内部使用的rpc)进行了大版本升级,在升级之后的压测过程中发现吞吐量相较于旧版本下降了百分之20左右(3w tps -> 2.2w tps),注意这个3w tps是我们在为保证功能正确的情况下,使用非常大的对象(入参、出参)压测出的结果。

具体表现和各个指标

具体表现是吞吐量下降(100个并发),rt增高。性能QA反应,观察到YGC的次数和频率都远超旧版本,从哨兵系统上看到表现如下:

新版本:

老版本:

另外我们发现,新老版本的服务端的响应时间、YGC情况等均没有很大差别。另外,新老版本的网卡均没有瓶颈。

所以上述种种现象表现来看,瓶颈出现在客户端。

基本排查

可以看到,不管是YGC的次数还是YGC的时间都有非常大的上涨。由于只是进行了YGC,而且压测情况下由于YGC过于频繁,所以dump堆的作用比较小,但是还是尝试性的去进行了一些dump(新老版本各dump两次),dump出的堆果然并没有发现什么问题,没有过大的对象。

dump堆虽然没能直接找出问题,却有额外的收获:hashedwheeltimer的task非常多,可以复用。由于新老版本都存在这个问题,所以这个问题并不是导致两个版本吞吐量差异的主要问题。

dump堆无果的情况下,看下gc日志(线上是g1收集器):

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
26
27
2019-05-07T22:04:29.977+0800: 729.479: [GC pause (G1 Evacuation Pause) (young), 0.1900627 secs]
[Parallel Time: 187.2 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 729479.8, Avg: 729484.7, Max: 729490.6, Diff: 10.8]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.8, Max: 3.4, Diff: 3.4, Sum: 6.6]
[Update RS (ms): Min: 14.0, Avg: 20.6, Max: 34.4, Diff: 20.4, Sum: 165.0]
[Processed Buffers: Min: 44, Avg: 87.2, Max: 114, Diff: 70, Sum: 698]
[Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.1, Sum: 1.2]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 148.9, Avg: 160.4, Max: 162.5, Diff: 13.5, Sum: 1283.5]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 5.8, Max: 10, Diff: 9, Sum: 46]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
[GC Worker Total (ms): Min: 176.2, Avg: 182.1, Max: 187.0, Diff: 10.8, Sum: 1457.0]
[GC Worker End (ms): Min: 729666.8, Avg: 729666.8, Max: 729666.9, Diff: 0.1]
[Code Root Fixup: 0.2 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.4 ms]
[Other: 2.3 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.4 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.9 ms]
[Eden: 2796.0M(2796.0M)->0.0B(1992.0M) Survivors: 208.0M->376.0M Heap: 5632.0M(8192.0M)->3238.0M(8192.0M)]
[Times: user=1.40 sys=0.00, real=0.19 secs]

发现有两个阶段,花费了非常久的时间:

1
2
3
[Update RS (ms): Min: 14.0, Avg: 20.6, Max: 34.4, Diff: 20.4, Sum: 165.0]
[Processed Buffers: Min: 44, Avg: 87.2, Max: 114, Diff: 70, Sum: 698]
[Object Copy (ms): Min: 148.9, Avg: 160.4, Max: 162.5, Diff: 13.5, Sum: 1283.5]

其中object copy花费了非常多的时间。另外一个现象:[Eden: 2796.0M(2796.0M)->0.0B(1992.0M) Survivors: 208.0M->376.0M Heap: 5632.0M(8192.0M)->3238.0M(8192.0M)],每次YGC的时候,对象都会被完全回收,也就是说不存在无法被回收的对象。加上我们上面发现对象copy花费很久,我们判定:新版本YGC的问题,就是由于对象频繁分配导致的

继续跟组内网关的负责人聊了一下,他建议关注一下YGC的吞吐率这个指标,如果吞吐率一样,那么说明CPU花费在GC上的时间一直,说明导致RPC框架吞吐量下降的原因不是GC。听到这里我重新看了一下吞吐率指标:

新版本:

老版本:

可以看到,吞吐率相差百分之十五,而且新版本的吞吐率只有百分之八十一,非常低的一个数字。而且我们使用arthas同样抓了一波新老版本rpc主要方法执行的耗时,同样没有发现差别。

代码排查

由于新版本rpc的代码变动非常非常大,基本不可能通过还原代码来进行问题排查,这里对一些可能的点进行了还原和验证。

排查过程中,发现新老协议有一个区别,老协议编解码中,对一段数据进行了缓存,新版本没有缓存,每次都编解码,怀疑是这个问题,修复之后继续观察指标:

可以看到,YGC的次数确实降低了,但是YGC的时间变化不大,吞吐量上升了一点点。但是压测发现,总体TPS还下降了2k。说明老版本的协议虽然在GC表现上不错,但是在性能上不好,耗时更长。

说明协议层的变化也不是问题的根本原因。

有趣的现象

排查过程中,同事提议:应该调整小入参和出参。在入参和出参非常大的情况下,可能会混淆我们的视听,因为从各个监控软件上发现,基本上所有的耗时都集中在序列化和反序列化。如果我们降低入参和出参,会让其他地方的耗时或者内存分配体现的更明显一些。

把出参和入参删除了一些属性,重新压测。压完发现一个很有意思的现象:新版本的吞吐量本身相较于老版本低20%,入参和返回值对象内容变少之后,吞吐量相比于老版本只低10%了。

这时候我们还不能知道为什么会出现这种现象,关于这个现象只能得出结论:出参和入参越小,新版本的RPC和老版本的RPC性能约接近。仅此而已。

监控和对比

至此我们进入了一个困局,由于dump堆的成本比较大,需要dump,然后压缩(不压缩太大,有的超过5G),然后再把它下载到跳板机,再从跳板机上下载下来再分析等等。我们需要一些实时的监控,这时候我们的性能测试建议使用jprofile进行远程监控。

jprofile远程监控需要一个agent,具体的配置和使用不说了。我和同事一个人链接新版本,一个人链接老版本,然后实时监控对比两个堆的活跃对象以及变化。

到这里看到一个非常可以的问题,就是我们的User对象(User对象是RPC调用的参数)在两个堆中的表现:

新版本:

可以看到,有84w个。

老版本:

可以看到只有5w多个。

另外一个现象,就是新版本中,User可以被GC回收,但是回收完一般还会剩余10w+个,而老版本可能会回收到0!

但是新版本没有产生Full GC,这里说明:新版本中,User的生命周期比老版本的长!

看看引用的路径:

这里music-rpc也使用HashedWheelTimer做超时检测,TimeoutCheckTask的声明周期就是RPC接口的超时时间,这里我们是3s。我们从上图引用关系发现,User被绑定到了Response上,Response又绑定到了MusicFuture上,最终被绑定到了TimeoutCheckTask上。

新版本中,我确实在Response中增加了一个private Object result的引用。那么新版本中,TimeoutCheckTask不被回收的话,我们的返回值User也没法被回收。在老版本中,由于没有这个引用关系,所以User能够被更快的回收。

在请求级别上看,一个请求花费在10ms以内,如果User对象被绑定到TimeoutCheckTask上,则生命周期延长到3s。那么这里结案了,最终原因并不是新版本中分配的临时对象比老版本多了,而是临时对象的生命周期被拉长了。

修改之后

修改方式很简单,只要去除Response中的引用即可。修改之后看看各个指标:

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
26
27
2019-05-09T19:56:25.044+0800: 7622.384: [GC pause (G1 Evacuation Pause) (young), 0.0750529 secs]
[Parallel Time: 69.0 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 7622384.1, Avg: 7622396.1, Max: 7622414.8, Diff: 30.8]
[Ext Root Scanning (ms): Min: 0.0, Avg: 1.1, Max: 5.7, Diff: 5.6, Sum: 9.1]
[Update RS (ms): Min: 0.0, Avg: 1.3, Max: 5.0, Diff: 5.0, Sum: 10.4]
[Processed Buffers: Min: 0, Avg: 30.8, Max: 129, Diff: 129, Sum: 246]
[Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.4, Diff: 0.3, Sum: 1.5]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 37.7, Avg: 54.1, Max: 60.0, Diff: 22.3, Sum: 432.7]
[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: 8]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
[GC Worker Total (ms): Min: 38.0, Avg: 56.8, Max: 68.8, Diff: 30.8, Sum: 454.4]
[GC Worker End (ms): Min: 7622452.8, Avg: 7622452.9, Max: 7622452.9, Diff: 0.1]
[Code Root Fixup: 0.3 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.9 ms]
[Other: 4.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 2.5 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 1.4 ms]
[Eden: 4532.0M(4532.0M)->0.0B(4560.0M) Survivors: 380.0M->352.0M Heap: 6049.2M(8192.0M)->1489.3M(8192.0M)]
[Times: user=0.42 sys=0.00, real=0.22 secs]
1
2
3
[Update RS (ms): Min: 0.0, Avg: 1.3, Max: 5.0, Diff: 5.0, Sum: 10.4]
[Processed Buffers: Min: 0, Avg: 30.8, Max: 129, Diff: 129, Sum: 246]
[Object Copy (ms): Min: 37.7, Avg: 54.1, Max: 60.0, Diff: 22.3, Sum: 432.7]

效果非常明显。我们的吞吐量修改之后超过了老版本,达到3.2w tps。从gc日志也可以看到Object copy的耗时下降非常多。

这里可以解释两个现象:

  1. 为什么Object copy的耗时短了。
  2. 为什么入参出参小的情况下,新老版本rpc的吞吐量差距小了。

这两个现象的原因都是由于上述问题导致的。

总结

沉淀一个解决YGC问题的方法论:可以通过Jprofile等工具,远程attach之后观察堆中对象的数量变化来定位问题。尤其是那些数量多但是GC之后数量暴跌的类。

意外惊喜

解决这个问题的过程中,我也收获了一些意外惊喜。

jackson序列化

之前我做过一次各种序列化的benchmarkhessian在对象越大的情况下,表现很稳定。我们如果使用jackson在这种大对象的情况下,TPS直接跌倒2w。更加说明了之前的结论。

TimeoutCheckTask的生命周期

排查问题过程中,有同事提出TimeoutCheckTask的生命周期太长了。上面也说了,TimeoutCheckTask的生命周期就是rpc接口的超时时间(上文是3s),非常不合理。如果3s的超时时间,rpc接口平均响应时间只有几ms,那么我们应该尽快让TimeoutCheckTask能够被GC。

关于这个问题我也做了后续修改。HashedWheelTimer支持cancel操作,可以提前结束TimeoutCheckTask。这里也贴一下修改的效果(基于YGC问题修复之后的新版本):

TimeoutCheckTask优化以后的GC日志:

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
26
27
2019-05-10T11:59:28.390+0800: 238.610: [GC pause (G1 Evacuation Pause) (young), 0.0161575 secs]
[Parallel Time: 10.4 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 238610.8, Avg: 238618.0, Max: 238620.9, Diff: 10.1]
[Ext Root Scanning (ms): Min: 0.0, Avg: 1.3, Max: 8.4, Diff: 8.4, Sum: 10.2]
[Update RS (ms): Min: 0.0, Avg: 0.3, Max: 1.2, Diff: 1.2, Sum: 2.4]
[Processed Buffers: Min: 0, Avg: 29.9, Max: 138, Diff: 138, Sum: 239]
[Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.5, Diff: 0.4, Sum: 1.4]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
[Object Copy (ms): Min: 0.0, Avg: 0.4, Max: 1.5, Diff: 1.5, Sum: 3.5]
[Termination (ms): Min: 0.0, Avg: 0.8, Max: 1.2, Diff: 1.2, Sum: 6.6]
[Termination Attempts: Min: 1, Avg: 1.5, Max: 3, Diff: 2, Sum: 12]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[GC Worker Total (ms): Min: 0.2, Avg: 3.1, Max: 10.3, Diff: 10.1, Sum: 24.6]
[GC Worker End (ms): Min: 238621.1, Avg: 238621.1, Max: 238621.1, Diff: 0.1]
[Code Root Fixup: 0.3 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.8 ms]
[Other: 4.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 2.9 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 1.1 ms]
[Eden: 4908.0M(4908.0M)->0.0B(4908.0M) Survivors: 4096.0K->4096.0K Heap: 5263.2M(8192.0M)->355.3M(8192.0M)]
[Times: user=0.02 sys=0.01, real=0.02 secs]

可以看到,GC效果已经非常好了。但是需要注意的是,修改之后的吞吐量并没有提升,说明修改前后,GC 吞吐量指标应该基本没变化,这也给我们一个提示,GC的一个重要指标是吞吐率,如果吞吐率变化不大,说明GC对于吞吐量的影响不大。