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 | 2019-05-07T22:04:29.977+0800: 729.479: [GC pause (G1 Evacuation Pause) (young), 0.1900627 secs] |
发现有两个阶段，花费了非常久的时间：
1 | [Update RS (ms): Min: 14.0, Avg: 20.6, Max: 34.4, Diff: 20.4, Sum: 165.0] |
其中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 | 2019-05-09T19:56:25.044+0800: 7622.384: [GC pause (G1 Evacuation Pause) (young), 0.0750529 secs] |
1 | [Update RS (ms): Min: 0.0, Avg: 1.3, Max: 5.0, Diff: 5.0, Sum: 10.4] |
效果非常明显。我们的吞吐量修改之后超过了老版本，达到3.2w tps。从gc日志也可以看到Object copy的耗时下降非常多。
这里可以解释两个现象：
- 为什么
Object copy的耗时短了。 - 为什么入参出参小的情况下，新老版本rpc的吞吐量差距小了。
这两个现象的原因都是由于上述问题导致的。
总结
沉淀一个解决YGC问题的方法论：可以通过Jprofile等工具，远程attach之后观察堆中对象的数量变化来定位问题。尤其是那些数量多但是GC之后数量暴跌的类。
意外惊喜
解决这个问题的过程中，我也收获了一些意外惊喜。
jackson序列化
之前我做过一次各种序列化的benchmark，hessian在对象越大的情况下，表现很稳定。我们如果使用jackson在这种大对象的情况下，TPS直接跌倒2w。更加说明了之前的结论。
TimeoutCheckTask的生命周期
排查问题过程中，有同事提出TimeoutCheckTask的生命周期太长了。上面也说了，TimeoutCheckTask的生命周期就是rpc接口的超时时间（上文是3s），非常不合理。如果3s的超时时间，rpc接口平均响应时间只有几ms，那么我们应该尽快让TimeoutCheckTask能够被GC。
关于这个问题我也做了后续修改。HashedWheelTimer支持cancel操作，可以提前结束TimeoutCheckTask。这里也贴一下修改的效果（基于YGC问题修复之后的新版本）：
TimeoutCheckTask优化以后的GC日志：
1 | 2019-05-10T11:59:28.390+0800: 238.610: [GC pause (G1 Evacuation Pause) (young), 0.0161575 secs] |
可以看到，GC效果已经非常好了。但是需要注意的是，修改之后的吞吐量并没有提升，说明修改前后，GC 吞吐量指标应该基本没变化，这也给我们一个提示，GC的一个重要指标是吞吐率，如果吞吐率变化不大，说明GC对于吞吐量的影响不大。