一次因线程池使用不当造成生产事故的排查记录与思考

最新推荐文章于 2024-08-27 04:25:52 发布

SunAlwaysOnline

最新推荐文章于 2024-08-27 04:25:52 发布

阅读量4.1k

点赞数 21

分类专栏： JAVA # 多线程 # 源码分析文章标签：线程池问题排查

本文链接：https://blog.csdn.net/qq_33591903/article/details/121172329

版权

JAVA 同时被 3 个专栏收录

168 篇文章 66 订阅

订阅专栏

多线程

35 篇文章 11 订阅

订阅专栏

源码分析

16 篇文章 8 订阅

订阅专栏

美好的一天从bug结束

某日当我点开熟悉的界面，一个又一个请求失败的提示赫然出现在屏幕上，不会是昨晚上线的代码有问题吧？

吓得我急忙按F12查看了响应——"exception":"java.lang.OutOfMemoryError","message":"unable to create new native thread"

出现了内存溢出的情况，无法创建更多的本地线程。

监控中显端倪

接着查看了实例的监控大盘，发现每个实例的JVM线程数量都处于9000+的规模，且还有上涨的趋势。

这是其中一个实例的线程数量监控图：

10.17日出现下降，并不是由于GC，而是由于上线，所以会降到0。

当前服务一共有8个实例，临时的方案是从负载均衡中摘除1个节点，用作排查使用，其他实例则按照顺序进行原地重建。

dump线程日志

登录上这个容器，使用

ps -ef|grep java

来查询到java应用的进程号，得到了1127

接着使用

jstack 1127 > thread.log

来导出进程内所有线程的状态数据，其中一部分的日志如图所示：

这两个线程，名称都是"pool-xxx-thread-xxx"的形式。

从Executors类中的静态内部类DefaultThreadFactory源码可知，默认线程工厂给线程池中的线程的取名规则就是这样的格式。

我们可以使用

grep -c "pool-" thread.log

来统计被线程池管理的线程总数，得到8336个，而一共才9000多个。

看来这次事故和线程池脱不了关系了，对线程池不了解的同学，可以先移步我的另外一篇文章还好我接住了面试官对线程池的夺命连环问

接着使用

grep java.lang.Thread.State thread.log | awk '{print $2$3$4$5}' | sort | uniq -c

按线程状态分组统计，得到这样的结果

40    RUNNABLE
5     TIMED_WAITING(onobjectmonitor)
63    TIMED_WAITING(parking)
12    TIMED_WAITING(sleeping)
73    WAITING(onobjectmonitor)
8100  WAITING(parking)

RUNNABLE

代表线程已经执行了start方法，但还没有获得CPU时间片，得到时间片后，才会变成RUNNING的状态。

TIMED_WAITING(onobjectmonitor)与WAITING(onobjectmonitor)

当线程获取监视器锁之后（一般是进入了synchronized方法），又调用了对象的wait或wait(time)方法，释放了锁，进入Wait Set中。

TIMED_WAITING(parking)与WAITING(parking)

当调用LockSupport.park就可以使得线程处于该状态，之后线程会定时或非定时地等待unpark的到来。

TIMED_WAITING(sleeping)

调用sleep(time)方法就会处于该状态，时间到了自动醒来。

所以，这边我们可以得出结论，大量线程池中的线程处于WAITING(parking)的状态。

我们随便（刻意）从日志中取到一个线程的运行堆栈信息：

worker在运行的过程中，会使用getTask方法从阻塞队列LinkedBlockQueue中获取任务。因为此时没有任务，因此被await方法阻塞，而await内部又会调用LockSupport的park方法，从而使得线程处于WAITING(parking)的状态。

随便看了一些日志，基本上都是这样，线程池中的大量线程因获取不到任务处于阻塞的状态。

排查到这里，我不禁发出疑问，线程池到底在搞什么鬼，都不干活的吗？

不经意的突破口

直到我在代码里搜索使用到线程池的地方时，我瞥到了这样一段代码：

在该段代码中，每次请求都会创建一个固定大小为10的线程池。但在处理完业务逻辑后，并没有调用shutdown或者shutdownNow方法。

难道是这里发生了线程泄露吗？pool作为局部变量，在方法执行完成后，应该会在GC中被回收掉啊！

假设pool及内部的线程会一直保留在内存中，不会被GC回收，确实有可能造成开头的现象。每个线程都会占用堆内存，最终造成OOM。

那么，线程池作为局部变量，在方法执行后，线程池及内部的线程会在什么时候进行回收呢？

实验开始

那我们就做一个实验吧，实地去验证下：

    @RequestMapping("/execute")
    public String execute() {

        ExecutorService pool = Executors.newFixedThreadPool(10, new MyThreadFactory());
        for (int i = 0; i < 20; i++) {
            pool.execute(() -> {
                try {
                    //模拟业务耗时
                    Thread.sleep(2000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            });
        }

        return "success";
    }

    static class MyThreadFactory implements ThreadFactory {
        private final AtomicInteger threadNumber = new AtomicInteger(1);

        @Override
        public Thread newThread(Runnable r) {
            String name = "MyThreadFactory-" + threadNumber.getAndIncrement();
            return new Thread(r, name);
        }
    }

MyThreadFactory是自定义的一个线程工厂，应用到该线程工厂的线程池，内部产生的线程的名称都有“MyThreadFactory”前缀。

启动这个SpringBoot项目，调用execute接口。这个时候产生的线程日志中，确实多出了10个线程。

借助JVisualVM工具

当然我们可以通过JVisualVM工具来查看内存与线程总数，这个工具就在jdk安装路径的bin目录中

jvm自动触发GC，以及在我们手动触发GC后，线程数基本没有任何变化。

MyThreadFactory产生的10个线程依然驻留在内存中，并没有被回收掉。

大胆的猜测

到这里，我们已经确定，方法执行结束后，相关线程确实不会被回收。

如果对线程池有一个简单的认识的话，一定会知道线程池会将Thread保证成一个Worker，体现在Worker类中有一个thread变量。

因此当Thread正在running或处于任何阻塞阶段，就不会被销毁，其Worker对象也不会被销毁。

而Woker类又是ThreadPoolExecutor里的一个非静态的内部类，对于一个非静态的内部类，在实例化时，会隐式地持有外部类的一个强引用，体现在编译器会自动往内部类的构造函数中追加一个外部类参数。

因此当前woker对象又持有着线程池对象的强引用，所以线程池对象也不会被销毁。不过我们再也访问不到该线程池对象，无法往该线程池中提交任何任务，从而造成了内存泄露。

源码探究

那么当我们退出方法后，线程池内部的线程究竟是处于什么状态呢？从上面的线程日志，其实可以得到一些线索——线程在阻塞获取任务。

为什么退出方法了，线程还处于阻塞状态呢？又怎么去释放这些线程呢？

我们从pool.execute入手

当目前线程数小于核心线程数时，会调用addWorker，将用户提交的任务封装成worker。

进入到addWorker方法中，省略一些代码

第一步会调用Woker的构造方法，会用到用户传入的Runnable任务。

看一下Woker的构造方法：

构造函数只做了两件事：

（1）将用户的Runnable任务赋值给了成员变量firstTask

（2）getThreadFactory.newThread(this)会调用我们自定义的线程工厂的newThread方法，参数是当前实现了Runnable接口的worker对象，并把生成的Thread对象赋值给了成员变量thread。

addWorker第二步则是将生成的worker对象存入线程池的woker集合中

addWorker第三步则是调用worker成员变量thread的start方法，用于启动worker线程

到这里，我们可以知道，线程池并不是将用户传入的Runnable任务作为一个线程执行，而是将任务包装成worker，转而去执行woker线程。

调用worker的start方法，则虚拟机会在合适时间回调run方法，那我们直接进入Worker类的run方法中。

在上图中，可以看到，run方法又调用了runWorker方法：

当初次进入while循环中，firstTask也就是用户的Runnable任务，肯定不会为null，因此会直接调用firstTask的run方法，执行用户任务，接着将firstTask置null。

当再次进入while循环中，firstTask为null，此时会调用getTask从阻塞队列中获取任务，如果getTask返回null，则会退出while循环，当前worker线程也就结束了。

进入到getTask中：

如果allowCoreThreadTimeOut被指定为true，则代表允许回收达到指定空闲时间的核心线程。另外当线程总数大于核心线程数时，都会使得timed为true。

如果timed为true，则调用阻塞队列中poll方法。当获取任务超时后，poll会返回null，并会在下一次for循环中，getTask返回null。

如果timed为false，则调用take方法，底层会使用到aqs，直到有任务后，该方法才会返回。

也就是说，如果我们没有设置allowCoreThreadTimeOut，那么allowCoreThreadTimeOut就默认为false，核心线程就会一直被阻塞在getTask上。

其实在线程日志中，早已经暴露了调用链路。

直到这里，我们才恍然大悟，原来核心线程处于阻塞阶段，自然不能被GC回收。

解决方案

局部线程池不太优雅，大可以使用一个全局线程池来做。如果你的业务就是需要用到局部线程池，去做一些隔离的事情。

那么需要及时地去释放核心线程与线程池，为了防止线程泄露，有以下的方式：

（1）从源码探究一节中，我们了解到可以设置allowCoreThreadTimeOut，来让线程池回收空闲达到指定时间的核心线程。

修改一下代码

    @RequestMapping("/execute")
    public String execute() {

        ThreadPoolExecutor pool = new ThreadPoolExecutor(
                10,
                10,
                3,
                TimeUnit.SECONDS,
                new LinkedBlockingQueue<>(),
                new MyThreadFactory());

        pool.allowCoreThreadTimeOut(true);

        for (int i = 0; i < 20; i++) {
            pool.execute(() -> {
                try {
                    //模拟业务耗时
                    Thread.sleep(2000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            });
        }
        
        return "success";
    }

10个核心线程，20个任务，每个任务耗时2秒，空闲时间为3秒，那么一个线程应该会存活2+2+3=7秒左右，接着观察一下JVisualVM