记一次JSF异步调用引起的接口可用率降低
前言
本文记录了由于JSF异步调用超时引起的接口可用率降低问题的排查过程,主要介绍了排查思路和JSF异步调用的流程,希望可以帮助大家了解JSF的异步调用原理以及提供一些问题排查思路。本文分析的JSF源码是基于JSF 1,7.5-HOTFIX-T6版本。
起因
问题背景
(1)RpcContext中获取ResponseFuture方式
该方式需要先将Consumer端的async属性设置为true,代表开启异步调用,然后在调用Provider的地方使用RpcContext.getContext().getFuture()方法获取一个ResponseFuture,拿到Future以后就可以使用get方法去阻塞等待返回,但是这种方式已经不推荐使用了,因为第二种CompletableFuture的模式更加强大。
代码示例:
asyncHelloService.sayHello("The ResponseFuture One");
ResponseFuture<Object> future1 = RpcContext.getContext().getFuture();
asyncHelloService.sayNoting("The ResponseFuture Two");
ResponseFuture<Object> future2 = RpcContext.getContext().getFuture();
try {
future1.get();
future2.get();
} catch (Throwable e) {
LOGGER.error("catch " + e.getClass().getCanonicalName() + " " + e.getMessage(), e);
}
(2)RpcContext中获取CompletableFuture方式(1.7.5及以上版本支持)
该方式需要先将Consumer端的async属性设置为true,代表开启异步调用,然后在调用Provider的地方使用RpcContext.getContext().getCompletableFuture()方法获取到一个CompletableFuture进行后续操作。CompletableFuture对Future进行了扩展,可以通过设置回调的方式处理计算结果,支持组合操作,也支持进一步的编排,一定程度解决了回调地狱的问题。
代码示例:
asyncHelloService.sayHello("The CompletableFuture One");
CompletableFuture<String> cf1 = RpcContext.getContext().getCompletableFuture();
asyncHelloService.sayNoting("The CompletableFuture Two");
CompletableFuture<String> cf2 = RpcContext.getContext().getCompletableFuture();
CompletableFuture<String> cf3 {
asyncHelloService.sayHello("The CompletableFuture Three");
});
try {
cf1.get();
cf2.get();
cf3.get();
} catch (Throwable e) {
LOGGER.error("catch " + e.getClass().getCanonicalName() + " " + e.getMessage(), e);
}
(3)使用 CompletableFuture 签名的接口(1.7.5及以上版本支持)
这种模式需要改造代码,需要服务的提供者事先定义方法的返回值签名为CompletableFuture,这种调用端无需配置即可使用异步。
代码示例:
CompletableFuture<String> cf4 = asyncHelloService.sayHelloAsync("The CompletableFuture Fore");
cf4.whenComplete((res, err) {
if (err != null) {
LOGGER.error("interface async cf4 now complete error " + err.getClass().getCanonicalName() + " " + err.getMessage(), err);
} else {
LOGGER.info("interface async cf4 now complete : {}", res);
}
});
CompletableFuture<Void> cf5 = asyncHelloService.sayNotingAsync("The CompletableFuture Five");
try {
LOGGER.info("interface async cf1 now is : {}", cf4.get());
LOGGER.info("interface async cf2 now is : {}", cf5.get());
} catch (Throwable e) {
LOGGER.error("catch " + e.getClass().getCanonicalName() + " " + e.getMessage(), e);
}
通过对已上三种异步调用模式的分析,第三种需要提供者修改方法签名支持异步,难以实现;本着改动最小化,API使用最优化,我们最终选择了第二种方式,即在调用端设置async属性为true,同时在发起调用后从RpcContext中获取一个CompletableFuture对象进行后续的操作。
问题现象
经过异步模式改造,部分依赖很多外部服务的接口耗时有明显的下降,表面看系统一片祥和,但是偶尔的接口可用率降低却是一个非常危险的信号,下面是使用异步调用的某个接口的可用率监控
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-12-18-18-00n0Pv12cabms18Ramc.png)
通过监控我们可以发现,这个接口偶尔会出现可用率降低,一般接口可用率降低可能是因为超时或者触发了某些隐藏问题导致,但是这个接口的逻辑非常简单,就是根据id查询数据库,业务逻辑非常简单,理论上不应该出现这么多可用率降低的情况。我们通过日志排查发现在异步调用使用CompletableFuture的get方法阻塞等待的时候发生了TimeOutException异常,目前接口配置的超时时间为5s,本来接口超时是一个我们经常遇见的问题,但是我们去提供者端查询日志发现,本次请求只耗费了几毫秒,明明提供者端几毫秒或者几十毫秒就返回了,为什么消费端还超时了,带着这个疑问我们继续分析,会不会是JSF异步的原因导致的。
排查定位原因
通过阅读JSF的源码,我们了解到JSF异步调用的基本流程为客户端向服务端发送请求前,会先判断本次请求是否需要走异步调用,如果需要的话,会生成一个JSFCompletableFuture对象 这个类是继承自CompletableFuture的,同时使用一个futureMap对象缓存了请求的唯一msgId和一个MsgFuture对象,MsgFuture对象里面持有了本次调用使用的channel、message、timeout、compatibleFuture等属性,方便服务端回调后,可以通过msgId找到对应的MsgFuture对象做后续处理。
首先在doSendAsyn方法里生成MsgId和MsgFuture对象的映射,然后序列化数据,最后通过netty的长连接向channel里面写入要发送的数据。
(1)生成JSFCompletableFuture
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-08-22-13-46tt6p1YVxmRbAIXZ.png)
(2)维护msgId和MsgFuture的关系
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-08-23-20-45F45aLePSMip8fn9T.png)
(3) 维护msgId和MsgFuture的关系
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-12-18-18-01AVNghA0PDWm9QKt.png)
(4)发起调用
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-08-22-13-54D7FEk8D54rjLXjRl.png)
服务端收到请求后,会触发服务端的ServerChannelHandler类的channelRead方法被回调,这个方法里面会验证序列化协议,然后生成一个JSFTask的任务,将这个任务提交到JSF的业务线程池去执行,等业务线程池里的任务执行完成以后,会调用write方法将返回值通过channel写回客户端。
(1)服务端收到响应处理
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-12-18-18-0312kgDbazXYzwctG7.png)
(2)服务端回写响应
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-08-22-14-02nQT14AdtNdw8naH9.png)
客户端收到响应后,会触发客户端的ClientChannelHandler类的channelRead方法,这个方法里面会通过服务端返回的msgId找到客户端缓存的MsgFuture对象,然后会判断对象内的compatibleFuture属性是不是非空,如果非空,会往Callback线程池内提交一个任务,这个任务的主要功能是执行CompletableFuture的completeExceptionally和complete方法,用于触发CompletableFuture的下一阶段执行。
(1)客户端收到响应
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-08-22-13-50CpfgiouhLZLG22gS.png)
(2)找到本地的MsgFuture
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-08-22-13-51nyqO22dtouyNPxuI.png)
(3)将MsgFuture添加到线程池
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-08-22-13-56856jUJyvgo7DMiZh.png)
(4) 触发CompletableFuture的complete或者completeExceptionally方法
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-08-23-20-44IFW9aRnfI8Sg0Zj.png)
通过对已上源码的分析,我们虽然知道了JSF异步调用的全部流程,但是还是无法解释为什么偶尔会出现不应该超时的超时(此处指服务端明明没有超时,客户端还显示超时了),通过对各个流程的排除,我们最终定位到可能和JSF异步回调后将任务添加到Callback线程池去执行CompletableFuture的complete方法有关,因为这个方法会继续执行CompletableFuture后续的阶段,我们业务代码在拿到RpcContext里面返回的CompletableFuture对象以后,一般会使用CompletableFuture的一元依赖方法ThenApply去执行一些后续处理,CompletableFuture的complete方法就是用来触发这些后续阶段去执行的。
异步调用业务代码:
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-12-18-18-05ccxkZEryrt41QkXx.png)
下面介绍一下CompletableFuture的基础知识,每个CompletableFuture都可以被看作一个被观察者,其内部有一个Completion类型的链表成员变量stack,用来存储注册到其中的所有观察者。当被观察者执行完成后会弹栈stack属性,依次通知注册到其中的观察者,所以在这个阶段会去调用我们程序中的ThenApply方法,下图是CompletableFuture内部的关键属性。
![图12 thenApply简图](https://p0.meituan.net/travelcube/f45b271b656f3ae243875fcb2af36a1141224.png)
如果上面的异步调用流程感觉不清晰,可以看下面的一张调用关系图
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-08-23-20-43eC9XA8RTqZ6858gN.jpg)
通过查看Callack线程池的默认配置,发现他的核心线程数为20,队列长度256,最大线程数200。看到这我们猜测可能是核心线程数不够用,导致一些回调任务积压在队列中没来得及执行导致了超时。由于无法通过其他方式获取当时CallBack线程池的运行状态,因此我们通过修改业务代码,在发生超时异常的时候获取Callback线程池当前的状态来验证我们的猜测。
(1)获取线程池状态代码
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-12-18-18-07DYTzTdWQAa9ztIP.png)
修改完代码上线后,系统运行一段时间出现了接口可用率降低的现象,接着我们查询日志,从日志里可以看出,在发生超时异常的时候,JSF的Callback线程池核心线程数已满,同时队列中积压了71个任务,通过这个日志就可以确定是因为JSF 回调线程池核心线程数满导致任务排队出现的超时
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-12-18-18-09K18BKDZm9VSDVjIv.png)
问题分析
1、通过上面的日志我们知道是因为异步线程池满导致的,理论上正常请求就算有些排队应该也会很快就能处理掉,但是我们排查业务代码后发现,我们有些业务在ThenApply里面做了一些耗时的操作、还有在ThenApply里面又调用了另外一个异步方法。
2、第一种情况会导致线程池的线程会被一直占用,其他任务都会在排队,这种其实还是能接受的,但是第二种情况可能会出现线程池循环引用导致死锁,原因是父任务会将异步回调放在线程池执行,父任务的子任务也会将异步回调放在线程池执行,Callback线程池核心线程大小为20,当同一时刻有20个请求到达,则Callback core thread被打满,子任务请求线程时进入阻塞队列排队,但是父任务的完成又依赖于子任务,这时由于子任务得不到线程,父任务无法完成,主线程执行get进入阻塞状态,并且永远无法恢复。
解决方案
短期方案:因为线程池核心线程满导致排队,所以将JSF 的回调线程池核心线程数从20调整为200,
长期方案:优化代码将ThenApply里面耗时的操作不放在回调线程池执行,同时优化代码逻辑,将在ThenApply方法内部再次开启异步调用的流程去除。
调整完前后的对比:
![](https://s3.cn-north-1.jdcloud-oss.com/shendengbucket1/2023-12-18-18-11OfqrLMAli7ncpP6.png)
通过查看监控可以发现,优化后接口可用率一直保持在100%。
作者:京东零售 宋维飞
来源:京东云开发者社区 转载请注明来源