在高并發(fā)、異步化等場景，線程池的運用可以說無處不在。線程池從本質(zhì)上來講，即通過空間換取時間，因為線程的創(chuàng)建和銷毀都是要消耗資源和時間的，對于大量使用線程的場景，使用池化管理可以延遲線程的銷毀，大大提高單個線程的復(fù)用能力，進一步提升整體性能。

今天遇到了一個比較典型的線上問題，剛好和線程池有關(guān)，另外涉及到死鎖、jstack命令的使用、JDK不同線程池的適合場景等知識點，同時整個調(diào)查思路可以借鑒，特此記錄和分享一下。

01 業(yè)務(wù)背景描述

該線上問題發(fā)生在廣告系統(tǒng)的核心扣費服務(wù)，首先簡單交代下大致的業(yè)務(wù)流程，方便理解問題。

綠框部分即扣費服務(wù)在廣告召回扣費流程中所處的位置，簡單理解：當(dāng)用戶點擊一個廣告后，會從C端發(fā)起一次實時扣費請求(CPC，按點擊扣費模式)，扣費服務(wù)則承接了該動作的核心業(yè)務(wù)邏輯：包括執(zhí)行反作弊策略、創(chuàng)建扣費記錄、click日志埋點等。

02 問題現(xiàn)象和業(yè)務(wù)影響

12月2號晚上11點左右，我們收到了一個線上告警通知：扣費服務(wù)的線程池任務(wù)隊列大小遠(yuǎn)遠(yuǎn)超出了設(shè)定閾值，而且隊列大小隨著時間推移還在持續(xù)變大。詳細(xì)告警內(nèi)容如下：

相應(yīng)的，我們的廣告指標(biāo)：點擊數(shù)、收入等也出現(xiàn)了非常明顯的下滑，幾乎同時發(fā)出了業(yè)務(wù)告警通知。其中，點擊數(shù)指標(biāo)對應(yīng)的曲線表現(xiàn)如下：

該線上故障發(fā)生在流量高峰期，持續(xù)了將近30分鐘后才恢復(fù)正常。

03 問題調(diào)查和事故解決過程

下面詳細(xì)說下整個事故的調(diào)查和分析過程。

第1步：收到線程池任務(wù)隊列的告警后，我們第一時間查看了扣費服務(wù)各個維度的實時數(shù)據(jù)：包括服務(wù)調(diào)用量、超時量、錯誤日志、JVM監(jiān)控，均未發(fā)現(xiàn)異常。

第2步：然后進一步排查了扣費服務(wù)依賴的存儲資源（mysql、redis、mq），外部服務(wù)，發(fā)現(xiàn)了事故期間存在大量的數(shù)據(jù)庫慢查詢。

上述慢查詢來自于事故期間一個剛上線的大數(shù)據(jù)抽取任務(wù)，從扣費服務(wù)的mysql數(shù)據(jù)庫中大批量并發(fā)抽取數(shù)據(jù)到hive表。因為扣費流程也涉及到寫mysql，猜測這個時候mysql的所有讀寫性能都受到了影響，果然進一步發(fā)現(xiàn)insert操作的耗時也遠(yuǎn)遠(yuǎn)大于正常時期。

第3步：我們猜測數(shù)據(jù)庫慢查詢影響了扣費流程的性能，從而造成了任務(wù)隊列的積壓，所以決定立馬暫定大數(shù)據(jù)抽取任務(wù)。但是很奇怪：停止抽取任務(wù)后，數(shù)據(jù)庫的insert性能恢復(fù)到正常水平了，但是阻塞隊列大小仍然還在持續(xù)增大，告警并未消失。

第4步：考慮廣告收入還在持續(xù)大幅度下跌，進一步分析代碼需要比較長的時間，所以決定立即重啟服務(wù)看看有沒有效果。為了保留事故現(xiàn)場，我們保留了一臺服務(wù)器未做重啟，只是把這臺機器從服務(wù)管理平臺摘掉了，這樣它不會接收到新的扣費請求。

果然重啟服務(wù)的殺手锏很管用，各項業(yè)務(wù)指標(biāo)都恢復(fù)正常了，告警也沒有再出現(xiàn)。至此，整個線上故障得到解決，持續(xù)了大概30分鐘。

04 問題根本原因的分析過程

下面再詳細(xì)說下事故根本原因的分析過程。

第1步：第二天上班后，我們猜測那臺保留了事故現(xiàn)場的服務(wù)器，隊列中積壓的任務(wù)應(yīng)該都被線程池處理掉了，所以嘗試把這臺服務(wù)器再次掛載上去驗證下我們的猜測，結(jié)果和預(yù)期完全相反，積壓的任務(wù)仍然都在，而且隨著新請求進來，系統(tǒng)告警立刻再次出現(xiàn)了，所以又馬上把這臺服務(wù)器摘了下來。

第2步：線程池積壓的幾千個任務(wù)，經(jīng)過1個晚上都沒被線程池處理掉，我們猜測應(yīng)該存在死鎖情況。所以打算通過jstack命令dump線程快照做下詳細(xì)分析。 

#找到扣費服務(wù)的進程號    
$ jstack pid > /tmp/stack.txt    
# 通過進程號dump線程快照，輸出到文件中   
$ jstack pid > /tmp/stack.txt   

在jstack的日志文件中，立馬發(fā)現(xiàn)了：用于扣費的業(yè)務(wù)線程池的所有線程都處于waiting狀態(tài)，線程全部卡在了截圖中紅框部分對應(yīng)的代碼行上，這行代碼調(diào)用了countDownLatch的await()方法，即等待計數(shù)器變?yōu)?后釋放共享鎖。

第3步：找到上述異常后，距離找到根本原因就很接近了，我們回到代碼中繼續(xù)調(diào)查，首先看了下業(yè)務(wù)代碼中使用了newFixedThreadPool線程池，核心線程數(shù)設(shè)置為25。針對newFixedThreadPool，JDK文檔的說明如下：

創(chuàng)建一個可重用固定線程數(shù)的線程池，以共享的無界隊列方式來運行這些線程。如果在所有線程處于活躍狀態(tài)時提交新任務(wù)，則在有可用線程之前，新任務(wù)將在隊列中等待。

關(guān)于newFixedThreadPool，核心包括兩點：

    1、最大線程數(shù) = 核心線程數(shù)，當(dāng)所有核心線程都在處理任務(wù)時，新進來的任務(wù)會提交到任務(wù)隊列中等待；

    2、使用了無界隊列：提交給線程池的任務(wù)隊列是不限制大小的，如果任務(wù)被阻塞或者處理變慢，那么顯然隊列會越來越大。

所以，進一步結(jié)論是：核心線程全部死鎖，新進的任務(wù)不對涌入無界隊列，導(dǎo)致任務(wù)隊列不斷增加。

第4步：到底是什么原因?qū)е碌乃梨i，我們再次回到j(luò)stack日志文件中提示的那行代碼做進一步分析。下面是我簡化過后的示例代碼： 

/**    
 * 執(zhí)行扣費任務(wù)    
 */    
public Result<Integer> executeDeduct(ChargeInputDTO chargeInput) {    
  ChargeTask chargeTask = new ChargeTask(chargeInput);    
  bizThreadPool.execute(() -> chargeTaskBll.execute(chargeTask ));   
  return Result.success();    
}    
/*    
 * 扣費任務(wù)的具體業(yè)務(wù)邏輯    
 */    
public class ChargeTaskBll implements Runnable {   
  public void execute(ChargeTask chargeTask) {    
     // 第一步：參數(shù)校驗    
     verifyInputParam(chargeTask);    
     // 第二步：執(zhí)行反作弊子任務(wù)    
     executeUserSpam(SpamHelper.userConfigs);  
     // 第三步：執(zhí)行扣費    
     handlePay(chargeTask);    
     // 其他步驟：點擊埋點等    
     ...    
  }    
}    
/**    
 * 執(zhí)行反作弊子任務(wù)    
 */    
public void executeUserSpam(List<SpamUserConfigDO> configs) {    
  if (CollectionUtils.isEmpty(configs)) {    
    return;    
  }    
  try {    
    CountDownLatch latch = new CountDownLatch(configs.size());    
    for (SpamUserConfigDO config : configs) {    
      UserSpamTask task = new UserSpamTask(config,latch);    
      bizThreadPool.execute(task);    
    }    
    latch.await();    
  } catch (Exception ex) {    
    logger.error("", ex);    
  }    
}   

通過上述代碼，大家能否發(fā)現(xiàn)死鎖是怎么發(fā)生的呢？

根本原因在于：一次扣費行為屬于父任務(wù)，同時它又包含了多次子任務(wù)：子任務(wù)用于并行執(zhí)行反作弊策略，而父任務(wù)和子任務(wù)使用的是同一個業(yè)務(wù)線程池。

當(dāng)線程池中全部都是執(zhí)行中的父任務(wù)時，并且所有父任務(wù)都存在子任務(wù)未執(zhí)行完，這樣就會發(fā)生死鎖。下面通過1張圖再來直觀地看下死鎖的情況：

假設(shè)核心線程數(shù)是2，目前正在執(zhí)行扣費父任務(wù)1和2。另外，反作弊子任務(wù)1和3都執(zhí)行完了，反作弊子任務(wù)2和4都積壓在任務(wù)隊列中等待被調(diào)度。因為反作弊子任務(wù)2和4沒執(zhí)行完，所以扣費父任務(wù)1和2都不可能執(zhí)行完成，這樣就發(fā)生了死鎖，核心線程永遠(yuǎn)不可能釋放，從而造成任務(wù)隊列不斷增大，直到程序OOM crash。

死鎖原因清楚后，還有個疑問：上述代碼在線上運行很長時間了，為什么現(xiàn)在才暴露出問題呢？另外跟數(shù)據(jù)庫慢查詢到底有沒有直接關(guān)聯(lián)呢？

暫時我們還沒有復(fù)現(xiàn)證實，但是可以推斷出：上述代碼一定存在死鎖的概率，尤其在高并發(fā)或者任務(wù)處理變慢的情況下，概率會大大增加。數(shù)據(jù)庫慢查詢應(yīng)該就是導(dǎo)致此次事故出現(xiàn)的導(dǎo)火索。

05 解決方案

弄清楚根本原因后，最簡單的解決方案就是：增加一個新的業(yè)務(wù)線程池，用來隔離父子任務(wù)，現(xiàn)有的線程池只用來處理扣費任務(wù)，新的線程池用來處理反作弊任務(wù)。這樣就可以徹底避免死鎖的情況了。

06 問題總結(jié)

回顧事故的解決過程以及扣費的技術(shù)方案，存在以下幾點待繼續(xù)優(yōu)化：

1、使用固定線程數(shù)的線程池存在OOM風(fēng)險，在阿里巴巴Java開發(fā)手冊中也明確指出，而且用的詞是『不允許』使用Executors創(chuàng)建線程池。而是通過ThreadPoolExecutor去創(chuàng)建，這樣讓寫的同學(xué)能更加明確線程池的運行規(guī)則和核心參數(shù)設(shè)置，規(guī)避資源耗盡的風(fēng)險。

2、廣告的扣費場景是一個異步過程，通過線程池或者MQ來實現(xiàn)異步化處理都是可選的方案。另外，極個別的點擊請求丟失不扣費從業(yè)務(wù)上是允許的，但是大批量的請求丟棄不處理且沒有補償方案是不允許的。后續(xù)采用有界隊列后，拒絕策略可以考慮發(fā)送MQ做重試處理。