记一次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对象进行后续的操作。

问题现象

经过异步模式改造，部分依赖很多外部服务的接口耗时有明显的下降，表面看系统一片祥和，但是偶尔的接口可用率降低却是一个非常危险的信号，下面是使用异步调用的某个接口的可用率监控

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

通过监控我们可以发现，这个接口偶尔会出现可用率降低，一般接口可用率降低可能是因为超时或者触发了某些隐藏问题导致，但是这个接口的逻辑非常简单，就是根据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

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

（2）维护msgId和MsgFuture的关系

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

(3) 维护msgId和MsgFuture的关系

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

（4）发起调用

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

服务端收到请求后，会触发服务端的ServerChannelHandler类的channelRead方法被回调，这个方法里面会验证序列化协议，然后生成一个JSFTask的任务，将这个任务提交到JSF的业务线程池去执行，等业务线程池里的任务执行完成以后，会调用write方法将返回值通过channel写回客户端。

（1）服务端收到响应处理记一次JSF异步调用引起的接口可用率降低

（2）服务端回写响应记一次JSF异步调用引起的接口可用率降低

客户端收到响应后，会触发客户端的ClientChannelHandler类的channelRead方法，这个方法里面会通过服务端返回的msgId找到客户端缓存的MsgFuture对象，然后会判断对象内的compatibleFuture属性是不是非空，如果非空，会往Callback线程池内提交一个任务，这个任务的主要功能是执行CompletableFuture的completeExceptionally和complete方法，用于触发CompletableFuture的下一阶段执行。

(1)客户端收到响应

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

(2)找到本地的MsgFuture

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

(3)将MsgFuture添加到线程池

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

(4) 触发CompletableFuture的complete或者completeExceptionally方法记一次JSF异步调用引起的接口可用率降低
通过对已上源码的分析，我们虽然知道了JSF异步调用的全部流程，但是还是无法解释为什么偶尔会出现不应该超时的超时(此处指服务端明明没有超时，客户端还显示超时了)，通过对各个流程的排除，我们最终定位到可能和JSF异步回调后将任务添加到Callback线程池去执行CompletableFuture的complete方法有关，因为这个方法会继续执行CompletableFuture后续的阶段，我们业务代码在拿到RpcContext里面返回的CompletableFuture对象以后，一般会使用CompletableFuture的一元依赖方法ThenApply去执行一些后续处理，CompletableFuture的complete方法就是用来触发这些后续阶段去执行的。

异步调用业务代码：记一次JSF异步调用引起的接口可用率降低

下面介绍一下CompletableFuture的基础知识，每个CompletableFuture都可以被看作一个被观察者，其内部有一个Completion类型的链表成员变量stack，用来存储注册到其中的所有观察者。当被观察者执行完成后会弹栈stack属性，依次通知注册到其中的观察者，所以在这个阶段会去调用我们程序中的ThenApply方法，下图是CompletableFuture内部的关键属性。记一次JSF异步调用引起的接口可用率降低如果上面的异步调用流程感觉不清晰，可以看下面的一张调用关系图

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

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

问题分析

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

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