前言

本文記錄了由于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.廣告投放系統(tǒng)是典型的I/O密集型（I/O Bound）服務(wù)，系統(tǒng)中某些接口單次操作可能依賴十幾個(gè)外部接口,導(dǎo)致接口耗時(shí)較長(zhǎng)，嚴(yán)重影響用戶體驗(yàn)，因此需要將這些外部調(diào)用切換為異步模式，通過(guò)并發(fā)的模式降低整體耗時(shí)，提高接口的響應(yīng)速度。

2.在同步調(diào)用的場(chǎng)景下，接口耗時(shí)長(zhǎng)、性能差，接口響應(yīng)時(shí)間長(zhǎng)。這時(shí)為了縮短接口的響應(yīng)時(shí)間，一般會(huì)使用線程池的方式并行獲取數(shù)據(jù)，但是如果使用線程池來(lái)做，不同業(yè)務(wù)需要不同的線程池，最后會(huì)導(dǎo)致難以維護(hù)，隨著CPU調(diào)度線程數(shù)的增加，會(huì)導(dǎo)致更嚴(yán)重的資源爭(zhēng)用，寶貴的CPU資源被損耗在上下文切換上，而且線程本身也會(huì)占用系統(tǒng)資源，且不能無(wú)限增加。

3.通過(guò)閱讀JSF的文檔發(fā)現(xiàn)JSF是支持異步調(diào)用模式的，既然中間件已經(jīng)支持這個(gè)功能，所以我們就采用了JSF提供的異步調(diào)用模式，目前JSF支持三種異步調(diào)用方式，分別是ResponseFuture方式、CompletableFuture方式和定義返回值為 CompletableFuture 的接口簽名方式。

（1）RpcContext中獲取ResponseFuture方式

該方式需要先將Consumer端的async屬性設(shè)置為true，代表開(kāi)啟異步調(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 future1 = RpcContext.getContext().getFuture();
asyncHelloService.sayNoting("The ResponseFuture Two");
ResponseFuture 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，代表開(kāi)啟異步調(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 cf1 = RpcContext.getContext().getCompletableFuture();
asyncHelloService.sayNoting("The CompletableFuture Two");
CompletableFuture cf2 = RpcContext.getContext().getCompletableFuture();

CompletableFuture 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及以上版本支持）

這種模式需要改造代碼，需要服務(wù)的提供者事先定義方法的返回值簽名為CompletableFuture，這種調(diào)用端無(wú)需配置即可使用異步。

代碼示例:

CompletableFuture 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 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)常遇見(jiàn)的問(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ù)端明明沒(méi)有超時(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)用流程感覺(jué)不清晰，可以看下面的一張調(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ì)列中沒(méi)來(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)部再次開(kāi)啟異步調(diào)用的流程去除。

調(diào)整完前后的對(duì)比：

通過(guò)查看監(jiān)控可以發(fā)現(xiàn)，優(yōu)化后接口可用率一直保持在100%。

審核編輯 黃宇