前言
本文記錄了由于JSF異步調(diào)用超時(shí)引起的接口可用率降低問(wèn)題的排查過(guò)程，主要介紹了排查思路和JSF異步調(diào)用的流程，希望可以幫助大家了解JSF的異步調(diào)用原理以及提供一些問(wèn)題排查思路。本文分析的JSF源碼是基于JSF 1,7.5-HOTFIX-T6版本。
起因
問(wèn)題背景
（1）RpcContext中獲取ResponseFuture方式
該方式需要先將Consumer端的async屬性設(shè)置為true，代表開啟異步調(diào)用，然后在調(diào)用Provider的地方使用RpcContext.getContext().getFuture()方法獲取一個(gè)ResponseFuture，拿到Future以后就可以使用get方法去阻塞等待返回，但是這種方式已經(jīng)不推薦使用了，因?yàn)榈诙NCompletableFuture的模式更加強(qiáng)大。
代碼示例:
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屬性設(shè)置為true，代表開啟異步調(diào)用，然后在調(diào)用Provider的地方使用RpcContext.getContext().getCompletableFuture()方法獲取到一個(gè)CompletableFuture進(jìn)行后續(xù)操作。CompletableFuture對(duì)Future進(jìn)行了擴(kuò)展，可以通過(guò)設(shè)置回調(diào)的方式處理計(jì)算結(jié)果，支持組合操作，也支持進(jìn)一步的編排，一定程度解決了回調(diào)地獄的問(wèn)題。
代碼示例:
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及以上版本支持）
這種模式需要改造代碼，需要服務(wù)的提供者事先定義方法的返回值簽名為CompletableFuture，這種調(diào)用端無(wú)需配置即可使用異步。
代碼示例:
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);
}通過(guò)對(duì)已上三種異步調(diào)用模式的分析，第三種需要提供者修改方法簽名支持異步，難以實(shí)現(xiàn)；本著改動(dòng)最小化，API使用最優(yōu)化，我們最終選擇了第二種方式，即在調(diào)用端設(shè)置async屬性為true，同時(shí)在發(fā)起調(diào)用后從RpcContext中獲取一個(gè)CompletableFuture對(duì)象進(jìn)行后續(xù)的操作。
問(wèn)題現(xiàn)象
經(jīng)過(guò)異步模式改造，部分依賴很多外部服務(wù)的接口耗時(shí)有明顯的下降，表面看系統(tǒng)一片祥和，但是偶爾的接口可用率降低卻是一個(gè)非常危險(xiǎn)的信號(hào)，下面是使用異步調(diào)用的某個(gè)接口的可用率監(jiān)控
?
?
?
通過(guò)監(jiān)控我們可以發(fā)現(xiàn)，這個(gè)接口偶爾會(huì)出現(xiàn)可用率降低，一般接口可用率降低可能是因?yàn)槌瑫r(shí)或者觸發(fā)了某些隱藏問(wèn)題導(dǎo)致，但是這個(gè)接口的邏輯非常簡(jiǎn)單，就是根據(jù)id查詢數(shù)據(jù)庫(kù)，業(yè)務(wù)邏輯非常簡(jiǎn)單，理論上不應(yīng)該出現(xiàn)這么多可用率降低的情況。我們通過(guò)日志排查發(fā)現(xiàn)在異步調(diào)用使用CompletableFuture的get方法阻塞等待的時(shí)候發(fā)生了TimeOutException異常，目前接口配置的超時(shí)時(shí)間為5s，本來(lái)接口超時(shí)是一個(gè)我們經(jīng)常遇見的問(wèn)題，但是我們?nèi)ヌ峁┱叨瞬樵內(nèi)罩景l(fā)現(xiàn)，本次請(qǐng)求只耗費(fèi)了幾毫秒，明明提供者端幾毫秒或者幾十毫秒就返回了，為什么消費(fèi)端還超時(shí)了，帶著這個(gè)疑問(wèn)我們繼續(xù)分析，會(huì)不會(huì)是JSF異步的原因?qū)е碌摹?/p>
排查定位原因
通過(guò)閱讀JSF的源碼，我們了解到JSF異步調(diào)用的基本流程為客戶端向服務(wù)端發(fā)送請(qǐng)求前，會(huì)先判斷本次請(qǐng)求是否需要走異步調(diào)用，如果需要的話，會(huì)生成一個(gè)JSFCompletableFuture對(duì)象 這個(gè)類是繼承自CompletableFuture的，同時(shí)使用一個(gè)futureMap對(duì)象緩存了請(qǐng)求的唯一msgId和一個(gè)MsgFuture對(duì)象，MsgFuture對(duì)象里面持有了本次調(diào)用使用的channel、message、timeout、compatibleFuture等屬性，方便服務(wù)端回調(diào)后，可以通過(guò)msgId找到對(duì)應(yīng)的MsgFuture對(duì)象做后續(xù)處理。
首先在doSendAsyn方法里生成MsgId和MsgFuture對(duì)象的映射，然后序列化數(shù)據(jù)，最后通過(guò)netty的長(zhǎng)連接向channel里面寫入要發(fā)送的數(shù)據(jù)。
（1）生成JSFCompletableFuture
?
?
?
（2）維護(hù)msgId和MsgFuture的關(guān)系
?
?
?
(3) 維護(hù)msgId和MsgFuture的關(guān)系
?
?
?
（4）發(fā)起調(diào)用
?
?
?
服務(wù)端收到請(qǐng)求后，會(huì)觸發(fā)服務(wù)端的ServerChannelHandler類的channelRead方法被回調(diào)，這個(gè)方法里面會(huì)驗(yàn)證序列化協(xié)議，然后生成一個(gè)JSFTask的任務(wù)，將這個(gè)任務(wù)提交到JSF的業(yè)務(wù)線程池去執(zhí)行，等業(yè)務(wù)線程池里的任務(wù)執(zhí)行完成以后，會(huì)調(diào)用write方法將返回值通過(guò)channel寫回客戶端。
（1）服務(wù)端收到響應(yīng)處理
?
?
?
（2）服務(wù)端回寫響應(yīng)
?
?
?
客戶端收到響應(yīng)后，會(huì)觸發(fā)客戶端的ClientChannelHandler類的channelRead方法，這個(gè)方法里面會(huì)通過(guò)服務(wù)端返回的msgId找到客戶端緩存的MsgFuture對(duì)象，然后會(huì)判斷對(duì)象內(nèi)的compatibleFuture屬性是不是非空，如果非空，會(huì)往Callback線程池內(nèi)提交一個(gè)任務(wù)，這個(gè)任務(wù)的主要功能是執(zhí)行CompletableFuture的completeExceptionally和complete方法，用于觸發(fā)CompletableFuture的下一階段執(zhí)行。
(1)客戶端收到響應(yīng)
?
?
?
(2)找到本地的MsgFuture
?
?
?
(3)將MsgFuture添加到線程池
?
?
?
(4) 觸發(fā)CompletableFuture的complete或者completeExceptionally方法
?
?
?
通過(guò)對(duì)已上源碼的分析，我們雖然知道了JSF異步調(diào)用的全部流程，但是還是無(wú)法解釋為什么偶爾會(huì)出現(xiàn)不應(yīng)該超時(shí)的超時(shí)(此處指服務(wù)端明明沒有超時(shí)，客戶端還顯示超時(shí)了)，通過(guò)對(duì)各個(gè)流程的排除，我們最終定位到可能和JSF異步回調(diào)后將任務(wù)添加到Callback線程池去執(zhí)行CompletableFuture的complete方法有關(guān)，因?yàn)檫@個(gè)方法會(huì)繼續(xù)執(zhí)行CompletableFuture后續(xù)的階段，我們業(yè)務(wù)代碼在拿到RpcContext里面返回的CompletableFuture對(duì)象以后，一般會(huì)使用CompletableFuture的一元依賴方法ThenApply去執(zhí)行一些后續(xù)處理，CompletableFuture的complete方法就是用來(lái)觸發(fā)這些后續(xù)階段去執(zhí)行的。
異步調(diào)用業(yè)務(wù)代碼：
?
?
下面介紹一下CompletableFuture的基礎(chǔ)知識(shí)，每個(gè)CompletableFuture都可以被看作一個(gè)被觀察者，其內(nèi)部有一個(gè)Completion類型的鏈表成員變量stack，用來(lái)存儲(chǔ)注冊(cè)到其中的所有觀察者。當(dāng)被觀察者執(zhí)行完成后會(huì)彈棧stack屬性，依次通知注冊(cè)到其中的觀察者，所以在這個(gè)階段會(huì)去調(diào)用我們程序中的ThenApply方法，下圖是CompletableFuture內(nèi)部的關(guān)鍵屬性。
?
?
?
如果上面的異步調(diào)用流程感覺不清晰，可以看下面的一張調(diào)用關(guān)系圖
?
?
?
?
通過(guò)查看Callack線程池的默認(rèn)配置，發(fā)現(xiàn)他的核心線程數(shù)為20，隊(duì)列長(zhǎng)度256，最大線程數(shù)200。看到這我們猜測(cè)可能是核心線程數(shù)不夠用，導(dǎo)致一些回調(diào)任務(wù)積壓在隊(duì)列中沒來(lái)得及執(zhí)行導(dǎo)致了超時(shí)。由于無(wú)法通過(guò)其他方式獲取當(dāng)時(shí)CallBack線程池的運(yùn)行狀態(tài)，因此我們通過(guò)修改業(yè)務(wù)代碼，在發(fā)生超時(shí)異常的時(shí)候獲取Callback線程池當(dāng)前的狀態(tài)來(lái)驗(yàn)證我們的猜測(cè)。
(1)獲取線程池狀態(tài)代碼
?
?
?
修改完代碼上線后，系統(tǒng)運(yùn)行一段時(shí)間出現(xiàn)了接口可用率降低的現(xiàn)象，接著我們查詢?nèi)罩?，從日志里可以看出，在發(fā)生超時(shí)異常的時(shí)候，JSF的Callback線程池核心線程數(shù)已滿，同時(shí)隊(duì)列中積壓了71個(gè)任務(wù)，通過(guò)這個(gè)日志就可以確定是因?yàn)镴SF 回調(diào)線程池核心線程數(shù)滿導(dǎo)致任務(wù)排隊(duì)出現(xiàn)的超時(shí)
?
?
?
問(wèn)題分析
1、通過(guò)上面的日志我們知道是因?yàn)楫惒骄€程池滿導(dǎo)致的，理論上正常請(qǐng)求就算有些排隊(duì)?wèi)?yīng)該也會(huì)很快就能處理掉，但是我們排查業(yè)務(wù)代碼后發(fā)現(xiàn)，我們有些業(yè)務(wù)在ThenApply里面做了一些耗時(shí)的操作、還有在ThenApply里面又調(diào)用了另外一個(gè)異步方法。
2、第一種情況會(huì)導(dǎo)致線程池的線程會(huì)被一直占用，其他任務(wù)都會(huì)在排隊(duì)，這種其實(shí)還是能接受的，但是第二種情況可能會(huì)出現(xiàn)線程池循環(huán)引用導(dǎo)致死鎖，原因是父任務(wù)會(huì)將異步回調(diào)放在線程池執(zhí)行，父任務(wù)的子任務(wù)也會(huì)將異步回調(diào)放在線程池執(zhí)行，Callback線程池核心線程大小為20，當(dāng)同一時(shí)刻有20個(gè)請(qǐng)求到達(dá)，則Callback core thread被打滿，子任務(wù)請(qǐng)求線程時(shí)進(jìn)入阻塞隊(duì)列排隊(duì)，但是父任務(wù)的完成又依賴于子任務(wù)，這時(shí)由于子任務(wù)得不到線程，父任務(wù)無(wú)法完成，主線程執(zhí)行g(shù)et進(jìn)入阻塞狀態(tài)，并且永遠(yuǎn)無(wú)法恢復(fù)。
解決方案
短期方案：因?yàn)榫€程池核心線程滿導(dǎo)致排隊(duì)，所以將JSF 的回調(diào)線程池核心線程數(shù)從20調(diào)整為200，
長(zhǎng)期方案：優(yōu)化代碼將ThenApply里面耗時(shí)的操作不放在回調(diào)線程池執(zhí)行，同時(shí)優(yōu)化代碼邏輯，將在ThenApply方法內(nèi)部再次開啟異步調(diào)用的流程去除。
調(diào)整完前后的對(duì)比：
?
?
?
通過(guò)查看監(jiān)控可以發(fā)現(xiàn)，優(yōu)化后接口可用率一直保持在100%。
作者：京東零售 宋維飛文章來(lái)源：http://www.zghlxwxcb.cn/news/detail-777087.html
來(lái)源：京東云開發(fā)者社區(qū) 轉(zhuǎn)載請(qǐng)注明來(lái)源文章來(lái)源地址http://www.zghlxwxcb.cn/news/detail-777087.html
到了這里，關(guān)于記一次JSF異步調(diào)用引起的接口可用率降低的文章就介紹完了。如果您還想了解更多內(nèi)容，請(qǐng)?jiān)谟疑辖撬阉鱐OY模板網(wǎng)以前的文章或繼續(xù)瀏覽下面的相關(guān)文章，希望大家以后多多支持TOY模板網(wǎng)！
