震惊，程序运行一半就不运行了

近期，我们的项目在生产环境中运行时频繁出现一个难以理解的Bug。这个问题颇为有趣，因此我决定在此记录下整个排查过程。

首先，让我模拟一下出问题的代码：

XController.java

@Resource
private XService xService;

@GetMapping("/method1")
public void method1(){
System.out.println("a");
xService.method2();
}

 

XService.java

@Async
public void method2() {
    System.out.println("b");   
}

 

　　

如上代码所示，逻辑相当简单。在Controller中的`method1`里，我们首先打印一个“a”，然后调用Service的`method2`，在`method2`中打印一个“b”。

按照常理，每次调用`method1`都应该依次打印“a”和“b”。大多数人可能都会这样认为，也确信结果必然如此。

然而，事实日志却类似这样：

2024-07-01 [nio-9099-exec-2] : a
2024-07-01 [     myThread-1] : b
2024-07-01 [nio-9099-exec-2] : a
2024-07-01 [     myThread-1] : b
2024-07-01 [nio-9099-exec-2] : a
2024-07-01 [nio-9099-exec-2] : a
2024-07-01 [nio-9099-exec-2] : a
2024-07-01 [nio-9099-exec-2] : a
2024-07-01 [nio-9099-exec-2] : a

 

如上所示，有时只打印了“a”，而没有打印“b”，并且没有任何异常日志。

这个现象超出了我们的认知，一时间让人感到困惑。程序为何运行一半就停止了？难道多年的认知要被推翻，全世界都错了吗？

仔细思考后，作为一个拥有多年CRUD经验的程序员，我认为问题应该还是出在我自己身上。那么，问题究竟在哪里呢？

通过对比常规代码与这段代码的区别，我发现这段代码唯一特殊的地方在于使用了`@Async`注解。

另外，这部分代码近期才开始显现出问题，难道是其他地方的改动影响到了这里？

有两个排查方向：一是调查`@Async`的使用情况；二是检查近期的代码更改。

众所周知，`@Async`的作用是让系统在新的线程中执行`method2`。但为什么有时不执行呢？难道是系统没有开启新线程？或者是线程不够用了？

通常情况下，`@Async`使用的是Spring默认的线程池，而这个线程池的大小几乎是无限的。我们系统的访问量并未达到这个级别。

会不会是`@Async`使用了其他的线程池？为了核实这一点，我查看了日志文件，发现在打印“b”的那行日志前面有线程名“myThread-1”。这个线程名显然是自定义的，并非Spring自带的。

进一步在代码中全局搜索“myThread”关键字，果然发现了自定义线程池的地方。经过检查代码提交记录，确认是其他同事最近提交的代码引起的问题。

再来看自定义线程池的配置：

 

executor.setMaxPoolSize(1);
executor.setQueueCapacity(50);
executor.setRejectedExecutionHandler(new ThreadPoolExecutor.DiscardPolicy());

 

　　

线程池中只有一个线程，队列容量为50。这意味着同时只能有50个任务排队等待执行。拒绝策略采用了`DiscardPolicy`，该策略会在队列已满时直接抛弃新任务，且不抛出异常。

复盘系统实际运行过程：当`method1`执行到`method2`时，会使用自定义线程池中的唯一一个线程`myThread-1`来执行。如果`myThread-1`已有任务在执行，新任务会进入队列排队。若任务过多超过50个，新任务就会被抛弃，不再执行。

由于任务被抛弃，这就解释了为何没有打印“b”。同时，由于采用了`DiscardPolicy`策略，因此没有异常日志产生。

知道了问题的原因，解决方案就变得清晰了。有两种解决方法：
1. 移除自定义线程池，回归使用默认线程池（尽管默认线程池存在无限队列问题，但我们的项目负载不会那么大）。
2. 调整自定义线程池的配置，增加线程数至8，队列容量扩大到几千，并将拒绝策略改为抛出异常的策略。