[[434974]]

一、超時(shí)現(xiàn)象反饋

在發(fā)布卡點(diǎn)過程中，有同學(xué)反饋在發(fā)布過程中存在偶發(fā)性超時(shí)情況。集中在上下游服務(wù)較多節(jié)點(diǎn)的服務(wù)，幾十個(gè)上百個(gè)節(jié)點(diǎn)的服務(wù)較多。不是必然出現(xiàn)，一批服務(wù)偶爾有一個(gè)節(jié)點(diǎn)出現(xiàn)。剛出現(xiàn)的前幾例由于沒有觸發(fā)線程dump一直定位不到哪里的問題。

RPC框架中服務(wù)端線程池默認(rèn)使用線程超過80%會(huì)觸發(fā)線程dump，方便觀察運(yùn)行狀態(tài)。直到有兩個(gè)服務(wù)觸發(fā)了dump才把這個(gè)謎底揭開。

二、超時(shí)現(xiàn)象跟蹤

鏈路日志： 客戶端AppXXXService調(diào)用服務(wù)Appxxx發(fā)生超時(shí)，長(zhǎng)達(dá)50秒。

服務(wù)消費(fèi)方報(bào)錯(cuò)信息：

客戶端等待中取消請(qǐng)求，發(fā)生調(diào)用時(shí)間為：2021-11-02 22:11:59.148

耗時(shí)監(jiān)控曲線：該服務(wù)基本上在同一時(shí)間段發(fā)起向下游的服務(wù)均發(fā)生超時(shí)。

服務(wù)端隊(duì)列監(jiān)控：隊(duì)列顯示瞬間增加很多任務(wù)

磁盤IO和CPU都有上升

線程dump情況，通信線程調(diào)用到了SynchronizationContext，底層的work通信線程怎么調(diào)用到了獲取節(jié)點(diǎn)的業(yè)務(wù)方法去了。

三、問題根因

RPC框架中代碼中有使用SynchronizationContext，此處與gRPC共用。

SynchronizationContext使用的queue是ConcurrentLinkedQueue隊(duì)列，被單線程串行執(zhí)行。

問題原因：再回到上面的線程棧，業(yè)務(wù)節(jié)點(diǎn)發(fā)現(xiàn)事件和gRPC底層通信共用了SynchronizationContext造成阻塞，和線程錯(cuò)亂執(zhí)行。

問題解決：不再和gRPC共用SynchronizationContext，如果使用單獨(dú)實(shí)例化一個(gè)即可。該問題通過測(cè)試同學(xué)通過故障注入的方式得以復(fù)現(xiàn)。