從 RPC 調用超時異常,排查追蹤問題

1、業務場景,合同 SCF 服務調用電籤平臺 SCF 服務時,出現超時錯誤,如下:

從 SCF 的幫助文檔上我們可以找到相應的解決方案,如下:

最開始我們可能都會認爲應該是服務端處理時間過長導致客戶端等待超時,於是去服務管理平臺修改 receiveTimeout 的值,但是我們已經將 receiveTimeout 修改爲 90 秒,仍然出現超時錯誤,查看服務管理平臺也發現服務方好像並未收到客戶端的請求,於是我們覺得應該是客戶端的問題,通過查看代碼發現客戶端進行 RPC 調用時會傳遞一個字節數組,該數組儲存合同服務的合同信息,經查看合同文件的大小在 700K 左右。

於是猜想是否是因爲該數組儲存數據過大導致數據其實並未從客戶端發送出去,SCF 客戶端有一個 maxPackageSize 用於設置客戶端每次發送請求包的最大大小,默認值爲 102400,也就是默認最大爲 100K。

我們將 maxPackageSize 設置爲 4096000(4000K)後,客戶端超時問題解決,看來確實是因爲該值設置過小導致客戶端出現超時錯誤。按照我們的猜想如果是參數出現問題,那麼請求的時候應該會直接報參數校驗錯誤纔對,爲何會出現超時錯誤呢?下面我們從 SCF 客戶端的源碼進行分析:

2、SCF 客戶端源碼解析:

(1)我們在項目如果需要進行 RPC 調用會使用 ProxyFactory 創建一個代理對象,所有的 RPC 請求都由該代理對象發出:

(2)當代理對象發送實際的 RPC 請求時實際是將請求封裝爲一個 TransmitterTask 放入阻塞隊列中,如果是異步調用當前線程直接返回,否則如果是同步調用將會阻塞等待服務端的響應(我們使用的是同步調用):

(3)之後會有其他的線程不斷從阻塞隊列中拿出任務執行:

sendTask 其實是一個類。。其是 Transmitter 的一個內部類:

send 方法內部將使用 CSocket 發送數據:

上面的異常信息截不全,我再補個圖:

等等。。爲啥我們在服務管理平臺配置的屬性是 maxPackageSize,而代碼裏面判斷的卻是 sendBuffer 的值呢??在 CSocket 的構造方法中我們可以看到答案:

而當發送數據內部拋出異常時,異常會被捕獲,並打印一條日誌,其他啥事沒有~

(4)如果是同步調用,線程將請求包裝成 Task 丟到阻塞隊列後會等待服務端響應數據的返回:

等待服務端的數據返回在 receive 方法中,我們在控制檯查詢到的錯誤日誌也是在這裏面打印的:

throw new TimeoutException("ServiceName:[" + this.getServiceName() + "],ServiceIP:[" + this.getServiceIP() + "],Receive data timeout or error!timeout:" + timeout + "ms,queue length:" + queueLen);

在 Event.waitOne 裏面使用了 CountDownLatch 阻塞等待指定的時間,如果在等待過程中接受到服務端的響應將會被喚醒,否則將一直等待到超時:

3、總結:由於客戶端在發送 RPC 請求時底層其實是異步的(當前線程將 RPC 請求包裝成一個任務放到阻塞隊列中,等待其他線程獲取任務來執行),之後會使用 CountDownLatch 進行阻塞等待服務端的響應,當到達我們設置的 receiveTimeout 時間後拋出異常。因爲其他線程獲取阻塞隊列中的任務來執行時拋出了異常,所以請求實際並未到達服務端,此時不管我們將客戶端的超時時間設置多大都沒用,因爲不可能收到服務端的響應,阻塞的線程也就永遠不會被主動喚醒。

本文由 Readfog 進行 AMP 轉碼,版權歸原作者所有。
來源https://mp.weixin.qq.com/s/u_U_6MTdTRmU0ELBCb-0kA