1. 問題&分析

迭代剛上線，小艾同學(xué)又接到了一線業(yè)務(wù)的投訴，一起看下本次遇到的又是什么問題。

1.1. 案例

上周接到一個(gè)需求，需要對(duì)系統(tǒng)中的核心操作增加操作日志，也就是在操作完成后對(duì)操作人、操作時(shí)間等信息進(jìn)行詳細(xì)記錄。核心包括：創(chuàng)建訂單、取消訂單、刪除訂單、修改價(jià)格等。

在需求分析時(shí)，小艾做了深度思考：記錄操作日志不能影響正常的業(yè)務(wù)操作，比如創(chuàng)建訂單，哪怕是操作日志記錄失敗，也不能導(dǎo)致下單失敗。

當(dāng)然，方案1便是，記錄日志的邏輯使用 try-catch 進(jìn)行處理，哪怕是拋出異常也不能影響原來的主流程。

圖片

這樣做確實(shí)能控制住異常，但由于是在主線程中運(yùn)行，這樣會(huì)導(dǎo)致整個(gè)流程的處理時(shí)間加長。這時(shí)，小艾想起了線程池的異常操作，整體如下：

圖片

這個(gè)方案好處多多：

1. 可以非常好對(duì)異常進(jìn)行隔離，任務(wù)執(zhí)行發(fā)生異常也不會(huì)影響主流程
2. 操作日志在線程池中異步處理，不會(huì)占用主線程的時(shí)間，整體操作時(shí)間變化不大

核心代碼如下：

@GetMapping("createOrder")
public RestResult<String> createOrder(Integer taskId){
    log.info("begin to create Order {}", taskId);
    // 創(chuàng)建訂單
    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() {
        // 實(shí)際執(zhí)行業(yè)務(wù)邏輯，保存到數(shù)據(jù)庫
    }
}

在收到業(yè)務(wù)反饋時(shí)，小艾第一時(shí)間查看日志，居然沒有找到任何異常信息。難道是業(yè)務(wù)反饋信息有問題？根據(jù)業(yè)務(wù)提供的訂單號(hào)，在數(shù)據(jù)庫中確實(shí)沒有找到操作記錄，好奇怪呀。

從日志中提取出 正常 和 異常 信息，分別如下：

正常日志：

圖片

可以看出：

1. 在主線程中完成創(chuàng)建訂單和提交任務(wù)操作
2. 在線程池線程中完成操作日志保存操作
3. 在數(shù)據(jù)庫中能看到詳細(xì)的操作信息

異常日志：

圖片

可以看出少了些信息：

1. 主線程操作沒有變化，完成了創(chuàng)建訂單和提交任務(wù)操作
2. 線程池線程只打印了開始執(zhí)行的日志，未見到執(zhí)行成功日志
3. 數(shù)據(jù)中也沒有操作信息

對(duì)比日志可見，==保存操作日志的任務(wù)執(zhí)行失敗，同時(shí)系統(tǒng)沒有拋出任何異常?。?！==

1.2. 問題分析

核心還是對(duì) 線程池的核心 API 不熟悉，當(dāng)使用 `execute()` 方法提交任務(wù)時(shí)，異常信息不會(huì)直接拋出給調(diào)用者。這是因?yàn)榫€程池處理任務(wù)的方式是，將這些任務(wù)封裝到一個(gè) `Runnable` 中去執(zhí)行。`Runnable.run()` 方法沒有任何拋出異常的聲明，所以在運(yùn)行 `Runnable` 時(shí)產(chǎn)生的異常只會(huì)被內(nèi)部捕獲，不會(huì)拋出。

線程池中提供兩者函數(shù)：

1. `execute()` 方法用于提交不需要返回值的任務(wù)，所以無法判斷任務(wù)是否被線程池成功執(zhí)行。
2. `submit()` 方法用于提交需要返回值的任務(wù)。線程池會(huì)返回一個(gè) future 類型的對(duì)象，通過這個(gè) future 對(duì)象可以判斷任務(wù)是否執(zhí)行成功。

2. 解決方案

最大困擾原因是：出問題后沒有任何信息。所以對(duì)應(yīng)的解決方案便是：讓系統(tǒng)能夠打印異常棧暴露異常原因。

2.1. 手工拋出異常

最簡單方式便是，在Task代碼中通 try-catch 手工捕獲并打印異常日志。

詳細(xì)代碼如下：

@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);
        }
    }
}

當(dāng)出現(xiàn)異常數(shù)據(jù)時(shí)，日志如下：

圖片

可以看出，從 SaveOperationLogTask1 類中清楚的打印異常信息。

2.2. 封裝 Runnable 統(tǒng)一管理異常

每個(gè) Task 都手工添加 try-catch 邏輯，不僅工作量大也非常容易出現(xiàn)遺漏場(chǎng)景，我們需要一個(gè)更好的方案。

可以構(gòu)建一個(gè) Runnable 的封裝類來對(duì)異常進(jìn)行統(tǒng)一處理，詳細(xì)代碼如下：

@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);
        }
    }
}

// 在提交任務(wù)時(shí)，使用 LogBasedTaskWrapper 對(duì) Task 進(jìn)行封裝即可
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);

當(dāng)出現(xiàn)異常數(shù)據(jù)時(shí)，日志如下：

圖片

可以看出，從 LogBasedTaskWrapper 類中清楚的打印異常信息。

2.3. 定制化線程工廠

Wrapper 機(jī)制不錯(cuò)，但需要對(duì) Task 進(jìn)行封裝操作，還是容易被遺漏，我們還需要更簡單的方式。

可以對(duì)線程池的線程工廠進(jìn)行定制，對(duì)為捕獲異常進(jìn)行特殊處理，詳細(xì)代碼如下：

executorServiceV2 = new ThreadPoolExecutor(4, 4,
        0L, TimeUnit.MILLISECONDS,
        new LinkedBlockingQueue<Runnable>(20),
        new BasicThreadFactory.Builder()
                .namingPattern("BlackHole_thread-%d")
                // 設(shè)置為捕獲異常處理器
                .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))。當(dāng)出現(xiàn)未捕獲異常時(shí)，會(huì)統(tǒng)一被 UncaughtExceptionHandler 處理。詳細(xì)日志如下：

圖片

從日志中看到，從 ExceptionBlackHoleFixController 類中對(duì)異常進(jìn)行處理。

這是一勞永逸的方法，也是最鼓勵(lì)的方法。

2.4. 使用 CompletableFuture

當(dāng)使用 submit 提交任務(wù)時(shí)，會(huì)返回 Futrue 對(duì)象，通過 Future 的 get 方法便可以獲取任務(wù)運(yùn)行的異常信息，但這樣會(huì)阻塞主線程導(dǎo)致接口響應(yīng)時(shí)間過長。

這種情況下，可以使用更高級(jí)的 CompletableFuture，向 CompletableFuture 設(shè)置異常處理器后，出現(xiàn)異常時(shí)會(huì)自動(dòng)調(diào)用處理器，核心代碼如下：

// 異步保存操作日志
log.info("Begin to Submit Task {}", taskId);
CompletableFuture<Void> 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);

當(dāng)出現(xiàn)異常數(shù)據(jù)時(shí)，日志如下：

圖片

image

從日志中看到，從 ExceptionBlackHoleFixController 類中對(duì)異常進(jìn)行處理。

3. 示例&源碼

代碼倉庫：https://gitee.com/litao851025/learnFromBug

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