前言
本文记录了由于 JSF 异步调用超时引起的接口可用率降低问题的排查过程，主要介绍了排查思路和 JSF 异步调用的流程，希望可以帮助大家了解 JSF 的异步调用原理以及提供一些问题排查思路。本文分析的 JSF 源码是基于 JSF 1,7.5-HOTFIX-T6 版本。
起因
问题背景
1.广告投放系统是典型的 I/O 密集型（I/O Bound）服务，系统中某些接口单次操作可能依赖十几个外部接口,导致接口耗时较长，严重影响用户体验，因此需要将这些外部调用切换为异步模式，通过并发的模式降低整体耗时，提高接口的响应速度。
2.在同步调用的场景下，接口耗时长、性能差，接口响应时间长。这时为了缩短接口的响应时间，一般会使用线程池的方式并行获取数据，但是如果使用线程池来做，不同业务需要不同的线程池，最后会导致难以维护，随着 CPU 调度线程数的增加，会导致更严重的资源争用，宝贵的 CPU 资源被损耗在上下文切换上，而且线程本身也会占用系统资源，且不能无限增加。
3.通过阅读 JSF 的文档发现 JSF 是支持异步调用模式的，既然中间件已经支持这个功能，所以我们就采用了 JSF 提供的异步调用模式，目前 JSF 支持三种异步调用方式，分别是 ResponseFuture 方式、CompletableFuture 方式和定义返回值为 CompletableFuture 的接口签名方式。
（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 = RpcContext.getContext().asyncCall(() -> {
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 对象进行后续的操作。
问题现象
经过异步模式改造，部分依赖很多外部服务的接口耗时有明显的下降，表面看系统一片祥和，但是偶尔的接口可用率降低却是一个非常危险的信号，下面是使用异步调用的某个接口的可用率监控
通过监控我们可以发现，这个接口偶尔会出现可用率降低，一般接口可用率降低可能是因为超时或者触发了某些隐藏问题导致，但是这个接口的逻辑非常简单，就是根据 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
（2）维护 msgId 和 MsgFuture 的关系
(3) 维护 msgId 和 MsgFuture 的关系
（4）发起调用
服务端收到请求后，会触发服务端的 ServerChannelHandler 类的 channelRead 方法被回调，这个方法里面会验证序列化协议，然后生成一个 JSFTask 的任务，将这个任务提交到 JSF 的业务线程池去执行，等业务线程池里的任务执行完成以后，会调用 write 方法将返回值通过 channel 写回客户端。
（1）服务端收到响应处理
（2）服务端回写响应
客户端收到响应后，会触发客户端的 ClientChannelHandler 类的 channelRead 方法，这个方法里面会通过服务端返回的 msgId 找到客户端缓存的 MsgFuture 对象，然后会判断对象内的 compatibleFuture 属性是不是非空，如果非空，会往 Callback 线程池内提交一个任务，这个任务的主要功能是执行 CompletableFuture 的 completeExceptionally 和 complete 方法，用于触发 CompletableFuture 的下一阶段执行。
(1) 客户端收到响应
(2) 找到本地的 MsgFuture
(3) 将 MsgFuture 添加到线程池
(4) 触发 CompletableFuture 的 complete 或者 completeExceptionally 方法
通过对已上源码的分析，我们虽然知道了 JSF 异步调用的全部流程，但是还是无法解释为什么偶尔会出现不应该超时的超时 (此处指服务端明明没有超时，客户端还显示超时了)，通过对各个流程的排除，我们最终定位到可能和 JSF 异步回调后将任务添加到 Callback 线程池去执行 CompletableFuture 的 complete 方法有关，因为这个方法会继续执行 CompletableFuture 后续的阶段，我们业务代码在拿到 RpcContext 里面返回的 CompletableFuture 对象以后，一般会使用 CompletableFuture 的一元依赖方法 ThenApply 去执行一些后续处理，CompletableFuture 的 complete 方法就是用来触发这些后续阶段去执行的。
异步调用业务代码：
下面介绍一下 CompletableFuture 的基础知识，每个 CompletableFuture 都可以被看作一个被观察者，其内部有一个 Completion 类型的链表成员变量 stack，用来存储注册到其中的所有观察者。当被观察者执行完成后会弹栈 stack 属性，依次通知注册到其中的观察者，所以在这个阶段会去调用我们程序中的 ThenApply 方法，下图是 CompletableFuture 内部的关键属性。
如果上面的异步调用流程感觉不清晰，可以看下面的一张调用关系图
通过查看 Callack 线程池的默认配置，发现他的核心线程数为 20，队列长度 256，最大线程数 200。看到这我们猜测可能是核心线程数不够用，导致一些回调任务积压在队列中没来得及执行导致了超时。由于无法通过其他方式获取当时 CallBack 线程池的运行状态，因此我们通过修改业务代码，在发生超时异常的时候获取 Callback 线程池当前的状态来验证我们的猜测。
(1) 获取线程池状态代码
修改完代码上线后，系统运行一段时间出现了接口可用率降低的现象，接着我们查询日志，从日志里可以看出，在发生超时异常的时候，JSF 的 Callback 线程池核心线程数已满，同时队列中积压了 71 个任务，通过这个日志就可以确定是因为 JSF 回调线程池核心线程数满导致任务排队出现的超时
问题分析
1、通过上面的日志我们知道是因为异步线程池满导致的，理论上正常请求就算有些排队应该也会很快就能处理掉，但是我们排查业务代码后发现，我们有些业务在 ThenApply 里面做了一些耗时的操作、还有在 ThenApply 里面又调用了另外一个异步方法。
2、第一种情况会导致线程池的线程会被一直占用，其他任务都会在排队，这种其实还是能接受的，但是第二种情况可能会出现线程池循环引用导致死锁，原因是父任务会将异步回调放在线程池执行，父任务的子任务也会将异步回调放在线程池执行，Callback 线程池核心线程大小为 20，当同一时刻有 20 个请求到达，则 Callback core thread 被打满，子任务请求线程时进入阻塞队列排队，但是父任务的完成又依赖于子任务，这时由于子任务得不到线程，父任务无法完成，主线程执行 get 进入阻塞状态，并且永远无法恢复。
解决方案
短期方案：因为线程池核心线程满导致排队，所以将 JSF 的回调线程池核心线程数从 20 调整为 200，
长期方案：优化代码将 ThenApply 里面耗时的操作不放在回调线程池执行，同时优化代码逻辑，将在 ThenApply 方法内部再次开启异步调用的流程去除。
调整完前后的对比：
通过查看监控可以发现，优化后接口可用率一直保持在 100%。
作者：京东零售 宋维飞
来源：京东云开发者社区 转载请注明来源