記一次JSF異步調用引起的接口可用率降低

前言

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

起因

問題背景

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

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

3.通過閱讀JSF的文檔發(fā)現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 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屬性設置為true，代表開啟異步調用，然后在調用Provider的地方使用RpcContext.getContext().getCompletableFuture()方法獲取到一個CompletableFuture進行后續(xù)操作。CompletableFuture對Future進行了擴展，可以通過設置回調的方式處理計算結果，支持組合操作，也支持進一步的編排，一定程度解決了回調地獄的問題。

代碼示例:

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

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

代碼示例:

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

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

問題現象

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

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

排查定位原因

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

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

（1）生成JSFCompletableFuture

（2）維護msgId和MsgFuture的關系

(3) 維護msgId和MsgFuture的關系

（4）發(fā)起調用

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

（1）服務端收到響應處理

（2）服務端回寫響應

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

(1)客戶端收到響應

(2)找到本地的MsgFuture

(3)將MsgFuture添加到線程池

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

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

異步調用業(yè)務代碼：

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

如果上面的異步調用流程感覺不清晰，可以看下面的一張調用關系圖

?

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

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

修改完代碼上線后，系統(tǒng)運行一段時間出現了接口可用率降低的現象，接著我們查詢日志，從日志里可以看出，在發(fā)生超時異常的時候，JSF的Callback線程池核心線程數已滿，同時隊列中積壓了71個任務，通過這個日志就可以確定是因為JSF 回調線程池核心線程數滿導致任務排隊出現的超時

問題分析

1、通過上面的日志我們知道是因為異步線程池滿導致的，理論上正常請求就算有些排隊應該也會很快就能處理掉，但是我們排查業(yè)務代碼后發(fā)現，我們有些業(yè)務在ThenApply里面做了一些耗時的操作、還有在ThenApply里面又調用了另外一個異步方法。

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

解決方案

短期方案：因為線程池核心線程滿導致排隊，所以將JSF 的回調線程池核心線程數從20調整為200，

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

調整完前后的對比：

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

審核編輯 黃宇