記一次JSF非同步呼叫引起的介面可用率降低

京东云开发者發表於2024-08-05

前言

本文記錄了由於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%。

相關文章