執行緒池滿Thread pool exhausted排查和解決方案

2022-11-21 14:01:26

發生{Thread pool is EXHAUSTED}時的伺服器紀錄檔

產生原因

大並行導致設定的執行緒不夠用

在初始時候，dubbo協定設定，我是使用dubbo預設的引數，dubbo執行緒池預設是固定長度執行緒池，大小為200。

一開始出現執行緒池滿的問題，本以為是並行量大導致的，沒做太多關注，運維也沒有把相應的紀錄檔dump下來，直接重啟了。

所以一開始只是優化了dubbo的設定。調大固定執行緒池數量為400，並且將dispatcher轉發由預設的設定"all"改為message。

all表示所有訊息都派發到執行緒池，包括請求，連線事件，斷開事件，心跳等。message表示只有請求響應訊息派發到執行緒池，其他連線斷開事件，心跳等訊息，直接在IO執行緒上執行。

同時開啟了存取紀錄檔記錄，觀察是不是有出現其他消費系統有短時間大並行呼叫介面的情況。

accesslog設為true，將向logger中輸出存取紀錄檔，也可填寫存取紀錄檔檔案路徑，直接把存取紀錄檔輸出到指定檔案

<dubbo:protocol name="dubbo" port="33112" accesslog="true" dispatcher="message" threads="500"/>

呼叫外部介面程式出現阻塞，等待時間過長

通過紀錄檔觀察幾天下來，大概每天介面的呼叫量在60~70萬左右，瞬時並行呼叫量也就十幾，理論上不應該出現執行緒池滿的情況，所以這時候就懷疑是不是有出現執行緒Blocked的情況，這時候便想通過紀錄檔記錄一下線上的dubbo執行緒池的情況，即在未出現執行緒池滿之前能夠及時發現問題。

所以就增加了一個切面。切點是介面中的所有方法。在呼叫前和呼叫後列印執行緒池資訊的紀錄檔。

通過檢視執行緒池原始碼我們可知，執行緒池的toString()方法，記錄了執行緒池的情況資訊

定位方式

通過運用統計發生異常時間段內的介面TPS/QPS，來定位是否大並行導致的執行緒設定不夠用

正常來說需要在程式在調外部介面時需要列印異常紀錄檔，可以通過查詢log檔案的方式，定位是否是Blocked導致的

通過切面類紀錄檔列印紀錄檔來定位問題，具體如下：

import com.alibaba.dubbo.common.Constants;
import com.alibaba.dubbo.common.extension.ExtensionLoader;
import com.alibaba.dubbo.common.store.DataStore;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
 
import java.util.Map;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.ThreadPoolExecutor;
 
/**
 * @ClassName  DubboAOP
 * @Description
 * @Author  libo
 * @Date  2019/7/25 11:46
 * @Version  1.0
 **/
@Component
@Aspect
public class DubboAOP {
 
    private static final Logger logger = LoggerFactory.getLogger(DubboAOP.class);
 
    @Pointcut("execution(* com.ncarzone.oa.biz.facade.EmployeeServiceFacadeImpl.*(..))")
    public void pointCut(){
 
    }
 
 
    @Before("pointCut()")
    public void before(){
        logger.info("======before()======"+Thread.currentThread().getName());
        printDubboThreadInfo();
 
    }
 
    @After("pointCut()")
    public void after(){
        printDubboThreadInfo();
        logger.info("======after()==="+Thread.currentThread().getName());
    }
 
    private void printDubboThreadInfo(){
        DataStore dataStore = ExtensionLoader.getExtensionLoader(DataStore.class).getDefaultExtension();
        Map<String, Object> executors = dataStore.get(Constants.EXECUTOR_SERVICE_COMPONENT_KEY);
        for(Map.Entry<String,Object> entry : executors.entrySet()){
            ExecutorService executor =  (ExecutorService)entry.getValue();
            if(executor instanceof ThreadPoolExecutor){
                ThreadPoolExecutor tp = (ThreadPoolExecutor) executor;
                logger.info("===dubboThread======"+tp.toString());
            }
        }
    }
}

可以根據我們寫的切面的紀錄檔列印資訊可以看到活躍執行緒一直在增加，即一個新的請求過來之後，就沒有下文了，執行緒沒有執行完，自然就無法被回收到執行緒池中。因而判斷極有可能是執行緒出現阻塞或者是一直在等待的情況。所以這次直接讓運維人員幫忙dump下執行緒紀錄檔。 jstack + pid xxx.log

通過執行緒dump紀錄檔，我們可以看到出現了大量執行緒的等待，dump中記錄了出問題的程式碼之處。通過分析，可知在獲取redis連線，去取redis資料的時候，由於沒有拿到redis的連線，即getResource方法執行卡住了，同時專案的redis設定又沒有設定獲取連線的最大超時時間，通過redis原始碼我們可知，如果沒有設定，則預設是-1，即可能會出現長時間等待獲取連線的情況。它會從空閒的連線佇列(private final LinkedBlockingDeque<PooledObject<T>> idleObjects)中取第一個，因為用的是takefirst()方法,即如果沒有空閒連線，則會一直等待。而pollFirst()，超時則會返回成功或失敗

因而我們需要在專案的jedis連線池設定中增加MaxWaitMillis設定，我這裡設定的是500毫秒

現在知道了是此種情況導致的，但是因為我專案裡設定的最大分配連線是600，而專案裡使用redis的地方並不多，理論上不應該出現redis連線池滿的情況，應該還是有其他問題。所以繼續看了thread dump紀錄檔，發現了問題點所在，因為之前和釘釘的開放平臺對接，做了一個回撥介面，但偶爾會出現重複回撥的情況，所以就做了一個redis鎖，來避免這個問題。但是這邊程式碼有嚴重的問題，如果jedis設定快取不成功，則會進入執行緒休眠（Thread.sleep(1000)），執行緒休眠是不會釋放所持有的連線的，而這個地方就陷入了死迴圈。導致該連線被一直佔用，從而連線池中可用的連線越來越少，直到被佔滿

將此處程式碼做了修改.使用sleep雖然保證了執行緒安全，但是影響效能。修改為根據具有唯一性的欄位進行加鎖