记一次full gc耗时且频繁的故障定位

背景

事情最初是LZ这边用jersey提供的客户端API封装了一个rest客户端集成到业务系统A中，结果某次系统A在线上运行时崩了，分析线程栈的dump文件时，发现是因为大量线程阻塞拖跨了应用。

线程阻塞的原因是因为jersey的方法内部存在同步操作，遇到流量陡增并且机器资源也比较紧张时对CPU调度产生了影响，导致线程阻塞耗时久，请求处理慢。恶性循环下，导致线程爆了。

于是对封装的rest客户端进行了减少同步操作的优化，优化的措施可以看LZ的一些使用jersey的客户端API封装rest客户端优化建议这篇文章。

优化之后的rest客户端，自然是要做一些压测来看下性能，然后，问题来了。

新的问题

首先，对未优化的老版本做一些压测作为基准数据，老版本的tps虽然不高，但是持续压测一段时间后，内存、CPU、GC情况看起来还是比较稳定。

优化后的新版本，在相同并发情况下，在压测的最初时间段，可以很明显的看到吞吐量有一个质的提升。在持续压测一段时间后，出现了应用进程hung死的现象。此时CPU占用基本是100%的状态。即使停止压测，这种现象还是存在，通过jvisualvm的界面查看内存情况，内存居高不下，像是内存溢出了。停止压测，查看GC信息，但是依然频繁full gc，且full gc耗时很久。在压测过程中dump线程栈信息，优化前的同步操作阻塞线程的情况很少，几乎忽略不计。

定位

p.s. 堆内存配置：最大堆内存3G，初始内存3G，老年代与新生代比例设置的是2：1，用的Parallel垃圾收集器

我重新配置JVM参数，打印GC日志，重新压测，然后实时查看GC日志，发现最初young gc虽然频繁，但是full gc还是隔一段时间才会触发，不过full gc还是比较耗时，可能几秒。但是看起来至少程序还可以正常运行。压测一段时间后，full gc开始频繁且耗时，最长的一次可能达到20多秒，要知道这个最大堆内存只有3g。

即使一直在full gc，但是老年代内存，依然无法回收掉，如下：

本来猜测，可能是每次请求临时大对象过多，所以老版本的时候还可以正常的gc掉，新版本由于tps高于老版本，说明，相同时间段内产生的临时大对象更多导致，但是这里显示老年代迟迟回收不掉，所以应该不是临时变量导致的。

然后使用jmc查看热点类的时候，发现HashMap占比过多，达到20%，其实这里判断错了，所以后续定位不到原因。

这个时候，虽然没有办法，但是分析堆dump是最好的选择。但是进程一直在full gc，所以使用jvisualvm来dump堆信息失败，使用命令也没有响应，然后使用-F强制执行，经过几个小时后，终于dump下来一个大小几个G的堆dump文件。

接下来使用mat查看dominator_tree的时候，发现java.lang.ref.Finalizer对象及引用对象的内存占比达到了98%。查看发现了问题原来出在Jersey的ClientRuntime类，如下：

可以看到Finalizer类引用了很Finalizer实例，每个实例引用ClientRuntime实例。这时候，猜测应该是ClientRuntime重载finalize方法的原因，查看源码，果然是：

它重载这个方法进行垃圾回收时的资源释放。

这里简单说明下Finalizer与重载finalize方法关系。如果某个类实现了finalize方法，在构造实例后，JVM会创建一个Finalizer实例引用它，看上面那个mat分析的截图，可以知道Finalizer这个类系统类是可以做为GC根的，所以最终引用的实现了finalize方法的类对象是可达的，所以GC的时候不会被回收掉，多次后就放入了老年代，并且实现了finalize方法会被放入一个引用队列中。

这个引用队列会由一个Finalizer线程不停的弹出一个对象并调用finalize方法，之后取消Finalizer对象的引用关系，下次GC才会回收掉。

所以上面这里说明了它能被GC掉的原因，之前认为这个Finalizer线程优先级特别低，执行的机会也要低于工作线程，这样导致了这类对象被GC的更慢，其实这是因为这个框架的实现有同步操作的原因，我看了JDK的源码，Finalizer线程优先级的值为8（JDK7中），当然了实际优先级是和操作系统有关。

然后，我查看dump的线程信息：

发现，竟然还存在同步操作，根据这个ID查下，发现对象初始化调用的时候，也必须持有这个锁，这个锁是全局唯一的，所有初始化操作包括执行finalize方法都必须持有这把锁（200个工程线程加上1条Finalizer线程此时有100多个线程阻塞在这个锁上）！！！这便是为什么 GC特别慢的原因了。

这下就全部清楚了。

原因

1. 未优化版本为什么没有问题：

因为未优化版本使用相同的并发数，每个请求同步操作过多，整体吞吐量上不来，虽然每个请求都要创建一定数量 的ClientRuntime对象，但是tps在这摆这，某个时间段也只创建这么多个对象，虽然GC比较慢，但是创建与回收勉强能达到一个平衡，所以没有问题。

2. 优化后的版本为什么出现问题：

优化后的版本，减少每个请求的同步操作次数，请求处理速度更快，整体tps，上来了，能处理的请求更多了，虽然每个请求创建 的ClientRuntim对象还是这么多，但是某个时间段创建的总数更多了。同时 ，每条线程阻塞的机会变少，又导致Finalizer这个守护线程执行的机会更少，引用队列的要回收的对象更多，但是处理速度更慢。恶性循环，所以导致了后来频繁full gc，且full gc非常耗时。

3. 为什么停止请求后还一直在full gc，内存下不来：

因为这些要回收的对象都是在引用队列中，Finalizer线程一直执行的才能给垃圾回收器机会回收这些已经处理过的对象，但是这个时full gc频繁且耗时的原因，导致Finalizer线程偶尔才有机会处理几个对象，让垃圾回收器回收下，所以需要很长时间，一点一点的最终把这些对象回收完。