ThreadPoolExecutor线程池问题排查：线程池设置不合理导致future.get()阻塞

Hey 锡瑞

已于 2022-05-24 00:44:57 修改

阅读量7.1k

点赞数 7

分类专栏：问题排查文章标签： java 开发语言

于 2020-12-16 18:20:37 首次发布

本文链接：https://blog.csdn.net/RuiKe1400360107/article/details/111295747

版权

问题排查专栏收录该内容

6 篇文章 2 订阅

订阅专栏

一、业务背景

有一个接口的部分功能使用了线程池，这个功能放在线程池里和主线程并行执行，等线程池里的任务执行完通过future.get的方式(如果需要得到线程池里的线程执行结果，使用future的方式)获取线程池里的线程执行结果，然后合并到主流程的结果里返回给前端。业务场景很简单，目的是不影响主流程的性能，不增加整体响应时间。但是遇到了设计的逻辑错误。

设计场景：I/O密集型(大部分业务都是通过调用接口实现的)
核心线程数：4核（cpu核数）
最大线程数：cpu核数*2
等待队列：2048

二、相关知识

设计线程池时忽略的问题：

（1）等待队列workQueue填满后，新创建的线程会优先处理新请求进来的任务，而不是去处理队列里的任务，队列里的任务只能等核心线程数忙完了才能被执行。有可能造成队列里的任务长时间等待，导致队列积压，尤其是I/O密集场景

（2）如果需要得到线程池里的线程执行结果，使用future的方式，拒绝策略不能使用DiscardPolicy，这种丢弃策略虽然不执行子线程的任务，但是还是会返回future对象(其实在这种情况下我们已经不需要线程池返回的结果了)，然后后续代码即使判断了future!=null也没用，这样的话还是会走到future.get()方法，如果get方法没有设置超时时间会导致一直阻塞下去!

// 如果线程池已满，新的请求会直接执行拒绝策略
Future<String> future = executor.submit(() -> {
    // 业务逻辑,比如调用第三方接口等耗时操作放在线程池里执行
    return result;
});

// 主流程调用逻辑
if(future != null) 
  // 如果拒绝策略设置不合理还是会走到下面代码
  // 调用方阻塞等待结果返回，直到超时
  future.get(超时时间);

ThreadPoolExecutor结构介绍：

ThreadPoolExecutor类实现了ExecutorService接口和Executor接口，可以设置线程池corePoolSize，最大线程池大小，AliveTime，拒绝策略等。常用构造方法：

ThreadPoolExecutor
(
int corePoolSize,
int maximumPoolSize,
long keepAliveTime, 
TimeUnit unit,
BlockingQueue workQueue,
RejectedExecutionHandler handler
)

corePoolSize： 线程池维护线程的最少数量（核心线程数）
maximumPoolSize：线程池维护线程的最大数量
keepAliveTime： 线程池维护线程所允许的空闲时间
unit： 线程池维护线程所允许的空闲时间的单位
workQueue： 线程池所使用的缓冲队列
handler： 线程池对拒绝任务的处理策略

当一个任务通过execute(Runnable)方法欲添加到线程池时：

（1）如果此时线程池中的数量小于corePoolSize，即使线程池中的线程都处于空闲状态，也要创建新的线程来处理被添加的任务。

（2）如果此时线程池中的数量等于 corePoolSize，但是缓冲队列 workQueue未满，那么任务被放入缓冲队列。

（3）如果此时线程池中的数量大于corePoolSize，缓冲队列workQueue满，并且线程池中的数量小于maximumPoolSize，建新的线程来处理被添加的任务。

（4）如果此时线程池中的数量大于corePoolSize，缓冲队列workQueue满，并且线程池中的数量等于maximumPoolSize，那么通过 handler所指定的策略（拒绝策略）来处理此任务。也就是：处理任务的优先级为：核心线程corePoolSize、任务队列workQueue、最大线程maximumPoolSize，如果三者都满了，使用handler处理被拒绝的任务。

四种拒绝策略：

（1）拒绝策略1：直接抛出 RejectedExecutionException异常

缺点：由于抛出一个RuntimeException，因此会中断调用者的处理过程。

private static class Worker implements Runnable {

public void run() {
      System.out.println(Thread.currentThread().getName() + " is running");
}

}


public static void main(String[] args) {
int corePoolSize = 5;
int maxPoolSize = 10;
long keepAliveTime = 5;
BlockingQueue<Runnable> queue = new LinkedBlockingQueue<Runnable>(10);

RejectedExecutionHandler handler = new ThreadPoolExecutor.AbortPolicy();
ThreadPoolExecutor executor = new ThreadPoolExecutor(corePoolSize, maxPoolSize, 
keepAliveTime, TimeUnit.SECONDS, queue, handler);

for(int i=0; i<100; i++) {
   executor.execute(new Worker());
}
   executor.shutdown();
}

运行结果如下：

pool-1-thread-2 is running
pool-1-thread-3 is running
Exception in thread "main" java.util.concurrent.RejectedExecutionException
pool-1-thread-1 is running
pool-1-thread-7 is running
pool-1-thread-6 is running
pool-1-thread-4 is running
pool-1-thread-9 is running
pool-1-thread-8 is running
pool-1-thread-5 is running

at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:1760)
at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:767)
at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:658)
at concurrent.ThreadPoolDemo.main(ThreadPoolDemo.java:33)
pool-1-thread-10 is running

处理源码：

public void rejectedExecution(Runnable r, ThreadPoolExecutor e) {
           throw new RejectedExecutionException();
}

拒绝策略2：ThreadPoolExecutor.CallerRunsPolicy：

作用：用于被拒绝任务的处理程序，它直接在 execute 方法的调用线程中运行被拒绝的任务；如果执行程序已关闭，则会丢弃该任务。

RejectedExecutionHandler handler = new ThreadPoolExecutor.CallerRunsPolicy();

运行如下：

pool-1-thread-7 is running
pool-1-thread-7 is running
pool-1-thread-7 is running
pool-1-thread-7 is running
pool-1-thread-7 is running
pool-1-thread-7 is running
pool-1-thread-2 is running
pool-1-thread-3 is running
pool-1-thread-1 is running
pool-1-thread-8 is running
main is running
main is running
main is running
pool-1-thread-4 is running
pool-1-thread-7 is running
pool-1-thread-7 is running
pool-1-thread-7 is running

处理源码：

public void rejectedExecution(Runnable r, ThreadPoolExecutor e) {
           if (!e.isShutdown()) {
               r.run();
           }
       }

拒绝策略3：

RejectedExecutionHandler handler = new ThreadPoolExecutor.DiscardOldestPolicy();

这样运行结果就不会有100个线程全部被执行。处理源码如下：

     public void rejectedExecution(Runnable r, ThreadPoolExecutor e) {
            if (!e.isShutdown()) {
                e.getQueue().poll();
                e.execute(r);
            }
        }

策略4：ThreadPoolExecutor.DiscardPolicy 用于被拒绝任务的处理程序，默认情况下它将丢弃被拒绝的任务。

运行结果也不会全部执行100个线程。

但是却有两种方式，到底是该丢弃哪一个任务：比如可以丢弃当前将要加入队列的任务本身（DiscardPolicy）或者丢弃任务队列中最旧任务（DiscardOldestPolicy）。

源码如下，实际就是对线程不执行操作：

public static class DiscardPolicy implements RejectedExecutionHandler {

     public DiscardPolicy() { }

     public void rejectedExecution(Runnable r, ThreadPoolExecutor e) {

     }

 }

三、问题排查

用线程池的接口整体响应时间变长，有的甚至到10秒才返回数据，通过线程dump分析，发现有大量的线程都阻塞在future.get方法上。future.get方法会阻塞当前主流程，在超时时间内等待子线程返回结果，如果超时还没结果则结束等待继续执行后续的代码，超时时间设置的是默认接口超时时间10秒。

future是线程池返回的：

Future<String> future = executor.submit(() -> {
    // 业务逻辑,比如调用第三方接口等耗时操作放在线程池里执行
    return result;
});

step1:

通过上面的代码可知future没有结果的原因是提交到线程池里的任务迟迟没有被执行。为什么没被执行？继续分析线程池的dump文件发现，线程池里的线程数已达到最大数量。

8个线程都是runnable状态，说明等待队列里已经塞满任务了，之前设置的队列长度是2048，也就是说还有2048个任务等待执行，这无疑加剧了整个接口的耗时。

线程池的执行顺序是：核心线程数 -> 等待队列 -> 最大线程数 -> 拒绝策略

这里基本确定接口耗时变长的主要原因是线程池设置不合理导致的。

step2:

线上日志显示虽然线程池执行了，但是线程池里的任务却没有记录运行日志，线程池里的任务是调用另外一个服务的接口，可我们自己的日志里却没有记录下调用日志，经过进一步查看代码发现当时的线程池拒绝策略也被修改过，并不是默认的抛出异常不执行策略AbortPolicy，而是设置的CallerRunsPolicy策略，即交给调用方执行！

也就是说当线程池达到最大负荷时执行的拒绝策略是：让主流程去执行提交到线程池里的任务，这样除了进一步加剧整个接口的耗时外，还会导致主流程被卡死，最关键的是无法确定是在哪一步执行提交到线程池的任务。

这种拒绝策略并不适合我们现在的业务场景，因为线程池里的任务不是核心任务，不应该影响主流程的执行。

step3：如何改进

（1）调整线程池参数

核心线程数：基于线上接口的QPS计算

最大线程数：参考线上tomcat的最大线程数配置

队列：设置的尽量小，避免造成任务挤压

（2）扩展线程池ThreadPoolExecutor

封装原生JDK线程池ThreadPoolExecutor，增加对线程池各项指标的监控，包括线程池运行状态、核心线程数、最大线程数、任务等待数、已完成任务数、线程池异常关闭等信息，便于实时监控和定位问题。

（3）重写线程池拒绝策略

记录超出线程池负载情况下的各项指标情况，以及调用线程的堆栈信息，便于排查分析，通过抛出异常方式中断执行，避免引用的future不为null的问题

（4）合理调整future.get超时时间，防止阻塞主线程时间过长。

自定义线程池代码：

public class ThreadPoolExt extends ThreadPoolExecutor{

    private static final Logger log = LoggerFactory.getLogger(ThreadPoolExt.class);

    private TimeUnit timeUnit;

    public ThreadPoolExt(int corePoolSize,
                         int maximumPoolSize,
                         long keepAliveTime,
                         TimeUnit unit,
                         BlockingQueue<Runnable> workQueue,
                         ThreadFactory threadFactory,
                         RejectedExecutionHandler handler)
{
        super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);
        this.timeUnit = unit;
    }

    @Override
    public void shutdown() {
        // 线程池将要关闭事件,此方法会等待线程池中正在执行的任务和队列中等待的任务执行完毕再关闭
        monitor("ThreadPool will be shutdown:");
        super.shutdown();
    }

    @Override
    public List<Runnable> shutdownNow() {
        // 线程池立即关闭事件,此方法会立即关闭线程池,但是会返回队列中等待的任务
        monitor("ThreadPool going to immediately be shutdown:");
        // 记录被丢弃的任务, 暂时只记录日志, 后续可根据业务场景做进一步处理
        List<Runnable> dropTasks = null;
        try {
            dropTasks = super.shutdownNow();
            log.error(MessageFormat.format("ThreadPool discard task count:{0}", dropTasks.size()));
        } catch (Exception e) {
            log.error("ThreadPool shutdownNow error", e);
        }
        return dropTasks;
    }

    @Override
    protected void beforeExecute(Thread t, Runnable r) {
        // 监控线程池运行时的各项指标
        monitor("ThreadPool monitor data:");
    }

    @Override
    protected void afterExecute(Runnable r, Throwable ex) {
        if (ex != null) { // 监控线程池中的线程执行是否异常
            log.error("unknown exception caught in ThreadPool afterExecute:", ex);
        }
    }

    /**
     * 监控线程池运行时的各项指标, 比如:任务等待数、任务异常信息、已完成任务数、核心线程数、最大线程数等<p>
     */
    private void monitor(String title){
        try {
            // 线程池监控信息记录, 这里需要注意写ES的时机,尤其是多个子线程的日志合并到主流程的记录方式
            String threadPoolMonitor = MessageFormat.format(
                    "{0}{1}core pool size:{2}, current pool size:{3}, queue wait size:{4}, active count:{5}, completed task count:{6}, " +
                            "task count:{7}, largest pool size:{8}, max pool size:{9}, keep alive time:{10}, is shutdown:{11}, is terminated:{12}, " +
                            "thread name:{13}{14}",
                    System.lineSeparator(), title, this.getCorePoolSize(), this.getPoolSize(),
                    this.getQueue().size(), this.getActiveCount(), this.getCompletedTaskCount(), this.getTaskCount(), this.getLargestPoolSize(),
                    this.getMaximumPoolSize(), this.getKeepAliveTime(timeUnit != null ? timeUnit : TimeUnit.SECONDS), this.isShutdown(),
                    this.isTerminated(), Thread.currentThread().getName(), System.lineSeparator());
            log.info(threadPoolMonitor);
        } catch (Exception e) {
            log.error("ThreadPool monitor error", e);
        }
    }
}

自定义拒绝策略代码：

public class RejectedPolicyWithReport implements RejectedExecutionHandler {

    private static final Logger log = LoggerFactory.getLogger(RejectedPolicyWithReport.class);

    private static volatile long lastPrintTime = 0;

    private static final long TEN_MINUTES_MILLS = 10 * 60 * 1000;

    private static Semaphore guard = new Semaphore(1);
    @Override
    public void rejectedExecution(Runnable r, ThreadPoolExecutor e) {
        try {
            String title = "thread pool execute reject policy!!";
            String msg = MessageFormat.format(
                    "{0}{1}core pool size:{2}, current pool size:{3}, queue wait size:{4}, active count:{5}, completed task count:{6}, " +
                            "task count:{7}, largest pool size:{8}, max pool size:{9}, keep alive time:{10}, is shutdown:{11}, is terminated:{12}, " +
                            "thread name:{13}{14}",
                    System.lineSeparator(), title, e.getCorePoolSize(), e.getPoolSize(), e.getQueue().size(), e.getActiveCount(),
                    e.getCompletedTaskCount(), e.getTaskCount(), e.getLargestPoolSize(), e.getMaximumPoolSize(), e.getKeepAliveTime(TimeUnit.SECONDS),
                    e.isShutdown(), e.isTerminated(), Thread.currentThread().getName(), System.lineSeparator());
            log.info(msg);
            threadDump(); // 记录线程堆栈信息包括锁争用信息
        } catch (Exception ex) {
            log.error("RejectedPolicyWithReport rejectedExecution error", ex);
        }
        throw new RejectedExecutionException("thread pool execute reject policy!!");
    }

    /**
     * 获取线程dump信息<p>
     * 注意: 该方法默认会记录所有线程和锁信息虽然方便debug, 使用时最好加开关和间隔调用, 否则可能会增加latency<p>
     * 1.当前线程的基本信息:id,name,state<p>
     * 2.堆栈信息<p>
     * 3.锁相关信息(可以设置不记录)<p>
     *  默认在log记录<p>
     * @return
     */
    private void threadDump() {
        long now = System.currentTimeMillis();
        // 每隔10分钟dump一次
        if (now - lastPrintTime < TEN_MINUTES_MILLS) { 
            return; 
        } 
        if (!guard.tryAcquire()) { 
            return; 
        } 
        // 异步dump线程池信息 
        ExecutorService pool = Executors.newSingleThreadExecutor(); 
        pool.execute(() -> {
            try {
                ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean();
                StringBuilder sb = new StringBuilder();
                for (ThreadInfo threadInfo : threadMxBean.dumpAllThreads(true, true)) {
                    sb.append(getThreadDumpString(threadInfo));
                }
                log.error("thread dump info:", sb.toString());
            } catch (Exception e) {
                log.error("thread dump error", e);
            } finally {
                guard.release();
            }
            lastPrintTime = System.currentTimeMillis();
        });
        pool.shutdown();
    }

    @SuppressWarnings("all")
    private String getThreadDumpString(ThreadInfo threadInfo) {
        StringBuilder sb = new StringBuilder("\"" + threadInfo.getThreadName() + "\"" +
                " Id=" + threadInfo.getThreadId() + " " +
                threadInfo.getThreadState());
        if (threadInfo.getLockName() != null) {
            sb.append(" on " + threadInfo.getLockName());
        }
        if (threadInfo.getLockOwnerName() != null) {
            sb.append(" owned by \"" + threadInfo.getLockOwnerName() +
                    "\" Id=" + threadInfo.getLockOwnerId());
        }
        if (threadInfo.isSuspended()) {
            sb.append(" (suspended)");
        }
        if (threadInfo.isInNative()) {
            sb.append(" (in native)");
        }
        sb.append('\n');
        int i = 0;

        StackTraceElement[] stackTrace = threadInfo.getStackTrace();
        MonitorInfo[] lockedMonitors = threadInfo.getLockedMonitors();
        for (; i < stackTrace.length && i < 32; i++) {
            StackTraceElement ste = stackTrace[i];
            sb.append("\tat " + ste.toString());
            sb.append('\n');
            if (i == 0 && threadInfo.getLockInfo() != null) {
                Thread.State ts = threadInfo.getThreadState();
                switch (ts) {
                    case BLOCKED:
                        sb.append("\t-  blocked on " + threadInfo.getLockInfo());
                        sb.append('\n');
                        break;
                    case WAITING:
                        sb.append("\t-  waiting on " + threadInfo.getLockInfo());
                        sb.append('\n');
                        break;
                    case TIMED_WAITING:
                        sb.append("\t-  waiting on " + threadInfo.getLockInfo());
                        sb.append('\n');
                        break;
                    default:
                }
            }

            for (MonitorInfo mi : lockedMonitors) {
                if (mi.getLockedStackDepth() == i) {
                    sb.append("\t-  locked " + mi);
                    sb.append('\n');
                }
            }
        }
        if (i < stackTrace.length) {
            sb.append("\t...");
            sb.append('\n');
        }

        LockInfo[] locks = threadInfo.getLockedSynchronizers();
        if (locks.length > 0) {
            sb.append("\n\tNumber of locked synchronizers = " + locks.length);
            sb.append('\n');
            for (LockInfo li : locks) {
                sb.append("\t- " + li);
                sb.append('\n');
            }
        }
        sb.append('\n');
        return sb.toString();
    }
}

参考：ThreadPoolExecutor里面4种拒绝策略-阿里云开发者社区