spring-cloud-gateway是spring出品的微服务网关，我们公司基于此进行了二次开发并承载公司所有web流量，之前我们一直用的是spring-cloud Finchley.SR2版本对应的gateway，最近我们尝试升级到spring-cloud Greenwich.RELEASE版本时发现GC恶化了不少，于是排查之旅就此开始。
先在两台升级前后的机器上执行jstat命令，这个命令可以查看GC概况，在排查GC问题时非常有用，如下两图分别是升级前后的GC概况：
图1. 升级前GC概况
图2. 升级后GC概况
从这两张图中我们可以得到如下结论：
young gc频率差不多，都是大约4秒一次，但是每次young gc后，图2中survivor区占用内存明显比图1高很多，图2中每次晋升到old区的内存量也明显比图1高；这说明升级后存活对象数增加了很多，导致gc恶化。图中也可以看出升级后FGCT（笔者用的是CMS垃圾回收算法）明显比升级前多了很多。
那么到底是哪些存活对象变多了导致GC恶化了呢？楼主在分析问题的时候用了一款瑞士军刀：https://github.com/DarLiner/vjtools/tree/master/vjmap
在升级前后的机器上分别执行命令：./vjmap.sh -sur PID > histo-sur.log，这个命令可以输出survivor区的对象统计信息（这个命令会STW，执行前别忘了先切断流量），两台机器执行结果分别如下：
图3. 升级前survivor区对象统计信息
图4. 升级后survivor区对象统计信息
从图中可以看出升级后java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask这个类的对象占用了8.7M内存，而升级前这个类的对象非常少，看来李鬼就在这里了。
那么这些对象到底是哪里来的呢，从以上概况已经看不出更多信息了，这个时候就该用jmap命令dump内存看看了，balabala，十几分钟过后，楼主打开新鲜出炉的内存dump文件，经过一番分析，发现了如下关键信息：
内存dump分析
如上图所示，可以看到大量java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask对象存在ScheduledThreadPoolExecutor的工作队列中，看源码可以知道ScheduledThreadPoolExecutor会把所有提交的任务包装成ScheduledFutureTask放入queue中，并在执行完成后删除，从这里也能看出ScheduledThreadPoolExecutor的threadFactory使用了reactor.core.schedule.ReactorThreadFactory, 看起来是有地方在使用reactor-java提交大量延时任务导致的。
目前使用上述手段也已经无法获得更多信息，继续从其他地方着手继续排查。楼主发现在断开流量后，过五六分钟去重新执行命令查看survivor区对象，ScheduledFutureTask对象实例几乎没有了，这说明ScheduledFutureTask这个对象的创建基本是由流量触发的。于是我打开本地代码，在ScheduledThreadPoolExecutor类中所有提交任务的代码中加入断点，并加入断点条件：this.getThreadFactory().getClass().getSimpleName().equals("ReactorThreadFactory")
Idea增加条件断点
然后通过浏览器打开页面，果然触发了断点。断点所在堆栈很长，楼主截取了关键信息如下：
"reactor-http-kqueue-4" #340 daemon prio=5 os_prio=31 tid=0x00007fe61cb62800 nid=0x15207 at breakpoint[0x000070000fa71000] java.lang.Thread.State: RUNNABLE at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(ScheduledThreadPoolExecutor.java:544) at reactor.core.scheduler.Schedulers.directSchedule(Schedulers.java:838) at reactor.core.scheduler.ParallelScheduler.schedule(ParallelScheduler.java:158) at reactor.core.scheduler.Schedulers$CachedScheduler.schedule(Schedulers.java:767) at reactor.core.publisher.MonoDelay.subscribe(MonoDelay.java:58) at reactor.core.publisher.MonoOnErrorResume.subscribe(MonoOnErrorResume.java:44) at reactor.core.publisher.Mono.subscribe(Mono.java:3710) at reactor.core.publisher.FluxTimeout.subscribe(FluxTimeout.java:89) at reactor.core.publisher.FluxOnErrorResume.subscribe(FluxOnErrorResume.java:47) at reactor.core.publisher.Flux.subscribe(Flux.java:7793)
......
......
at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) at reactor.core.publisher.Mono.subscribe(Mono.java:3710) at rx.RxReactiveStreams$1.call(RxReactiveStreams.java:60) at rx.RxReactiveStreams$1.call(RxReactiveStreams.java:57)
......
......
at rx.Observable.subscribe(Observable.java:10095) at org.springframework.cloud.gateway.filter.factory.HystrixGatewayFilterFactory.lambda$null$0(HystrixGatewayFilterFactory.java:102) at org.springframework.cloud.gateway.filter.factory.HystrixGatewayFilterFactory$$Lambda$948/2078441774.accept(Unknown Source) at reactor.core.publisher.MonoCreate.subscribe(MonoCreate.java:57) at reactor.core.publisher.MonoOnErrorResume.subscribe(MonoOnErrorResume.java:44) at reactor.core.publisher.Mono.subscribe(Mono.java:3710) at reactor.core.publisher.MonoIgnorePublisher.subscribe(MonoIgnorePublisher.java:41)
......
......
at reactor.netty.http.server.HttpServerHandle.onStateChange(HttpServerHandle.java:64) at reactor.netty.tcp.TcpServerBind$ChildObserver.onStateChange(TcpServerBind.java:234) at reactor.netty.http.server.HttpServerOperations.onInboundNext(HttpServerOperations.java:436) at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:141) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) at reactor.netty.http.server.HttpTrafficHandler.channelRead(HttpTrafficHandler.java:162) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
......
......
at java.lang.Thread.run(Thread.java:745)
注意其中的粗体部分，FluxTimeout，从这个类可以看出调用来自Flux.timeout方法，类似reactor的框架素来就对调试非常不友好，从这个堆栈完全看不出是哪里调用了Flux.timeout, 经过一番查找和调试，笔者发现Flux.timeout来自源码org.springframework.cloud.gateway.filter.NettyRoutingFilter：
spring源码
spring在这里设置了超时时间，如果从上游的响应超过了超时时间，则抛出异常。笔者这里的超时时间设置了59秒。
结合以上分析，答案自然浮出了水面：spring-cloud-gateway每次处理一个http请求时都会调用Flux.timeout往ScheduledThreadPoolExecutor中提交一个延时任务（在这个例子中是延迟59秒后执行）并生成一个ScheduledFutureTask放入工作队列中，大部分情况下上游的响应都会在十几ms内响应，reactor-java会调用ScheduledFutureTask.cancel来取消这个延时任务的触发，然而这个ScheduledFutureTask对象仍然会存在于工作队列中，直到59秒后才会被从队列中剔除。
由于大量ScheduledFutureTask对象都会存活59秒，这些对象很容易就熬过了几次young gc，并最终晋升到老年代，这样不仅导致了young gc时间变长，还导致CMS GC频次的大幅增加。
那么怎么解决这个问题呢？笔者在阅读ScheduledThreadPoolExecutor源码时发现其中一个有意思的方法：
ScheduledThreadPoolExecutor源码
从注释可以看出，如果把removeOnCancel属性设置为true，那么调用ScheduledFutureTask.cancel方法的同时也会把ScheduledFutureTask从工作队列中移除，从而可以尽快被gc回收掉（removeOnCancel属性默认为false）。
那么有什么办法修改reactor-java内部创建的ScheduledThreadPoolExecutor的属性呢？reactor-java已经提供了hook给我们，只要在适当的地方（比如刚启动时）调用如下代码就可以了：
Schedulers.addExecutorServiceDecorator("setRemoveOnCancel", (scheduler, scheduledExecutorService) -> {
if (scheduledExecutorService instanceof ScheduledThreadPoolExecutor) { ((ScheduledThreadPoolExecutor)scheduledExecutorService) .setRemoveOnCancelPolicy(true); }
return scheduledExecutorService;
});
最后抛出个问题留给读者自己思考：为什么升级前不会有这个问题呢？读者可自行阅读源码研究一下。
后续：笔者顺便看了下另一款框架RxJava的实现，其内部创建的ScheduledThreadPoolExecutor默认都是把removeOnCancel设置为true的，笔者个人觉得这算是一个问题，故给reactor-java提交了一个PR：https://github.com/reactor/reactor-core/pull/1674
网友评论