前言

本文記錄了由于JSF異步調(diào)用超時引起的接口可用率降低問題的排查過程，主要介紹了排查思路和JSF異步調(diào)用的流程，希望可以幫助大家了解JSF的異步調(diào)用原理以及提供一些問題排查思路。本文分析的JSF源碼是基于JSF 1,7.5-HOTFIX-T6版本。

起因

問題背景

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

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

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

（1）RpcContext中獲取ResponseFuture方式

該方式需要先將Consumer端的async屬性設(shè)置為true，代表開啟異步調(diào)用，然后在調(diào)用Provider的地方使用RpcContext.getContext().getFuture()方法獲取一個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，代表開啟異步調(diào)用，然后在調(diào)用Provider的地方使用RpcContext.getContext().getCompletableFuture()方法獲取到一個CompletableFuture進(jìn)行后續(xù)操作。CompletableFuture對Future進(jìn)行了擴(kuò)展，可以通過設(shè)置回調(diào)的方式處理計(jì)算結(jié)果，支持組合操作，也支持進(jìn)一步的編排，一定程度解決了回調(diào)地獄的問題。

代碼示例:

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)用端無需配置即可使用異步。

代碼示例:

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);
}

通過對已上三種異步調(diào)用模式的分析，第三種需要提供者修改方法簽名支持異步，難以實(shí)現(xiàn)；本著改動最小化，API使用最優(yōu)化，我們最終選擇了第二種方式，即在調(diào)用端設(shè)置async屬性為true，同時在發(fā)起調(diào)用后從RpcContext中獲取一個CompletableFuture對象進(jìn)行后續(xù)的操作。

問題現(xiàn)象

經(jīng)過異步模式改造，部分依賴很多外部服務(wù)的接口耗時有明顯的下降，表面看系統(tǒng)一片祥和，但是偶爾的接口可用率降低卻是一個非常危險(xiǎn)的信號，下面是使用異步調(diào)用的某個接口的可用率監(jiān)控

通過監(jiān)控我們可以發(fā)現(xiàn)，這個接口偶爾會出現(xiàn)可用率降低，一般接口可用率降低可能是因?yàn)槌瑫r或者觸發(fā)了某些隱藏問題導(dǎo)致，但是這個接口的邏輯非常簡單，就是根據(jù)id查詢數(shù)據(jù)庫，業(yè)務(wù)邏輯非常簡單，理論上不應(yīng)該出現(xiàn)這么多可用率降低的情況。我們通過日志排查發(fā)現(xiàn)在異步調(diào)用使用CompletableFuture的get方法阻塞等待的時候發(fā)生了TimeOutException異常，目前接口配置的超時時間為5s，本來接口超時是一個我們經(jīng)常遇見的問題，但是我們?nèi)ヌ峁┱叨瞬樵內(nèi)罩景l(fā)現(xiàn)，本次請求只耗費(fèi)了幾毫秒，明明提供者端幾毫秒或者幾十毫秒就返回了，為什么消費(fèi)端還超時了，帶著這個疑問我們繼續(xù)分析，會不會是JSF異步的原因?qū)е碌摹?/p>

排查定位原因

通過閱讀JSF的源碼，我們了解到JSF異步調(diào)用的基本流程為客戶端向服務(wù)端發(fā)送請求前，會先判斷本次請求是否需要走異步調(diào)用，如果需要的話，會生成一個JSFCompletableFuture對象 這個類是繼承自CompletableFuture的，同時使用一個futureMap對象緩存了請求的唯一msgId和一個MsgFuture對象，MsgFuture對象里面持有了本次調(diào)用使用的channel、message、timeout、compatibleFuture等屬性，方便服務(wù)端回調(diào)后，可以通過msgId找到對應(yīng)的MsgFuture對象做后續(xù)處理。

首先在doSendAsyn方法里生成MsgId和MsgFuture對象的映射，然后序列化數(shù)據(jù)，最后通過netty的長連接向channel里面寫入要發(fā)送的數(shù)據(jù)。

（1）生成JSFCompletableFuture

（2）維護(hù)msgId和MsgFuture的關(guān)系

(3) 維護(hù)msgId和MsgFuture的關(guān)系

（4）發(fā)起調(diào)用

服務(wù)端收到請求后，會觸發(fā)服務(wù)端的ServerChannelHandler類的channelRead方法被回調(diào)，這個方法里面會驗(yàn)證序列化協(xié)議，然后生成一個JSFTask的任務(wù)，將這個任務(wù)提交到JSF的業(yè)務(wù)線程池去執(zhí)行，等業(yè)務(wù)線程池里的任務(wù)執(zhí)行完成以后，會調(diào)用write方法將返回值通過channel寫回客戶端。

（1）服務(wù)端收到響應(yīng)處理

（2）服務(wù)端回寫響應(yīng)

客戶端收到響應(yīng)后，會觸發(fā)客戶端的ClientChannelHandler類的channelRead方法，這個方法里面會通過服務(wù)端返回的msgId找到客戶端緩存的MsgFuture對象，然后會判斷對象內(nèi)的compatibleFuture屬性是不是非空，如果非空，會往Callback線程池內(nèi)提交一個任務(wù)，這個任務(wù)的主要功能是執(zhí)行CompletableFuture的completeExceptionally和complete方法，用于觸發(fā)CompletableFuture的下一階段執(zhí)行。

(1)客戶端收到響應(yīng)

(2)找到本地的MsgFuture

(3)將MsgFuture添加到線程池

(4) 觸發(fā)CompletableFuture的complete或者completeExceptionally方法

通過對已上源碼的分析，我們雖然知道了JSF異步調(diào)用的全部流程，但是還是無法解釋為什么偶爾會出現(xiàn)不應(yīng)該超時的超時(此處指服務(wù)端明明沒有超時，客戶端還顯示超時了)，通過對各個流程的排除，我們最終定位到可能和JSF異步回調(diào)后將任務(wù)添加到Callback線程池去執(zhí)行CompletableFuture的complete方法有關(guān)，因?yàn)檫@個方法會繼續(xù)執(zhí)行CompletableFuture后續(xù)的階段，我們業(yè)務(wù)代碼在拿到RpcContext里面返回的CompletableFuture對象以后，一般會使用CompletableFuture的一元依賴方法ThenApply去執(zhí)行一些后續(xù)處理，CompletableFuture的complete方法就是用來觸發(fā)這些后續(xù)階段去執(zhí)行的。

異步調(diào)用業(yè)務(wù)代碼：

下面介紹一下CompletableFuture的基礎(chǔ)知識，每個CompletableFuture都可以被看作一個被觀察者，其內(nèi)部有一個Completion類型的鏈表成員變量stack，用來存儲注冊到其中的所有觀察者。當(dāng)被觀察者執(zhí)行完成后會彈棧stack屬性，依次通知注冊到其中的觀察者，所以在這個階段會去調(diào)用我們程序中的ThenApply方法，下圖是CompletableFuture內(nèi)部的關(guān)鍵屬性。

如果上面的異步調(diào)用流程感覺不清晰，可以看下面的一張調(diào)用關(guān)系圖

?

通過查看Callack線程池的默認(rèn)配置，發(fā)現(xiàn)他的核心線程數(shù)為20，隊(duì)列長度256，最大線程數(shù)200。看到這我們猜測可能是核心線程數(shù)不夠用，導(dǎo)致一些回調(diào)任務(wù)積壓在隊(duì)列中沒來得及執(zhí)行導(dǎo)致了超時。由于無法通過其他方式獲取當(dāng)時CallBack線程池的運(yùn)行狀態(tài)，因此我們通過修改業(yè)務(wù)代碼，在發(fā)生超時異常的時候獲取Callback線程池當(dāng)前的狀態(tài)來驗(yàn)證我們的猜測。

(1)獲取線程池狀態(tài)代碼

修改完代碼上線后，系統(tǒng)運(yùn)行一段時間出現(xiàn)了接口可用率降低的現(xiàn)象，接著我們查詢?nèi)罩荆瑥娜罩纠锟梢钥闯觯诎l(fā)生超時異常的時候，JSF的Callback線程池核心線程數(shù)已滿，同時隊(duì)列中積壓了71個任務(wù)，通過這個日志就可以確定是因?yàn)镴SF 回調(diào)線程池核心線程數(shù)滿導(dǎo)致任務(wù)排隊(duì)出現(xiàn)的超時

問題分析

1、通過上面的日志我們知道是因?yàn)楫惒骄€程池滿導(dǎo)致的，理論上正常請求就算有些排隊(duì)?wèi)?yīng)該也會很快就能處理掉，但是我們排查業(yè)務(wù)代碼后發(fā)現(xiàn)，我們有些業(yè)務(wù)在ThenApply里面做了一些耗時的操作、還有在ThenApply里面又調(diào)用了另外一個異步方法。

2、第一種情況會導(dǎo)致線程池的線程會被一直占用，其他任務(wù)都會在排隊(duì)，這種其實(shí)還是能接受的，但是第二種情況可能會出現(xiàn)線程池循環(huán)引用導(dǎo)致死鎖，原因是父任務(wù)會將異步回調(diào)放在線程池執(zhí)行，父任務(wù)的子任務(wù)也會將異步回調(diào)放在線程池執(zhí)行，Callback線程池核心線程大小為20，當(dāng)同一時刻有20個請求到達(dá)，則Callback core thread被打滿，子任務(wù)請求線程時進(jìn)入阻塞隊(duì)列排隊(duì)，但是父任務(wù)的完成又依賴于子任務(wù)，這時由于子任務(wù)得不到線程，父任務(wù)無法完成，主線程執(zhí)行g(shù)et進(jìn)入阻塞狀態(tài)，并且永遠(yuǎn)無法恢復(fù)。

解決方案

短期方案：因?yàn)榫€程池核心線程滿導(dǎo)致排隊(duì)，所以將JSF 的回調(diào)線程池核心線程數(shù)從20調(diào)整為200，

長期方案：優(yōu)化代碼將ThenApply里面耗時的操作不放在回調(diào)線程池執(zhí)行，同時優(yōu)化代碼邏輯，將在ThenApply方法內(nèi)部再次開啟異步調(diào)用的流程去除。

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

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

審核編輯 黃宇