進程還在，JSF接口不干活了，這你敢信？

1、問題背景：

應用在配合R2m升級redis版本的過程中，上游反饋調用接口報錯，RpcException：[Biz thread pool of provider has been exhausted]，通過監(jiān)控系統(tǒng)和日志系統(tǒng)定位到現象只出現在一兩個節(jié)點，并持續(xù)出現。第一時間通過JSF將有問題的節(jié)點下線，保留現場，業(yè)務恢復。

報錯日志如下：

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、排查步驟：

從現象開始推測原因，系統(tǒng)啟動時，會給JSF線程池分配固定的大小，當線程都在工作的時，外部流量又打進來，那么會沒有線程去處理請求，此時會有上述的異常。那么JSF線程在干什么呢？

1）借助SGM打印棧信息

2）分析棧信息

可以用在線分析工具：http://spotify.github.io/threaddump-analyzer/?

2.1）分析線程狀態(tài)

通過工具可以定位到JSF線程大部分卡在JedisClusterInfoCache#getSlaveOfSlotFromDc方法，如圖：

2.2）分析線程夯住的方法

getSlaveOfSlotFromDc在方法入口就需要獲取讀鎖，同時在全局變量聲明了讀鎖和寫鎖：

此時對問題有一個大體的了解，大概推測：getSlaveOfSlotFromDc是獲取redis連接池，該方法入口處需要獲取讀鎖，由于讀鎖之間不會互斥，所以猜測有業(yè)務獲取到寫鎖后沒有釋放。同時讀鎖沒有設置超時時間，所以導致杰夫線程處理業(yè)務時卡在獲取讀鎖處，無法釋放。

2.3）從業(yè)務的角度分析持有寫鎖的邏輯

向中間件研發(fā)尋求幫助，經過排查，定位到有個更新拓撲的定時任務，執(zhí)行時會先獲取寫鎖，根據該消息，定位到任務的棧信息：

代碼截圖：

圖1

圖2

圖3

從日志驗證：日志只打印更新拓撲的日志，沒有打印更新成功的日志，且02:20分以后r2m-topo-updater就不在打印日志

2.4）深入挖掘原因

雖然現象已經可以推測出來，但是對問題的原因還是百思不得其解，難道parallelStream().forEach存在bug？難道有遠程請求，沒有設置超時時間？...

經過查找資料確認，如果沒有指定，那么parallelStream().forEach會使用ForkJoinPool.commonPool這個默認的線程池去處理任務，該線程池默認設置（容器核心數-1）個活躍線程。同時caffeine數據過期后會異步刷新數據，如果沒有指定線程池，它默認也會使用ForkJoinPool.commonPool()來執(zhí)行異步線程。那么就有概率出現獲取到寫鎖的線程無法獲取執(zhí)行權，獲取執(zhí)行權的線程無法獲取到讀鎖。

2.5）驗證

3個ForkJoinPool.commonPool-worker的確都夯在獲取redis連接處，線程池的活躍線程都在等待讀鎖。

本地caffeine緩存沒有設置自定義線程池

topo-updater夯在foreach業(yè)務處理邏輯中

3.復盤

1）此問題在特定的使用場景下才會小概率出現，非常感謝中間件團隊一起協(xié)助定位問題，后續(xù)也將異步更新拓撲改為同步處理。

2）Java提供了很多異步處理的能力，但是異常處理也代表需要開啟線程或者使用共用的線程池，也需要注意。

3）做好監(jiān)控，能第一時間發(fā)現問題并處理問題。

審核編輯 黃宇