發(fā)生{Thread pool is EXHAUSTED}時的服務(wù)器日志

產(chǎn)生原因 

大并發(fā)導(dǎo)致配置的線程不夠用

在初始時候，dubbo協(xié)議配置，我是使用dubbo默認的參數(shù)，dubbo線程池默認是固定長度線程池，大小為200。

一開始出現(xiàn)線程池滿的問題，本以為是并發(fā)量大導(dǎo)致的，沒做太多關(guān)注，運維也沒有把相應(yīng)的日志dump下來，直接重啟了。

所以一開始只是優(yōu)化了dubbo的配置。調(diào)大固定線程池數(shù)量為400，并且將dispatcher轉(zhuǎn)發(fā)由默認的配置"all"改為message。

all表示所有消息都派發(fā)到線程池，包括請求，連接事件，斷開事件，心跳等。message表示只有請求響應(yīng)消息派發(fā)到線程池，其他連接斷開事件，心跳等消息，直接在IO線程上執(zhí)行。

同時開啟了訪問日志記錄，觀察是不是有出現(xiàn)其他消費系統(tǒng)有短時間大并發(fā)調(diào)用接口的情況。

accesslog設(shè)為true，將向logger中輸出訪問日志，也可填寫訪問日志文件路徑，直接把訪問日志輸出到指定文件 

<dubbo:protocol name="dubbo" port="33112" accesslog="true" dispatcher="message" threads="500"/><!--開啟訪問日志記錄 -->

調(diào)用外部接口程序出現(xiàn)阻塞，等待時間過長

通過日志觀察幾天下來，大概每天接口的調(diào)用量在60~70萬左右，瞬時并發(fā)調(diào)用量也就十幾，理論上不應(yīng)該出現(xiàn)線程池滿的情況，所以這時候就懷疑是不是有出現(xiàn)線程Blocked的情況，這時候便想通過日志記錄一下線上的dubbo線程池的情況，即在未出現(xiàn)線程池滿之前能夠及時發(fā)現(xiàn)問題。

所以就增加了一個切面。切點是接口中的所有方法。在調(diào)用前和調(diào)用后打印線程池信息的日志。

通過查看線程池源碼我們可知，線程池的toString()方法，記錄了線程池的情況信息

定位方式 

通過運用統(tǒng)計發(fā)生異常時間段內(nèi)的接口TPS/QPS，來定位是否大并發(fā)導(dǎo)致的線程配置不夠用

正常來說需要在程序在調(diào)外部接口時需要打印異常日志，可以通過查詢log文件的方式，定位是否是Blocked導(dǎo)致的

通過切面類日志打印日志來定位問題，具體如下：

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());
            }
        }
    }
}

可以根據(jù)我們寫的切面的日志打印信息可以看到活躍線程一直在增加，即一個新的請求過來之后，就沒有下文了，線程沒有運行完，自然就無法被回收到線程池中。因而判斷極有可能是線程出現(xiàn)阻塞或者是一直在等待的情況。所以這次直接讓運維人員幫忙dump下線程日志。 jstack + pid  xxx.log

通過線程dump日志，我們可以看到出現(xiàn)了大量線程的等待，dump中記錄了出問題的代碼之處。通過分析，可知在獲取redis連接，去取redis數(shù)據(jù)的時候，由于沒有拿到redis的連接，即getResource方法執(zhí)行卡住了，同時項目的redis配置又沒有設(shè)置獲取連接的最大超時時間，通過redis源碼我們可知，如果沒有設(shè)置，則默認是-1，即可能會出現(xiàn)長時間等待獲取連接的情況。它會從空閑的連接隊列(private final LinkedBlockingDeque<PooledObject<T>> idleObjects)中取第一個，因為用的是takefirst()方法,即如果沒有空閑連接，則會一直等待。而pollFirst()，超時則會返回成功或失敗

因而我們需要在項目的jedis連接池配置中增加MaxWaitMillis配置，我這里設(shè)置的是500毫秒

現(xiàn)在知道了是此種情況導(dǎo)致的，但是因為我項目里配置的最大分配連接是600，而項目里使用redis的地方并不多，理論上不應(yīng)該出現(xiàn)redis連接池滿的情況，應(yīng)該還是有其他問題。所以繼續(xù)看了thread dump日志，發(fā)現(xiàn)了問題點所在，因為之前和釘釘?shù)拈_放平臺對接，做了一個回調(diào)接口，但偶爾會出現(xiàn)重復(fù)回調(diào)的情況，所以就做了一個redis鎖，來避免這個問題。但是這邊代碼有嚴重的問題，如果jedis設(shè)置緩存不成功，則會進入線程休眠（Thread.sleep(1000)），線程休眠是不會釋放所持有的連接的，而這個地方就陷入了死循環(huán)。導(dǎo)致該連接被一直占用，從而連接池中可用的連接越來越少，直到被占滿

將此處代碼做了修改.使用sleep雖然保證了線程安全，但是影響性能。修改為根據(jù)具有唯一性的字段進行加鎖

Dubbo線上Thread pool is EXHAUSTED問題跟蹤

今天發(fā)現(xiàn)了服務(wù)在某段時間內(nèi)大量出現(xiàn)這個異常：

detail msg:Thread pool is EXHAUSTED! 

下游服務(wù)的 Dubbo 線程池滿了，經(jīng)過溝通得知下游服務(wù)在那個時間段之內(nèi)出現(xiàn)了慢 SQL，導(dǎo)致數(shù)據(jù)庫連接被打滿，進而影響了其他 Dubbo 服務(wù)的。

以上為個人經(jīng)驗，希望能給大家一個參考，也希望大家多多支持腳本之家。

最新評論