1. 問題描述

問題來源於某開源專案，在程式執行過程中，如果連線的資料庫停掉，會導致程式卡死，問題簡化後的程式碼如下：

@Test
public void testThreadPoolSubmitBlocked() {
    ExecutorService workerExecutor = Util.newSingleThreadExecutor(5000L);
    ((ThreadPoolExecutor) workerExecutor).setThreadFactory(new ThreadFactoryBuilder().setNameFormat("workerExecutor-pool-%d").build());

    ExecutorService groupInnerExecutorService = Util.newFixedThreadPool(1, 5000L);
    ((ThreadPoolExecutor) groupInnerExecutorService).setThreadFactory(new ThreadFactoryBuilder().setNameFormat("group-inner-pool-%d").build());

    for (int i = 0; i < 5; i++) {
        log.info("committing new task");
        Future<Boolean> workerExecutorFuture = workerExecutor.submit(() -> {
            Future<Boolean> groupInnerFuture = groupInnerExecutorService.submit(new Callable<Boolean>() {
                @Override
                public Boolean call() throws Exception {
                    try {
                        Thread.sleep(10000); //6s正常執行，10s時好時壞，20s卡死
                    } catch (InterruptedException e) {
                        log.info("interrupted");
                        throw new RuntimeException("child thread was interrupted!");
                    }
                    return true;
                }
            });

            try {
                groupInnerFuture.get();
            } catch (Exception e) {
                throw new RuntimeException(e);
            }
            return true;
        });

        log.info("task committed");

        try {
            Boolean aBoolean = workerExecutorFuture.get(5, TimeUnit.SECONDS);
            if (aBoolean != null && aBoolean) {
                break;
            }
        } catch (Exception e) {
            workerExecutorFuture.cancel(true);
        }
    }
}
 

Util.java:

public static ThreadPoolExecutor newFixedThreadPool(int nThreads, long keepAliveTime) {
    return new ThreadPoolExecutor(nThreads,
        nThreads,
        keepAliveTime,
        TimeUnit.MILLISECONDS,
        new SynchronousQueue<>(),
        (r, exe) -> {
            if (!exe.isShutdown()) {
                try {
                    exe.getQueue().put(r);
                } catch (InterruptedException e) {
                    // ignore
                }
            }
        });
}
 

因為Util類被在較多地方引用，為降低影響沒有修改Util類來設定執行緒池名稱。
執行上面的測試程式碼，輸出日誌內容大致如下：

09:22:48.206 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - committing new task
09:22:48.212 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - task committed
09:22:53.228 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - committing new task
09:22:53.229 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - task committed
09:22:58.243 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - committing new task
09:22:58.244 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - task committed
09:23:03.248 [main] INFO  c.a.o.c.c.adapter.support.UtilTest - committing new task
 

然後執行緒一直阻塞。

2. 原因分析

上面的多執行緒問題，原因如下：

workerExecutorFuture.cancel(true)方法會導致內部任務執行緒中斷；

而內部執行緒恰好阻塞在groupInnerExecutorService.submit()方法處，更精確一點，是在Util類中exe.getQueue().put(r)處；

當中斷髮生時，內部執行緒會丟擲InterruptedException異常，然後進入到catch塊，然而catch塊中什麼也沒做；

這樣就導致groupInnerExecutorService.submit()方法返回了一個Future例項，但這個例項對應的任務永遠不會被執行緒池執行；

groupInnerFuture.get()會一直阻塞。

3. 問題思考

上面的問題癥結在於這一處程式碼：

try {
    exe.getQueue().put(r);
} catch (InterruptedException e) {
    // ignore
}

這裡進入到異常分支卻什麼也沒做，導致出現問題卻沒有任何提示，對排查問題造成了不少障礙，如果列印一行錯誤日誌，將會使問題更容易定位。而如果改成下面這樣，阻塞的問題將不會出現：

try {
    exe.getQueue().put(r);
} catch (InterruptedException e) {
    // ignore
    logger.error("put runnable to queue failed");
    throw new RuntimeException("put runnable to queue failed, caused by: ", e);
}

原因是丟擲異常會使groupInnerExecutorService.submit()方法不返回結果，而是直接將異常繼續上拋導致執行緒終止。如果將workerExecutor.submit(()->{ ... }) 內部程式碼塊用try catch進行異常的捕獲並列印日誌，那麼異常資訊將會被列印。

上面的問題是專案中的問題被複現後再簡化得到的，實際專案中的原始碼比上面複雜得多。事實上將專案中的問題簡化成上面的程式碼就花了好幾天。事後總結了一下，認為如果先對日誌進行優化，也許問題會解決地快一點。

4. 不規範使用日誌示例

上面的問題只暴露出專案中日誌使用不規範的一些，還有其它不規範的做法也導致問題定位的困難，這裡總結如下：

4.1 不列印異常

如前所述，捕捉到異常後不做任何事，一旦異常真的發生，且導致問題出現，在複雜專案中可能會極難定位。除非真的確定異常發生不會有影響，否則至少還是列印一下日誌吧。

4.2 執行緒池任務異常不捕獲

如前所述，workerExecutor.submit(()->{ ... }) 內部程式碼塊最好用 try catch 包圍，然後列印一下日誌，如果有必要的話，可以再次丟擲異常。

4.3 logger物件定義為protected

protected final Logger logger = LoggerFactory.getLogger(this.getClass());

上面定義Logger物件的方式的有問題的，this.getClass()獲取的是例項的Class, 而不是類的Class, 這樣父類中列印日誌時，顯示的類名可能為子類（例項為子類物件）。

顯然this.getClass()改成 Test.class 也是有問題的，這會導致子類列印日誌顯示父類的類名。事實上，logger物件不應該在父類和子類間共享，所以定義為protected 是不合適的。

一般還是應採用如下寫法：

private static final Logger logger = LoggerFactory.getLogger(Test.class);

如果嫌麻煩，就用lombok或者IDEA自動生成程式碼吧。

4.4 異常日誌沒有說明

logger.error(e.getMessage(), e);

當捕捉到異常時，列印日誌採用上面寫法雖然省事，但卻不便於根據日誌快速定位至程式碼位置，一般應簡單說明錯誤內容。如：

logger.error("send message error!", e);

4.5 執行緒池沒有設定名稱

在遇到較複雜的多執行緒問題時，沒有命名的執行緒池會使問題更難定位。

4.6 異常日誌不列印堆疊

logger.error(e.getMessage() + " send message error!");

這種寫法不列印堆疊資訊，僅通過e.getMessage()可能根本無法推斷出異常的具體來源。

5. 總結

上面這些示例都是本次在定位問題過程中發現的，為解決問題不得不一點點優化日誌列印，直至最後問題解決。
回過頭來想一想，在定位問題前，若一開始就把日誌優化好，再來定位問題，也許效率會更高。