当前位置：首页 > 软件设计 > 正文内容

CountdownLatch使用不当导致的线程卡死

邻居的猫1个月前 (12-09)软件设计1371

问题现象

今天有其他项目遇到了一个问题，找了好久没有找到原因，所以找到我帮助看下。他们运用了Spring Scheduling开发了一个守时使命，然后每天早上的8点会履行一次。在DEV环境的时分是正常运转而且测试经过的，可是在发布到UAT环境之后发现了一个问题，这个守时使命只会在服务发布后触发一次，然后就再也不会调度了。

排查进程

根本查看

首要是对线上环境的装备进行了查看，首要是守时使命的装备是否有问题。

是否敞开了守时使命

@EnableScheduling
@SpringBootApplication(exclude = {
        RedisAutoConfiguration.class, RedissonAutoConfiguration.class,
        SecurityAutoConfiguration.class,
        ManagementWebSecurityAutoConfiguration.class})
public class FrontProviderApplication {
    
}

首要确定是敞开了调度使命的（实际上这个肯定是没问题的，由于在这个问题中，守时使命是触发了的，只不过只触发了一次）

调度装备是否正确，是不是装备成了一次性使命。

@Scheduled(cron = "30 10 8 * * ?")
    public void setCollectData() throws InterruptedException {
        log.info("history=开端处理历史数据");
        historyCollectComponent.setCollectData();
        log.info("history=处理历史数据结束");
}

经过查看也没有发现问题。

日志排查

装备假如没有问题的话，只能经过日志看下"案发现场"有没有什么头绪。不出预料，日志天然也是平平无奇。也没有发现有显着的反常。

日志中呈现了调度使命一开端就打印的日志，可是没有结束的日志。中心也没有发现反常。

history=开端处理历史数据

复现

排查到这儿，能够承认的是调度使命触发了，可是一向没有结束，可能是线程一向在等候。所以我预备复现下这个问题，所以把守时使命的频率调整为5分钟履行一次。这个的条件是我查看了守时使命的逻辑，也跟项目的开发搭档承认了。这个守时使命是幂等的。所以我暂时调整为5分钟一次，并不会有什么问题。

调整为5分钟一次后，发现守时使命居然又正常了，5分钟一次有序进行。那这就有点伤脑筋了。这个问题暂时无法复现。

所以比较简略的方法便是，在今晚做一次服务重启，然后等候明日早上的8点，运用arthas监控一下守时使命方法的履行，看下是什么问题。

代码逻辑筛查

这么古怪的问题，要比及第二天早上才干找出原因，着实有点难过。所以我带着好奇心，耐着性质捋了下全体的代码逻辑。这个守时使命的逻辑仍是比较复杂的。可是其间中心的逻辑结构大约如下：

@Component
public class SpringCountDownLatchScheduler {

    @Scheduled(cron = "0/15 * * * * ? ")
    public void setCollectData() throws InterruptedException {
        System.out.println("history=开端处理历史数据");
        serviceA();
        System.out.println("history=处理历史数据结束");
    }


    private void serviceA() throws InterruptedException {
        CountDownLatch countDownLatch = new CountDownLatch(2);
        serviceB(countDownLatch);
        countDownLatch.await();
    }

    private void serviceB(CountDownLatch countDownLatch) {
        new Thread() {
            @Override
            public void run() {
                System.out.println("子线程" + Thread.currentThread().getName() + "正在履行");
                try {
                    Thread.sleep(3000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                System.out.println("子线程" + Thread.currentThread().getName() + "履行结束");
                countDownLatch.countDown();
            }
        }.start();
        new Thread() {
            @Override
            public void run() {
                System.out.println("子线程" + Thread.currentThread().getName() + "正在履行");
                try {
                    Thread.sleep(3000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                System.out.println("子线程" + Thread.currentThread().getName() + "履行结束");
                countDownLatch.countDown();
            }
        }.start();
    }
}

在serviceA()方法中运用了CountDownLatch，计数器是2。然后发动两个子线程完结一系列逻辑，然后经过CountDownLatch的await()方法等候两个线程履行完，然后持续履行后续的逻辑。整个守时使命15s履行一次。

不知道咱们有没有发现这个结构的问题，我也是愣了一瞬间才发现不对劲。假如子线程在countDown()之前发生了反常呢？那主线程不就一向在等候了吗？所以我快速验证了一下：

@Component
public class SpringCountDownLatchScheduler {

    @Scheduled(cron = "0/15 * * * * ? ")
    public void setCollectData() throws InterruptedException {
        System.out.println("history=开端处理历史数据");
        serviceA();
        System.out.println("history=处理历史数据结束");
    }


    private void serviceA() throws InterruptedException {
        CountDownLatch countDownLatch = new CountDownLatch(2);
        serviceB(countDownLatch);
        countDownLatch.await();
    }

    private void serviceB(CountDownLatch countDownLatch) {
        new Thread() {
            @Override
            public void run() {
                System.out.println("子线程" + Thread.currentThread().getName() + "正在履行");
                try {
                    Thread.sleep(3000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                if (Boolean.TRUE) {
                    throw new RuntimeException("我是反常");
                }
                System.out.println("子线程" + Thread.currentThread().getName() + "履行结束");
                countDownLatch.countDown();
            }
        }.start();
        new Thread() {
            @Override
            public void run() {
                System.out.println("子线程" + Thread.currentThread().getName() + "正在履行");
                try {
                    Thread.sleep(3000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                System.out.println("子线程" + Thread.currentThread().getName() + "履行结束");
                countDownLatch.countDown();
            }
        }.start();
    }
}

在第一个线程countDown之前，自动抛一个RuntimeException来模仿第一个线程有反常的状况。

公然跟咱们预期的相同，守时使命只触发了一次之后，就卡死了。

到这儿，现已找到了这个问题的根本原因，应该便是某个子线程反常了，导致主线程一向处在等候状况。那么为啥日志里看不到呢？除非代码里吞了反常，我查看了，发现并没有。

我带着这个疑问，又去日志里逐行看了一遍，发现有一行十分不起眼的Error。

2024-08-27 08:11:00.031 ERROR default 81232 [ForkJoinPool.commonPool-worker-62] o.h.engine.jdbc.spi.SqlExceptionHelper 142  142 : HikariPool-1 - Connection is not available, request timed out after 30000ms.

这下真相大白了。本来是由于数据库超时了。但仍是有个问题，为什么我调低作业频率为5分钟的时分为什么没有复现。这个我跟项目组的技能承认后发现，是由于他们早上8点左右的时分正是数据库负载最高的时分，大数据渠道会在8点左右同步数据过来。而我复现的时分是在下午，负载并不高。所以并没有呈现由于数据库超时导致守时使命反常的现象。

问题处理

知道原因之后，怎样处理就很简略了，有许多方法

优化守时使命的逻辑代码，countdown()必定要加反常处理，或许主线程await要加上超时时刻。
调整守时使命的时刻，与大数据渠道的推送峰口错开。
进步数据库资源装备。

优化后的代码结构如下：

@Component
public class SpringCountDownLatchScheduler {

    @Scheduled(cron = "0/15 * * * * ? ")
    public void setCollectData() throws InterruptedException {
        System.out.println("history=开端处理历史数据");
        serviceA();
        System.out.println("history=处理历史数据结束");
    }


    private void serviceA() throws InterruptedException {
        CountDownLatch countDownLatch = new CountDownLatch(2);
        serviceB(countDownLatch);
        countDownLatch.await();
    }

    private void serviceB(CountDownLatch countDownLatch) {
        new Thread() {
            @Override
            public void run() {
                System.out.println("子线程" + Thread.currentThread().getName() + "正在履行");
                try {
                    Thread.sleep(3000);
                    if (Boolean.TRUE) {
                        throw new RuntimeException("我是反常");
                    }
                    System.out.println("子线程" + Thread.currentThread().getName() + "履行结束");
                } catch (InterruptedException e) {
                    e.printStackTrace();
                } finally {
                    countDownLatch.countDown();
                }


            }
        }.start();
        new Thread() {
            @Override
            public void run() {
                System.out.println("子线程" + Thread.currentThread().getName() + "正在履行");
                try {
                    Thread.sleep(3000);
                    System.out.println("子线程" + Thread.currentThread().getName() + "履行结束");
                } catch (InterruptedException e) {
                    e.printStackTrace();
                } finally {
                    countDownLatch.countDown();
                }

            }
        }.start();
    }
}

能够看到，尽管守时使命有反常，可是依然没有影响到后续的调度。

总结反思

这次这个问题本质上是由于CountDownLatch的运用不标准导致的。可是实际上暴露了许多隐形的问题：

项目的日志打印很不标准，错误信息欠好辨识，这也是一开端没有定位到问题的很大一个原因。针对反常信息，必定要将完好的仓库信息同时打印出来，不要只输出message。辨识度很低而且不利于排查问题原因。
最好不要手艺发动线程，而是运用线程池，而且给线程的命名供给符合实际意义的命名，这样会十分有利于排查问题。
运用CountDownLatch.countdown()时必定要注意反常处理。

[重要提示]

一切博客内容，在我的个人博客网站可见，欢迎拜访： TwoFish