记一次JSF异步调用引起的接口可用率降低

前言

本文记录了由于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内部的关键属性。

图12 thenApply简图

如果上面的异步调用流程感觉不清晰，可以看下面的一张调用关系图

通过查看Callack线程池的默认配置，发现他的核心线程数为20，队列长度256，最大线程数200。看到这我们猜测可能是核心线程数不够用，导致一些回调任务积压在队列中没来得及执行导致了超时。由于无法通过其他方式获取当时CallBack线程池的运行状态，因此我们通过修改业务代码，在发生超时异常的时候获取Callback线程池当前的状态来验证我们的猜测。

(1)获取线程池状态代码

修改完代码上线后，系统运行一段时间出现了接口可用率降低的现象，接着我们查询日志，从日志里可以看出，在发生超时异常的时候，JSF的Callback线程池核心线程数已满，同时队列中积压了71个任务，通过这个日志就可以确定是因为JSF 回调线程池核心线程数满导致任务排队出现的超时

问题分析

1、通过上面的日志我们知道是因为异步线程池满导致的，理论上正常请求就算有些排队应该也会很快就能处理掉，但是我们排查业务代码后发现，我们有些业务在ThenApply里面做了一些耗时的操作、还有在ThenApply里面又调用了另外一个异步方法。

2、第一种情况会导致线程池的线程会被一直占用，其他任务都会在排队，这种其实还是能接受的，但是第二种情况可能会出现线程池循环引用导致死锁，原因是父任务会将异步回调放在线程池执行，父任务的子任务也会将异步回调放在线程池执行，Callback线程池核心线程大小为20，当同一时刻有20个请求到达，则Callback core thread被打满，子任务请求线程时进入阻塞队列排队，但是父任务的完成又依赖于子任务，这时由于子任务得不到线程，父任务无法完成，主线程执行get进入阻塞状态，并且永远无法恢复。