線程池運(yùn)用不當(dāng)引發(fā)的一次線上事故解決記錄分析
引言
在高并發(fā)、異步化等場景,線程池的運(yùn)用可以說無處不在。線程池從本質(zhì)上來講,即通過空間換取時(shí)間,因?yàn)榫€程的創(chuàng)建和銷毀都是要消耗資源和時(shí)間的,對(duì)于大量使用線程的場景,使用池化管理可以延遲線程的銷毀,大大提高單個(gè)線程的復(fù)用能力,進(jìn)一步提升整體性能。
今天遇到了一個(gè)比較典型的線上問題,剛好和線程池有關(guān),另外涉及到死鎖、jstack命令的使用、JDK不同線程池的適合場景等知識(shí)點(diǎn),同時(shí)整個(gè)調(diào)查思路可以借鑒,特此記錄和分享一下。
業(yè)務(wù)背景描述
該線上問題發(fā)生在廣告系統(tǒng)的核心扣費(fèi)服務(wù),首先簡單交代下大致的業(yè)務(wù)流程,方便理解問題。
綠框部分即扣費(fèi)服務(wù)在廣告召回扣費(fèi)流程中所處的位置,簡單理解:當(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)等。
問題現(xiàn)象和業(yè)務(wù)影響
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ù)正常。
問題調(diào)查和事故解決過程
下面詳細(xì)說下整個(gè)事故的調(diào)查和分析過程。
第1步:收到線程池任務(wù)隊(duì)列的告警后,我們第一時(shí)間查看了扣費(fèi)服務(wù)各個(gè)維度的實(shí)時(shí)數(shù)據(jù):包括服務(wù)調(diào)用量、超時(shí)量、錯(cuò)誤日志、JVM監(jiān)控,均未發(fā)現(xiàn)異常。
第2步:然后進(jìn)一步排查了扣費(fèi)服務(wù)依賴的存儲(chǔ)資源(mysql、redis、mq),外部服務(wù),發(fā)現(xiàn)了事故期間存在大量的數(shù)據(jù)庫慢查詢。
上述慢查詢來自于事故期間一個(gè)剛上線的大數(shù)據(jù)抽取任務(wù),從扣費(fèi)服務(wù)的mysql數(shù)據(jù)庫中大批量并發(fā)抽取數(shù)據(jù)到hive表。因?yàn)榭圪M(fèi)流程也涉及到寫mysql,猜測這個(gè)時(shí)候mysql的所有讀寫性能都受到了影響,果然進(jìn)一步發(fā)現(xiàn)insert操作的耗時(shí)也遠(yuǎn)遠(yuǎn)大于正常時(shí)期。
第3步:我們猜測數(shù)據(jù)庫慢查詢影響了扣費(fèi)流程的性能,從而造成了任務(wù)隊(duì)列的積壓,所以決定立馬暫定大數(shù)據(jù)抽取任務(wù)。但是很奇怪:停止抽取任務(wù)后,數(shù)據(jù)庫的insert性能恢復(fù)到正常水平了,但是阻塞隊(duì)列大小仍然還在持續(xù)增大,告警并未消失。
第4步:考慮廣告收入還在持續(xù)大幅度下跌,進(jìn)一步分析代碼需要比較長的時(shí)間,所以決定立即重啟服務(wù)看看有沒有效果。為了保留事故現(xiàn)場,我們保留了一臺(tái)服務(wù)器未做重啟,只是把這臺(tái)機(jī)器從服務(wù)管理平臺(tái)摘掉了,這樣它不會(huì)接收到新的扣費(fèi)請(qǐng)求。
果然重啟服務(wù)的殺手锏很管用,各項(xiàng)業(yè)務(wù)指標(biāo)都恢復(fù)正常了,告警也沒有再出現(xiàn)。至此,整個(gè)線上故障得到解決,持續(xù)了大概30分鐘。
問題根本原因的分析過程
下面再詳細(xì)說下事故根本原因的分析過程。
第1步:第二天上班后,我們猜測那臺(tái)保留了事故現(xiàn)場的服務(wù)器,隊(duì)列中積壓的任務(wù)應(yīng)該都被線程池處理掉了,所以嘗試把這臺(tái)服務(wù)器再次掛載上去驗(yàn)證下我們的猜測,結(jié)果和預(yù)期完全相反,積壓的任務(wù)仍然都在,而且隨著新請(qǐng)求進(jìn)來,系統(tǒng)告警立刻再次出現(xiàn)了,所以又馬上把這臺(tái)服務(wù)器摘了下來。
第2步:線程池積壓的幾千個(gè)任務(wù),經(jīng)過1個(gè)晚上都沒被線程池處理掉,我們猜測應(yīng)該存在死鎖情況。所以打算通過jstack命令dump線程快照做下詳細(xì)分析。
#找到扣費(fèi)服務(wù)的進(jìn)程號(hào) $ jstack pid > /tmp/stack.txt # 通過進(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文檔的說明如下:
創(chuàng)建一個(gè)可重用固定線程數(shù)的線程池,以共享的無界隊(duì)列方式來運(yùn)行這些線程。如果在所有線程處于活躍狀態(tài)時(shí)提交新任務(wù),則在有可用線程之前,新任務(wù)將在隊(duì)列中等待。
關(guān)于newFixedThreadPool,核心包括兩點(diǎn):
1、最大線程數(shù) = 核心線程數(shù),當(dāng)所有核心線程都在處理任務(wù)時(shí),新進(jìn)來的任務(wù)會(huì)提交到任務(wù)隊(duì)列中等待;
2、使用了無界隊(duì)列:提交給線程池的任務(wù)隊(duì)列是不限制大小的,如果任務(wù)被阻塞或者處理變慢,那么顯然隊(duì)列會(huì)越來越大。
所以,進(jìn)一步結(jié)論是:核心線程全部死鎖,新進(jìn)的任務(wù)不對(duì)涌入無界隊(duì)列,導(dǎo)致任務(wù)隊(duì)列不斷增加。
第4步:到底是什么原因?qū)е碌乃梨i,我們?cè)俅位氐絡(luò)stack日志文件中提示的那行代碼做進(jìn)一步分析。下面是我簡化過后的示例代碼:
/** * 執(zhí)行扣費(fèi)任務(wù) */ public Result<Integer> 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<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ā)生的呢?根本原因在于:一次扣費(fèi)行為屬于父任務(wù),同時(shí)它又包含了多次子任務(wù):子任務(wù)用于并行執(zhí)行反作弊策略,而父任務(wù)和子任務(wù)使用的是同一個(gè)業(yè)務(wù)線程池。當(dāng)線程池中全部都是執(zhí)行中的父任務(wù)時(shí),并且所有父任務(wù)都存在子任務(wù)未執(zhí)行完,這樣就會(huì)發(fā)生死鎖。下面通過1張圖再來直觀地看下死鎖的情況:
假設(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沒執(zhí)行完,所以扣費(fèi)父任務(wù)1和2都不可能執(zhí)行完成,這樣就發(fā)生了死鎖,核心線程永遠(yuǎn)不可能釋放,從而造成任務(wù)隊(duì)列不斷增大,直到程序OOM crash。
死鎖原因清楚后,還有個(gè)疑問:上述代碼在線上運(yùn)行很長時(shí)間了,為什么現(xiàn)在才暴露出問題呢?另外跟數(shù)據(jù)庫慢查詢到底有沒有直接關(guān)聯(lián)呢?
暫時(shí)我們還沒有復(fù)現(xiàn)證實(shí),但是可以推斷出:上述代碼一定存在死鎖的概率,尤其在高并發(fā)或者任務(wù)處理變慢的情況下,概率會(huì)大大增加。數(shù)據(jù)庫慢查詢應(yīng)該就是導(dǎo)致此次事故出現(xiàn)的導(dǎo)火索。
解決方案
弄清楚根本原因后,最簡單的解決方案就是:增加一個(gè)新的業(yè)務(wù)線程池,用來隔離父子任務(wù),現(xiàn)有的線程池只用來處理扣費(fèi)任務(wù),新的線程池用來處理反作弊任務(wù)。這樣就可以徹底避免死鎖的情況了。
問題總結(jié)
回顧事故的解決過程以及扣費(fèi)的技術(shù)方案,存在以下幾點(diǎn)待繼續(xù)優(yōu)化:
- 使用固定線程數(shù)的線程池存在OOM風(fēng)險(xiǎn),在阿里巴巴Java開發(fā)手冊(cè)中也明確指出,而且用的詞是『不允許』使用Executors創(chuàng)建線程池。 而是通過ThreadPoolExecutor去創(chuàng)建,這樣讓寫的同學(xué)能更加明確線程池的運(yùn)行規(guī)則和核心參數(shù)設(shè)置,規(guī)避資源耗盡的風(fēng)險(xiǎn)。
- 廣告的扣費(fèi)場景是一個(gè)異步過程,通過線程池或者M(jìn)Q來實(shí)現(xiàn)異步化處理都是可選的方案。另外,極個(gè)別的點(diǎn)擊請(qǐng)求丟失不扣費(fèi)從業(yè)務(wù)上是允許的,但是大批量的請(qǐng)求丟棄不處理且沒有補(bǔ)償方案是不允許的。后續(xù)采用有界隊(duì)列后,拒絕策略可以考慮發(fā)送MQ做重試處理。
以上就是線程池運(yùn)用不當(dāng)引發(fā)的一次線上事故解決記錄分析的詳細(xì)內(nèi)容,更多關(guān)于線程池線上事故的資料請(qǐng)關(guān)注腳本之家其它相關(guān)文章!
相關(guān)文章
使用log4j2打印mybatis的sql執(zhí)行日志方式
這篇文章主要介紹了使用log4j2打印mybatis的sql執(zhí)行日志方式,具有很好的參考價(jià)值,希望對(duì)大家有所幫助,如有錯(cuò)誤或未考慮完全的地方,望不吝賜教2023-09-09java8 實(shí)現(xiàn)提取集合對(duì)象的每個(gè)屬性
這篇文章主要介紹了java8 實(shí)現(xiàn)提取集合對(duì)象的每個(gè)屬性方式,具有很好的參考價(jià)值,希望對(duì)大家有所幫助。一起跟隨小編過來看看吧2021-02-02SpringCloud容器化服務(wù)發(fā)現(xiàn)及注冊(cè)實(shí)現(xiàn)方法解析
這篇文章主要介紹了SpringCloud容器化服務(wù)發(fā)現(xiàn)及注冊(cè)實(shí)現(xiàn)方法解析,文中通過示例代碼介紹的非常詳細(xì),對(duì)大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值,需要的朋友可以參考下2020-08-08springboot + jpa實(shí)現(xiàn)刪除數(shù)據(jù)的操作代碼
這篇文章主要介紹了springboot + jpa實(shí)現(xiàn)刪除數(shù)據(jù)的操作代碼,本文通過實(shí)例代碼給大家介紹的非常詳細(xì),對(duì)大家的學(xué)習(xí)或工作具有一定的參考借鑒價(jià)值,需要的朋友參考下吧2024-05-05SpringBoot實(shí)戰(zhàn)項(xiàng)目之谷歌瀏覽器全屏效果實(shí)現(xiàn)
這篇文章主要介紹了通過 Java SpringBoot來實(shí)現(xiàn)谷歌瀏覽器的全屏效果,希望頁面展示時(shí)可以實(shí)現(xiàn)全屏效果以提高用戶體驗(yàn)。感興趣的小伙伴跟著小編往下看吧2021-09-09堆排序?qū)嵗?Java數(shù)組實(shí)現(xiàn))
下面小編就為大家分享一篇使用Java數(shù)組實(shí)現(xiàn)堆排序的實(shí)例,具有很好的參考價(jià)值,希望對(duì)大家有所幫助。一起跟隨小編過來看看吧2017-12-12ExpressionUtil工具類的應(yīng)用實(shí)例
這篇文章主要給大家介紹了關(guān)于ExpressionUtil工具類的應(yīng)用實(shí)例,常用的工具類有很多,這是其中一個(gè),了解基本的API可以幫助我們更好的開發(fā),文中通過代碼介紹的非常詳細(xì),需要的朋友可以參考下2024-04-04mybatis新增到數(shù)據(jù)庫后返回當(dāng)前ID問題
這篇文章主要介紹了mybatis新增到數(shù)據(jù)庫后返回當(dāng)前ID問題,具有很好的參考價(jià)值,希望對(duì)大家有所幫助,如有錯(cuò)誤或未考慮完全的地方,望不吝賜教2024-08-08半小時(shí)實(shí)現(xiàn)Java手?jǐn)]網(wǎng)絡(luò)爬蟲框架(附完整源碼)
最近在做一個(gè)搜索相關(guān)的項(xiàng)目,需要爬取網(wǎng)絡(luò)上的一些鏈接存儲(chǔ)到索引庫中,自己寫了一個(gè)簡單的網(wǎng)絡(luò)爬蟲,感興趣的可以了解一下2021-06-06