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
来源: http://www.jianshu.com/p/c93ac5d5bd01