CountdownLatch使用不当导致的线程卡死
问题现象
今天有其他项目遇到了一个问题，找了很久没有找到原因，于是找到我帮忙看下。他们使用了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
