Spring Cloud Gateway下的GC停顿排查之旅
01
背景
02
问题排查
面对内存突然升高，朴素的想法是内存泄漏，因为SpringCloudGateway的底层用的是Netty，如果没有及时释放ByteBuf，则会造成内存泄露。由于，之前就遇到过类似的问题，在程序的某个路径下，因为修改了response但又未及时释放，导致了内存泄漏。所以，很自然地想到，是不是有类似的情况导致了没有及时释放内存。但是，在开启了-Dio.netty.leakDetection.level的日志后，发现并没有内存泄漏。
另外，如果是内存泄漏的话，程序通常是直接挂了然后重启，而不是半分钟之后又恢复了，且之后内存保持不动，又正常运行了。所以想到的另一种可能，是不是发生fullgc，导致长时间的停顿，使得服务不响应了。于是查看gc log，遗憾的是没有发现full gc的发生。但意外发现的是，在remark阶段耗时高达13秒。由于我们用的是G1GC，所以remark阶段会进行STW，导致程序被卡了13秒之久，进而产生了大量的5xx。基本可以定位问题是发生在了remark阶段的长时间停顿，那到底是什么造成了remark阶段耗时这么久呢？
虽然remark阶段主要做的事情是最终标记（并发标记后最后再标记一次），但这个阶段也会附加一个reference的处理，叫ref-proc。通过添加-XX:+PrintReferenceGC and -XX:+PrintGCDetail后，可以看到remark阶段的详细日志，如下：
可以看到，最终标记Finalize Marking才花了0.0003153秒，真正耗时的是ref-proc，耗时主要发生在FinalReference，花了13.1秒多，看到数量也是惊人的2.3万多的reference。
03
调优
治标缓解
找到原因之后，剩下的就是如何调优了，由于耗时是发生在remark的ref-proc这个阶段，主要有两个方向：1. 如何加快处理速度，缩减耗时 2. 如何减少FinalReference的数量。
通过查阅资料，发现可以通过增加-XX:+ParallelRefProcEnabled参数来加速reference的处理，其原理是通过增加处理的线程来并行处理，默认是串行的，只有一个线程处理，而启动并行处理后，就会按cpu数量来创建线程数进行并行处理，即采用了ParallelGCThreads的线程数。
关于ParallelGCThreads的线程数，可以通过 -XX:ParallelGCThreads=n来指定，或者采用默认值。默认情况下，当 CPU 数量小于8， ParallelGCThreads 的值等于 CPU 数量，当 CPU 数量大于 8 时，则使用公式：ParallelGCThreads = 8 + ((N - 8) * 5/8) = 3 +（（5*CPU）/ 8），即对于超过8的cpu数量，选用5/8的比例。其源码如下：
因此，可以通过启用-XX:+ParallelRefProcEnabled来加速ref-proc的处理速度。
但这种方式，只是治标并不治本，只是通过消耗更多的cpu资源来加快处理速度。特别是，我们的容器配置是2核4G的低配实例，即使开启了并行处理，也只是多了一个线程，减少耗时的程度有限，只能缓解问题，但并未根治。为此，只能向第二个方向发力，就是如何减少FinalReference的数量，或者说是什么原因产生了如此多的FinalReference。
我们知道，产生FinalReference的唯一方法就是一个class实现了finalize()方法，那到底是人为的误用实现了finalize()方法，还是引入了有问题的库导致的，为此我们需要dump一份jvm内存来一探究竟。
治本探索
为此，可以通过jmap来对内存进行dump。一开始，我们只对存活对象进行dump，即命令如下：jmap -dump:live,format=b,file=heapdump.phrof pid（注意：在dump live的时候，会触发fullgc，所以在生产环境中慎用）
利用Java官方的VisualVM查看dump文件发现，其FinalReference的数量并不多，虽然有很多重复的JarFileWrapper，但类比其他服务的，看起来属于正常的情况。关于JarFileWrapper，其实是SpringBoot的一个bug，其官方已经在新版本修复，点击可跳转相关内容。虽然这是一个bug，但并不是引起本次问题的元凶。
考虑到FinalReference在remark阶段是有两万多的，而这次却只有两千多，数量上差距很多，因此想到一个可能，是不是有很多FinalReference在dump的时候就被gc回收了。为此，再对程序来了一次全量的dump。
发现果然多了很多Finalizer，有六千多。但仔细对比发现，多出来的Finalizer，都是没有引用对象的（referent为null），即这些Reference的引用对象早就被垃圾回收了。这个时候就会有个疑问，难道是这些已经失去引用对象的Reference造成了gc时ref-proc耗时过长？要回答这个问题，就需要我们去深入了解jvm在gc时，到底是怎么处理Reference的。
04
Reference的处理过程
GC标记时，对Reference对象进行判断，调用discover_reference方法，如果是active，则加入discoveredList队列; 遍历discoveredList队列，调用process_discovered_references方法，对每一个Reference进行处理，如果引用的referent仍然是存活的，则踢出队列中；剩下的，根据Reference类型执行对应的操作（例如对于SoftReference进行保活操作）; 在process阶段之后，会进入enqueue阶段，即调用enqueue_discovered_references方法，将上一步过滤完之后的discoveredList队列中的Reference实例加入到pending队列中（pending队列是由Reference静态属性pending和实例属性discovered构成的一个链表）。同时更新Reference实例的next属性指向它自己，即将Reference实例标记成Pending状态。这个过程，即是所谓的enque阶段，注意这里enque的队列并不是ReferenceQueue，而是pending队列； 然后是由ReferenceHandler这个backgroud线程不断的从pending队列中将实例取出并放入ReferenceQueue中，并将实例属性discovered置为null，即处于enqueued状态； 最后，由应用程序从ReferenceQueue中获取实例，进行处理，此时会将实例的next属性置为null，即inactive状态，参见ReferenceQueue#reallyPollx0;的方法。
Active: discovered == null
Pending: discovered != null
Queued: next != null && next != this && discovered == null
Inactive: next == this && discovered == null
另外，可以看到，这五个步骤中，其中第一步发生在gc标记的时期，第四、第五步发生在用户程序阶段，只有第二、第三步才是gc阶段JVM做的事情，也就是ref-proc阶段的操作。
至此，我们看到那些referent已经为空的Finalizer，其实都是Inactive的状态了。也就是说，这些Finalizer是不会进入当前ref-proc阶段的，它们应该是上一次gc ref-proc之后被加入到pending队列后，最终处理完并成为Inactive的。
在通过对ref-proc阶段的深入了解后，可以发现，一定是存在着两万多个active状态的Finalizer，导致了remark时候ref-proc耗时过长。那到底是什么样的class产生了如此多的Fianlizer？要想知道具体的实例情况，只能通过dump去分析。由于是时隔一两个星期才会出现一次，所以想要抓到有分析价值的dump也很难。在历经长时间多次的dump之后，通过将跨度一两个星期的dump文件进行对比，终于发现了端倪。
05
拨云见日
然后查看gc日志，发现是的确能产生这么多FinalReference的：
在确定是FileOutputStream产生大量FinalReference后，接下来就是确认是谁创造了这么多的FileOutputStream，通过dump文件里的引用关系，发现FileOutputStream的创建都来自于ResilientFileOutputStream，它是logback的一个类。
而ResilientFileOutputStream的创建也只来自于一个地方，就是每次创建新的日志文件的时候才会生成新的ResilientFileOutputStream。也就是有一个日志文件才会有一个FileOutputStream，那是不是我们有特别多的日志文件呢？查看容器实例，发现的确会打印出大量的日志文件，几乎一个小时就有十几个文件，在查看下logback的配置xml，发现目前的配置是每100M一个文件，所以会产生很多FileOutputStream是可以解释的。
06
总结
本文对Spring Cloud Gateway应用过程中遇到的remark阶段由于大量FinalReference导致的长时间停顿进行了详细的分析。其主要优化的难点主要在于对java reference不够熟悉，特别是jvm底层对reference的操作，即ref-proc阶段具体的过程，导致分析的时候会产生很多障碍。另外，也是从本次问题中，了解到了两个非直观的经验：
少用finalize，即使是正确的用法（如FileOutputStream），也可能会导致FinalReference过多，引发ref-proc阶段的长时间停顿
老年代gc不是触发频次越少越好，也需要控制在适当范围内，过长时间不触发，会导致“重型回收对象”大量堆积，导致单次gc时间过长。