在高并發(fā)、異步化等場(chǎng)景，線程池的運(yùn)用可以說(shuō)無(wú)處不在。線程池從本質(zhì)上來(lái)講，即通過(guò)空間換取時(shí)間，因?yàn)榫€程的創(chuàng)建和銷毀都是要消耗資源和時(shí)間的，對(duì)于大量使用線程的場(chǎng)景，使用池化管理可以延遲線程的銷毀，大大提高單個(gè)線程的復(fù)用能力，進(jìn)一步提升整體性能。

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

#找到扣費(fèi)服務(wù)的進(jìn)程號(hào)
$?jstack?pid?>?/tmp/stack.txt 

#?通過(guò)進(jìn)程號(hào)dump線程快照，輸出到文件中
$?jstack?pid?>?/tmp/stack.txt

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

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

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

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

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

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

/**
?*?執(zhí)行扣費(fèi)任務(wù)
?*/
public?Result?executeDeduct(ChargeInputDTO?chargeInput)?{
??ChargeTask?chargeTask?=?new?ChargeTask(chargeInput);
??bizThreadPool.execute(()?->?chargeTaskBll.execute(chargeTask?));
??return?Result.success();
}

/*
?*?扣費(fèi)任務(wù)的具體業(yè)務(wù)邏輯
?*/
public?class?ChargeTaskBll?implements?Runnable?{

??public?void?execute(ChargeTask?chargeTask)?{
?????//?第一步：參數(shù)校驗(yàn)
?????verifyInputParam(chargeTask);

?????//?第二步：執(zhí)行反作弊子任務(wù)
?????executeUserSpam(SpamHelper.userConfigs);

?????//?第三步：執(zhí)行扣費(fèi)
?????handlePay(chargeTask);

?????//?其他步驟：點(diǎn)擊埋點(diǎn)等
?????...
??}
}

/**
?*?執(zhí)行反作弊子任務(wù)
?*/
public?void?executeUserSpam(List?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);
??}
}

通過(guò)上述代碼，大家能否發(fā)現(xiàn)死鎖是怎么發(fā)生的呢？根本原因在于：一次扣費(fèi)行為屬于父任務(wù)，同時(shí)它又包含了多次子任務(wù)：子任務(wù)用于并行執(zhí)行反作弊策略，而父任務(wù)和子任務(wù)使用的是同一個(gè)業(yè)務(wù)線程池。當(dāng)線程池中全部都是執(zhí)行中的父任務(wù)時(shí)，并且所有父任務(wù)都存在子任務(wù)未執(zhí)行完，這樣就會(huì)發(fā)生死鎖。下面通過(guò)1張圖再來(lái)直觀地看下死鎖的情況：

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

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

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

05?解決方案

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

06 問(wèn)題總結(jié)

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

推薦閱讀：

一個(gè)架構(gòu)師的緩存修煉之路

Redis主節(jié)點(diǎn)的Key已過(guò)期的處理

Redis 哨兵模式

歡迎關(guān)注微信公眾號(hào)：互聯(lián)網(wǎng)全棧架構(gòu)，收取更多有價(jià)值的信息。