线程池满Thread pool exhausted排查和解决方案

目录

• 发生{Thread pool is EXHAUSTED}时的服务器日志
• 产生原因
• 大并发导致配置的线程不够用
• 调用外部接口程序出现阻塞，等待时间过长
• 定位方式
• Dubbo线上Thread pool is EXHAUSTED问题跟踪

发生{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 服务的。

以上为个人经验，希望能给大家一个参考，也希望大家多多支持我们。