1. 問題&分析

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

成都創(chuàng)新互聯(lián)是一家專業(yè)提供前郭企業(yè)網(wǎng)站建設(shè),專注與網(wǎng)站設(shè)計、成都做網(wǎng)站、html5、小程序制作等業(yè)務(wù)。10年已為前郭眾多企業(yè)、政府機構(gòu)等服務(wù)。創(chuàng)新互聯(lián)專業(yè)網(wǎng)絡(luò)公司優(yōu)惠進行中。

1.1. 案例

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

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

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

圖片

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

圖片

這個方案好處多多：

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

核心代碼如下：

@GetMapping("createOrder")
public RestResult 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() {
        // 實際執(zhí)行業(yè)務(wù)邏輯，保存到數(shù)據(jù)庫
    }
}

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

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

正常日志：

圖片

可以看出：

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

異常日志：

圖片

可以看出少了些信息：

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

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

1.2. 問題分析

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

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

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

2. 解決方案

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

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

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

圖片

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

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

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

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

@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ù)時，使用 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);

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

圖片

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

2.3. 定制化線程工廠

Wrapper 機制不錯，但需要對 Task 進行封裝操作，還是容易被遺漏，我們還需要更簡單的方式。

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

executorServiceV2 = new ThreadPoolExecutor(4, 4,
        0L, TimeUnit.MILLISECONDS,
        new LinkedBlockingQueue(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)未捕獲異常時，會統(tǒng)一被 UncaughtExceptionHandler 處理。詳細日志如下：

圖片

從日志中看到，從 ExceptionBlackHoleFixController 類中對異常進行處理。

這是一勞永逸的方法，也是最鼓勵的方法。

2.4. 使用 CompletableFuture

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

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

// 異步保存操作日志
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);

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

圖片

image

從日志中看到，從 ExceptionBlackHoleFixController 類中對異常進行處理。

3. 示例&源碼

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

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

當(dāng)前文章：線程池異常黑洞及其防范策略
文章網(wǎng)址：http://uogjgqi.cn/article/djccigg.html