1、問題背景:
應用在配合R2m升級redis版本的過程中,上游反饋調用接口報錯,RpcException:[Biz thread pool of provider has been exhausted],通過監控系統和日志系統定位到現象只出現在一兩個節點,并持續出現。第一時間通過JSF將有問題的節點下線,保留現場,業務恢復。
報錯日志如下:
24-03-13 02:21:20.188 [JSF-SEV-WORKER-57-T-5] ERROR BaseServerHandler - handlerRequest error msg:[JSF-23003]Biz thread pool of provider has been exhausted, the server port is 22003 24-03-13 02:21:20.658 [JSF-SEV-WORKER-57-T-5] WARN BusinessPool - [JSF-23002]Task:com.alibaba.ttl.TtlRunnable - com.jd.jsf.gd.server.JSFTask@0 has been reject for ThreadPool exhausted! pool:80, active:80, queue:300, taskcnt: 1067777
2、排查步驟:
從現象開始推測原因,系統啟動時,會給JSF線程池分配固定的大小,當線程都在工作的時,外部流量又打進來,那么會沒有線程去處理請求,此時會有上述的異常。那么JSF線程在干什么呢?
1)借助SGM打印棧信息
2)分析棧信息
可以用在線分析工具:http://spotify.github.io/threaddump-analyzer/?
2.1)分析線程狀態
通過工具可以定位到JSF線程大部分卡在JedisClusterInfoCache#getSlaveOfSlotFromDc方法,如圖:
2.2)分析線程夯住的方法
getSlaveOfSlotFromDc在方法入口就需要獲取讀鎖,同時在全局變量聲明了讀鎖和寫鎖:
此時對問題有一個大體的了解,大概推測:getSlaveOfSlotFromDc是獲取redis連接池,該方法入口處需要獲取讀鎖,由于讀鎖之間不會互斥,所以猜測有業務獲取到寫鎖后沒有釋放。同時讀鎖沒有設置超時時間,所以導致杰夫線程處理業務時卡在獲取讀鎖處,無法釋放。
2.3)從業務的角度分析持有寫鎖的邏輯
向中間件研發尋求幫助,經過排查,定位到有個更新拓撲的定時任務,執行時會先獲取寫鎖,根據該消息,定位到任務的棧信息:
代碼截圖:
圖1
圖2
圖3
從日志驗證:日志只打印更新拓撲的日志,沒有打印更新成功的日志,且02:20分以后r2m-topo-updater就不在打印日志
2.4)深入挖掘原因
雖然現象已經可以推測出來,但是對問題的原因還是百思不得其解,難道parallelStream().forEach存在bug?難道有遠程請求,沒有設置超時時間?...
經過查找資料確認,如果沒有指定,那么parallelStream().forEach會使用ForkJoinPool.commonPool這個默認的線程池去處理任務,該線程池默認設置(容器核心數-1)個活躍線程。同時caffeine數據過期后會異步刷新數據,如果沒有指定線程池,它默認也會使用ForkJoinPool.commonPool()來執行異步線程。那么就有概率出現獲取到寫鎖的線程無法獲取執行權,獲取執行權的線程無法獲取到讀鎖。
2.5)驗證
3個ForkJoinPool.commonPool-worker的確都夯在獲取redis連接處,線程池的活躍線程都在等待讀鎖。
本地caffeine緩存沒有設置自定義線程池
topo-updater夯在foreach業務處理邏輯中
3.復盤
1)此問題在特定的使用場景下才會小概率出現,非常感謝中間件團隊一起協助定位問題,后續也將異步更新拓撲改為同步處理。
2)Java提供了很多異步處理的能力,但是異常處理也代表需要開啟線程或者使用共用的線程池,也需要注意。
3)做好監控,能第一時間發現問題并處理問題。
審核編輯 黃宇
-
接口
+關注
關注
33文章
8650瀏覽量
151412 -
JSF
+關注
關注
0文章
11瀏覽量
7760
發布評論請先 登錄
相關推薦
評論