gRPC11# 超時問題定位
一、超時現(xiàn)象反饋
在發(fā)布卡點(diǎn)過程中,有同學(xué)反饋在發(fā)布過程中存在偶發(fā)性超時情況。集中在上下游服務(wù)較多節(jié)點(diǎn)的服務(wù),幾十個上百個節(jié)點(diǎn)的服務(wù)較多。不是必然出現(xiàn),一批服務(wù)偶爾有一個節(jié)點(diǎn)出現(xiàn)。剛出現(xiàn)的前幾例由于沒有觸發(fā)線程dump一直定位不到哪里的問題。
RPC框架中服務(wù)端線程池默認(rèn)使用線程超過80%會觸發(fā)線程dump,方便觀察運(yùn)行狀態(tài)。直到有兩個服務(wù)觸發(fā)了dump才把這個謎底揭開。
二、超時現(xiàn)象跟蹤
鏈路日志: 客戶端AppXXXService調(diào)用服務(wù)Appxxx發(fā)生超時,長達(dá)50秒。
服務(wù)消費(fèi)方報錯信息:
客戶端等待中取消請求,發(fā)生調(diào)用時間為:2021-11-02 22:11:59.148
耗時監(jiān)控曲線:該服務(wù)基本上在同一時間段發(fā)起向下游的服務(wù)均發(fā)生超時。
服務(wù)端隊列監(jiān)控:隊列顯示瞬間增加很多任務(wù)
磁盤IO和CPU都有上升
線程dump情況,通信線程調(diào)用到了SynchronizationContext,底層的work通信線程怎么調(diào)用到了獲取節(jié)點(diǎn)的業(yè)務(wù)方法去了。
三、問題根因
RPC框架中代碼中有使用SynchronizationContext,此處與gRPC共用。
SynchronizationContext使用的queue是ConcurrentLinkedQueue隊列,被單線程串行執(zhí)行。
問題原因:再回到上面的線程棧,業(yè)務(wù)節(jié)點(diǎn)發(fā)現(xiàn)事件和gRPC底層通信共用了SynchronizationContext造成阻塞,和線程錯亂執(zhí)行。
問題解決:不再和gRPC共用SynchronizationContext,如果使用單獨(dú)實(shí)例化一個即可。該問題通過測試同學(xué)通過故障注入的方式得以復(fù)現(xiàn)。




































