揪出一个导致GC慢慢变长的JVM设计缺陷

大家好，我是你假笨，来自阿里 JVM 团队，花名寒泉子，工作快 7 年了，之前一直负责支付宝开发框架 SOFA 的研发，从 2014 年底开始从事 JVM 及性能相关的工作，今天很高兴在这个高大上的架构群里和大家分享一些稍微底层点的东西，希望大家能有所收获。

这也是我第一次通过微信群的方式进行分享，还是比较新鲜的，如果体验好的话，后面可以时不时做点这种形式的分享。

今天要给大家分享的内容和 YGC（Young GC）有关，是我最近碰到的一个案例，希望将排查思路分享给大家，如果大家后面碰到类似的问题，可以直接作为一个经验来排查。

我之前在公众号里其实写过几篇 YGC 的文章，也许其中有人已经看过了，没看过的可以去看看，那两个坑在这里就不再描述，大家可以直接当经验使用。

Java 堆分为新生代和老生代，YGC 其实就是针对新生代的垃圾回收，对象都是优先在新生代分配的，因此当新生代内存不够分配的时候就会触发垃圾回收，正常情况下可能触发一次 YGC 就可以解决问题并正常分配的，当然也有极端情况可能要进行大扫除，对整个堆进行回收，也就是我们说的 Full GC，这种情况发生就会比较悲剧了。

这里再提一下，YGC 也是会 STW（stop the world） 的，也就是会暂停整个应用，不要觉得 YGC 发生频繁不是问题。

说实话我比较不喜欢排查 YGC 的问题，因为 YGC 的日志太简单了，正常情况下只能知道新生代内存从多少变到了多少，花了多长时间，再无其它信息了。

所以当有人来咨询为什么我的程序 YGC 越来越长的问题的时候，我其实是抗拒的，不过也无奈，总得尝试去帮人家解决，包括前面说的那两个问题，也是费了不少精力查出来的，希望大家珍惜。。。

有些时候你越想逃避，偏偏就会找上你，YGC 的问题最近说实话找我的挺多的，不过有好些都是踩过的坑，所以能顺利帮人家解决，但是今天要说的这个问题是之前从未碰到过的，是一个全新的问题，所以也费了我不少精力，也因为其他问题要查被拖延了几天。

这个问题最终排查下来其实是 JVM 本身设计上面的一个缺陷，我改天也会提到 openjdk 社区去和大家一起讨论下这个设计，希望能彻底根治这个问题。

这个问题现象也很明显，就是发现 YGC 的时间越来越长，从 20ms 慢慢增加到100ms+，甚至还一直在涨。

不过这个增长过程还是挺缓慢的，其实 YGC 时间在几十毫秒我个人认为算正常现象，没必要去深究，再说了还是经过压测了一个晚上才涨上来的，所以平时应该也不是啥问题吧，不过这次正巧赶上年中大促，所以大家对时间也比较敏感，便接手来排查这个案例了。

首先排除了之前碰到的几种情况，然后我要同事加了一个我们 alijdk 特定的参数，可以打印 YGC 过程里具体各个阶段的耗时情况，可惜的是并没有找出问题，因为我们漏掉了一些点，导致没有直接定位出来。

于是我怀疑那些没跟踪到的逻辑，首先怀疑的就是引用这块的处理，所以叫同事加上了 -XX:+PrintReferenceGC 这个参数，这个参数会打印各种引用的处理时间，大概如下：

[GC (Allocation Failure) [ParNew[SoftReference, 0 refs, 0.0001451 secs][WeakReference, 8 refs, 0.0001191 secs][FinalReference, 0 refs, 0.0001226 secs][PhantomReference, 0 refs, 0 refs, 0.0001833 secs][JNI Weak Reference

, 0.0111948 secs]: 81926K->6K(92160K), 0.0141540 secs] 82337K->417K(296960K), 0.0145097 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

从当时的那个日志里，我发现了一个现象，就是随着 YGC 时间的增长，JNI Weak Reference 的处理耗时也在不断增长，所以基本就定位到了 YGC 增长的直接原因。