记一次JSF异步调用引起的接口可用率降低 | 京东云技术团队

原创
2023/12/29 09:34
阅读数 21

前言

本文记录了由于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进入阻塞状态,并且永远无法恢复。

解决方案

短期方案:因为线程池核心线程满导致排队,所以将JSF 的回调线程池核心线程数从20调整为200,

长期方案:优化代码将ThenApply里面耗时的操作不放在回调线程池执行,同时优化代码逻辑,将在ThenApply方法内部再次开启异步调用的流程去除。

调整完前后的对比:





 

通过查看监控可以发现,优化后接口可用率一直保持在100%。

作者:京东零售 宋维飞

来源:京东云开发者社区 转载请注明来源

展开阅读全文
加载中
点击引领话题📣 发布并加入讨论🔥
打赏
0 评论
0 收藏
0
分享
返回顶部
顶部