近期,我们的项目在生产环境中运行时频繁出现一个难以理解的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”。大多数人可能都会这样认为,也确信结果必然如此。然而,事实却是有时只打印了“a”,而没有打印“b”,并且没有任何异常日志。
这个现象超出了我们的认知,一时间让人感到困惑。程序为何运行一半就停止了?难道多年的认知要被推翻,全世界都错了吗?
仔细思考后,作为一个拥有多年CRUD经验的程序员,我认为问题应该还是出在我自己身上。那么,问题究竟在哪里呢?
通过对比常规代码与这段代码的区别,我发现这段代码唯一特殊的地方在于使用了`@Async`注解。另外,这部分代码近期才开始显现出问题,难道是其他地方的改动影响到了这里?
有两个排查方向:一是调查`@Async`的使用情况;二是检查近期的代码更改。
众所周知,`@Async`的作用是让系统在新的线程中执行`method2`。但为什么有时不执行呢?难道是系统没有开启新线程?或者是线程不够用了?通常情况下,`@Async`使用的是Spring默认的线程池,而这个线程池的大小几乎是无限的。我们系统的访问量并未达到这个级别。
会不会是`@Async`使用了其他的线程池?为了核实这一点,我查看了日志文件,发现在打印“a”的那行日志前面有线程名“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,队列容量扩大到几千,并将拒绝策略改为抛出异常的策略。