線程池滿Thread pool exhausted排查和解決方案

Posted on by

發生{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雖然保證瞭線程安全，但是影響性能。修改為根據具有唯一性的字段進行加鎖

Dubbo線上Thread pool is EXHAUSTED問題跟蹤

今天發現瞭服務在某段時間內大量出現這個異常：

detail msg:Thread pool is EXHAUSTED! 

下遊服務的 Dubbo 線程池滿瞭，經過溝通得知下遊服務在那個時間段之內出現瞭慢 SQL，導致數據庫連接被打滿，進而影響瞭其他 Dubbo 服務的。

以上為個人經驗，希望能給大傢一個參考，也希望大傢多多支持WalkonNet。

推薦閱讀：