【故障现场】线程池异常黑洞及其防范策略

还原故障现场，挖掘通用场景，寻求最佳解决方案！！！

1. 问题&分析

迭代刚上线，小艾同学又接到了一线业务的投诉，一起看下本次遇到的又是什么问题。

1.1. 案例

上周接到一个需求，需要对系统中的核心操作增加操作日志，也就是在操作完成后对操作人、操作时间等信息进行详细记录。核心包括：创建订单、取消订单、删除订单、修改价格等。

在需求分析时，小艾做了深度思考：记录操作日志不能影响正常的业务操作，比如创建订单，哪怕是操作日志记录失败，也不能导致下单失败。

当然，方案1便是，记录日志的逻辑使用 try-catch 进行处理，哪怕是抛出异常也不能影响原来的主流程。

image

这样做确实能控制住异常，但由于是在主线程中运行，这样会导致整个流程的处理时间加长。这时，小艾想起了线程池的异常操作，整体如下：

image

这个方案好处多多：

可以非常好对异常进行隔离，任务执行发生异常也不会影响主流程

操作日志在线程池中异步处理，不会占用主线程的时间，整体操作时间变化不大

核心代码如下：

@GetMapping("createOrder")

public RestResult createOrder(Integer taskId){

log.info("begin to create Order {}", taskId);

// 创建订单

doCreateOrder(taskId);

log.info("end to create Order {}", taskId);

// 异步保存操作日志

log.info("Begin to Submit Task {}", taskId);

this.executorService.execute(new SaveOperationLogTask(taskId));

log.info("Success to Submit Task {}", taskId);

return RestResult.success("提交成功");

}

// 保存操作日志 Task

@Slf4j

public class SaveOperationLogTask implements Runnable {

// 省略部分代码

@Override

public void run() {

log.info("Begin to save operation");

// 保存日志

saveLog();

log.info("Success to Run task {}", this.taskId);

}

private void saveLog() {

// 实际执行业务逻辑，保存到数据库

}

}

在收到业务反馈时，小艾第一时间查看日志，居然没有找到任何异常信息。难道是业务反馈信息有问题？根据业务提供的订单号，在数据库中确实没有找到操作记录，好奇怪呀。

从日志中提取出 正常 和 异常 信息，分别如下：

正常日志：

image

可以看出：

在主线程中完成创建订单和提交任务操作

在线程池线程中完成操作日志保存操作

在数据库中能看到详细的操作信息

异常日志：

image

可以看出少了些信息：

主线程操作没有变化，完成了创建订单和提交任务操作

线程池线程只打印了开始执行的日志，未见到执行成功日志

数据中也没有操作信息

对比日志可见，==保存操作日志的任务执行失败，同时系统没有抛出任何异常！！！==

1.2. 问题分析

核心还是对 线程池的核心 API 不熟悉，当使用 `execute()` 方法提交任务时，异常信息不会直接抛出给调用者。这是因为线程池处理任务的方式是，将这些任务封装到一个 `Runnable` 中去执行。`Runnable.run()` 方法没有任何抛出异常的声明，所以在运行 `Runnable` 时产生的异常只会被内部捕获，不会抛出。

线程池中提供两者函数：

`execute()` 方法用于提交不需要返回值的任务，所以无法判断任务是否被线程池成功执行。

`submit()` 方法用于提交需要返回值的任务。线程池会返回一个 future 类型的对象，通过这个 future 对象可以判断任务是否执行成功。

2. 解决方案

最大困扰原因是：出问题后没有任何信息。所以对应的解决方案便是：让系统能够打印异常栈暴露异常原因。

2.1. 手工抛出异常

最简单方式便是，在Task代码中通 try-catch 手工捕获并打印异常日志。

详细代码如下：

@Slf4j

public class SaveOperationLogTask1 implements Runnable {

// 省略非核心代码

@Override

public void run() {

try {

int result = RandomUtils.nextInt() / this.taskId;

log.info("Success to Run task {}", this.taskId);

}catch (Exception e) {

log.error("failed to run task {}", taskId, e);

}

}

}

当出现异常数据时，日志如下：

image

可以看出，从 SaveOperationLogTask1 类中清楚的打印异常信息。

2.2. 封装 Runnable 统一管理异常

每个 Task 都手工添加 try-catch 逻辑，不仅工作量大也非常容易出现遗漏场景，我们需要一个更好的方案。

可以构建一个 Runnable 的封装类来对异常进行统一处理，详细代码如下：

@Slf4j

public class LogBasedTaskWrapper implements Runnable {

private final Runnable runnable;

public LogBasedTaskWrapper(Runnable runnable) {

this.runnable = runnable;

}

@Override

public void run() {

try {

this.runnable.run();

}catch (Exception e) {

log.error("Filed to run task {}", runnable, e);

}

}

}

// 在提交任务时，使用 LogBasedTaskWrapper 对 Task 进行封装即可

log.info("Begin to Submit Task {}", taskId);

Runnable task = new SaveOperationLogTask(taskId);

this.executorService.execute(new LogBasedTaskWrapper(task));

log.info("Success to Submit Task {}", taskId);

当出现异常数据时，日志如下：

image

可以看出，从 LogBasedTaskWrapper 类中清楚的打印异常信息。

2.3. 定制化线程工厂

Wrapper 机制不错，但需要对 Task 进行封装操作，还是容易被遗漏，我们还需要更简单的方式。

可以对线程池的线程工厂进行定制，对为捕获异常进行特殊处理，详细代码如下：

executorServiceV2 = new ThreadPoolExecutor(4, 4,

0L, TimeUnit.MILLISECONDS,

new LinkedBlockingQueue(20),

new BasicThreadFactory.Builder()

.namingPattern("BlackHole_thread-%d")

// 设置为捕获异常处理器

.uncaughtExceptionHandler((t, e) -> log.error("Failed to run task", e))

.build(),

new ThreadPoolExecutor.AbortPolicy());

// 然后使用 executorServiceV2 即可

// 异步保存操作日志

log.info("Begin to Submit Task {}", taskId);

this.executorServiceV2.execute(new SaveOperationLogTask(taskId));

log.info("Success to Submit Task {}", taskId);

核心代码就一句：.uncaughtExceptionHandler((t, e) -> log.error("Failed to run task", e))。当出现未捕获异常时，会统一被 UncaughtExceptionHandler 处理。详细日志如下：

image

从日志中看到，从 ExceptionBlackHoleFixController 类中对异常进行处理。

这是一劳永逸的方法，也是最鼓励的方法。

2.4. 使用 CompletableFuture

当使用 submit 提交任务时，会返回 Futrue 对象，通过 Future 的 get 方法便可以获取任务运行的异常信息，但这样会阻塞主线程导致接口响应时间过长。

这种情况下，可以使用更高级的 CompletableFuture，向 CompletableFuture 设置异常处理器后，出现异常时会自动调用处理器，核心代码如下：

// 异步保存操作日志

log.info("Begin to Submit Task {}", taskId);

CompletableFuture completableFuture = CompletableFuture.runAsync(new SaveOperationLogTask(taskId), this.executorService);

completableFuture.exceptionally(e -> {

log.error("Failed to Submit Task", e);

return null;

}

);

log.info("Success to Submit Task {}", taskId);

当出现异常数据时，日志如下：

image

从日志中看到，从 ExceptionBlackHoleFixController 类中对异常进行处理。

3. 示例&源码

代码仓库：https://gitee.com/litao851025/learnFromBug

代码地址：https://gitee.com/litao851025/learnFromBug/tree/master/src/main/java/com/geekhalo/demo/thread/exceptionblackhole