你好呀,我是歪歪。
最近在使用執行緒池的時候踩了一個坑,給你分享一下。
在實際業務場景下,涉及到業務程式碼和不同的微服務,導致問題有點難以定位,但是最終分析出原因之後,發現可以用一個很簡單的例子來演示。
所以歪師傅這次先用 Demo 說問題,再說場景,方便吸收。
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714195450.png)
Demo
老規矩,還是先上個程式碼:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240713223746.png)
這個程式碼的邏輯非常簡單,首先我們搞了一個執行緒池,然後起一個 for 迴圈往執行緒池裡面仍了 5 個任務,這是核心邏輯。
對於這幾個任務,我們的這個自定義執行緒池處理起來,不能說得心應手吧,至少也是手拿把掐。
其他的 StopWatch 是為了統計執行時間用的。 至於 CountDownLatch,你可以理解為在業務流程中,需要這五個任務都執行完成之後才能往下走,所以我搞了一個 CountDownLatch。
這個程式碼執行起來是沒有任何問題的,我們在日誌中搜尋“執行完成”,也能搜到 5 個,這個結果也能證明程式是正常結束的:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240713224028.png)
同時,可以看到執行時間是 4s。
示意圖大概是這樣的:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714110829.png)
然後歪師傅看著這個程式碼,發現了一個可以最佳化的地方:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240713224546.png)
這個地方從資料庫撈出來的資料,它們之間是沒有依賴關係的,也就是說它們之間也是可以並行執行的。
所以歪師傅把程式碼改成了這樣:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240713224748.png)
在非同步執行緒裡面去處理這部分從資料庫中撈出來的資料,並行處理加快響應速度。
對應到圖片,大概就是這個意思:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714111447.png)
把程式執行起來之後,日誌變成了這樣:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240713224916.png)
我們搜尋“執行完成”,也能搜到 5 個對應輸出。
而且我們就拿“任務2”來說:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240713225119.png)
當前執行緒pool-1-thread-3,---【任務2】開始執行---
當前執行緒pool-1-thread-3,---【任務2】執行完成---
當前執行緒pool-1-thread-1,【任務2】開始處理資料=1
當前執行緒pool-1-thread-2,【任務2】開始處理資料=2
從日誌輸出來看,任務 2 需要處理的兩個資料,確實是在不同的非同步執行緒中處理資料,也實現了我的需求。
但是,程式執行直接就是到了 9.9ms:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240713225240.png)
這個最佳化這麼牛逼的嗎?
從 4s 到了 9.9ms?
稍加分析,你會發現這裡面是有問題的。
那麼問題就來了,到底是啥問題呢?
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714195751.png)
你也分析分析大概是啥問題,別老是想著直接找答案啊。
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714195804.png)
問題就是由於轉非同步了,所以 for 迴圈裡面的任務中的 countDownLatch 很快就減到 0 了。
於是 await 繼續執行,所以很快就輸出了程式執行時間。
然而實際上子任務還在繼續執行,程式並沒有真正完成。
9.9ms 只是任務提交到執行緒池的時間,每個任務的資料處理時間還沒算呢:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714111713.png)
從日誌輸出上也可以看出,在輸出了 StopWatch 的日誌後,各個任務還在處理資料。
這樣時間就顯得不夠真實。
那麼我們應該怎麼辦呢?
很簡單嘛,需要子任務真正執行完成後,父任務的 countDownLatch 才能進行 countDown 的動作。
具體實現上就是給子任務再加一個 countDownLatch 柵欄:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240713225841.png)
我們希望的執行結果應該是這樣的:
當前執行緒pool-1-thread-3,---【任務2】開始執行---
當前執行緒pool-1-thread-1,【任務2】開始處理資料=1
當前執行緒pool-1-thread-2,【任務2】開始處理資料=2
當前執行緒pool-1-thread-3,---【任務2】執行完成---
即子任務全部完成之後,父任務才能算執行完成,這樣統計出來的時間才是準確的。
思路清晰,非常完美,再次執行,觀察日誌我們會發現:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240713225926.png)
呃,怎麼回事,日誌怎麼不輸出了?
是的,就是不輸出了。
不輸出了,就是踩到這個坑了。
不論你重啟多少次,都是這樣:日誌不輸出了,程式就像是卡著了一樣。
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714195910.png)
坑在哪兒
上面這個 Demo 已經是我基於遇到的生產問題,極力簡化後的版本了。
現在,這個坑也已經呈現在你眼前了。
我們一起來分析一波。
首先,我問你:真的線上上遇到這種程式“假死”的問題,你會怎麼辦?
早幾年,歪師傅的習慣是抱著程式碼慢慢啃,試圖從程式碼中找到端倪。
這樣確實是可以,但是通常來說效率不高。
現在我的習慣是直接把現場 dump 下來,分析現場。
比如在這個場景下,我們直觀上的感受是“卡住了”,那就 dump 一把執行緒,管它有棗沒棗,打一杆子再說:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714125006.png)
透過 Dump 檔案,可以發現執行緒池的執行緒都在 MainTest 的第 30 行上 parking ,處於等待狀態:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714125116.png)
那麼第 30 行是啥玩意?
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714125312.png)
這行程式碼在幹啥?
countDownLatchSub.await();
是父任務在等待子任務執行結束,執行 finally 程式碼,把 countDownLatchSub 的計數 countDown 到 0,才會繼續執行:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714125552.png)
所以現在的現象就是子任務的 countDownLatchSub 把父任務的攔住了。
換句話說就是父任務被攔住是因為子任務的 finally 程式碼中的 countDownLatchSub.countDown() 方法沒有被執行。
好,那麼最關鍵的問題就來了:為什麼沒有執行?
你先別往下看,閉上眼睛在你的小腦瓜子裡面推演一下,琢磨一下:finally 為什麼沒有執行?
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714200102.png)
或者再換個更加接近真實的問題:子任務為什麼沒有執行?
這個點,非常簡單,可以說一點就破。
琢磨明白了,這個坑的原理摸摸清楚了。
...
...
...
琢磨明白了嗎?你就刷刷往下看?
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714200141.png)
沒明白我再給你一個資訊:需要結合執行緒池的引數和執行原理來分析。
什麼?
你說執行緒池的執行原理你不清楚?
請你取關好嗎,你個假粉絲。
...
...
...
好,不管你“恍然大悟”了沒有,歪師傅給你講一下。
讓你知道“一點就破”這四個是怎麼回事兒。
首先,我們把目光聚焦線上程池這裡:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714130538.png)
這個執行緒池核心執行緒數是 3,但是我們要提交 5 個任務到執行緒池去。
父任務哐哐哐,就把核心執行緒數佔滿了。
接下來子任務也要往這個執行緒池提交任務怎麼辦?
當然是進佇列等著了。
一進佇列,就完犢子。
到這裡,我覺得你應該能想明白問題了。
應該給到我一個恍然大悟的表情,並配上“哦哦哦~”這樣的內心 OS。
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714200255.png)
你想想,父任務這個時候幹啥?
是不是等在 countDownLatchSub.await() 這裡。
而 countDownLatchSub.await() 什麼時候能繼續執行?
是不是要所有子任務都執行 finally 後?
那麼子任務現在在幹啥?
是不是都線上程池裡面的佇列等著被執行呢?
那執行緒池佇列裡面的任務什麼時候才執行?
是不是等著有空閒執行緒的時候?
那現在有沒有空閒執行緒?
沒有,所有的執行緒都去執行父任務去了。
那你想想,父任務這個時候幹啥?
是不是等在 countDownLatchSub.await() 這裡。
...
父任務在等子任務執行。
子任務在等執行緒池排程。
執行緒池在等父任務釋放執行緒。
閉環了,相互等待了,家人們。
這,就是坑。
現在把坑的原理摸清楚了,我在給你說一下真實的線上場景踩到這個坑是怎麼樣的呢?
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714134413.png)
上游發起請求到微服務 A 的介面 1,該介面需要呼叫微服務 B 的介面 2。
但是微服務 B 的介面 2,需要從微服務 A 介面 3 獲取資料。
然而在微服務 A 內部,全域性使用的是同一個自定義執行緒池。
更巧的是介面 1 和介面 3 內部都使用了這個自定義執行緒池做非同步並行處理,想著是加快響應速度。
整個情況就變成了這樣:
介面 1 收到請求之後,把請求轉到自定義執行緒池中,然後等介面 2 返回。 介面 2 呼叫介面 3,並等待返回。 介面 3 裡面把請求轉到了自定義執行緒池中,被放入了佇列。 執行緒池的執行緒都被介面 1 給佔住了,沒有資源去執行佇列裡面的介面 3 任務。 相互等待,一直僵持。
我們的 Demo 還是能比較清晰的看到父子任務之間的關係。
但是在這個微服務的場景下,在無形之間,就形成了不易察覺的父子任務關係。
所以就踩到了這個坑。
怎麼避免
找到了坑的原因,解決方案就隨之而出了。
父子任務不要共用一個執行緒池,給子任務也搞一個自定義執行緒池就可以了:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714135559.png)
執行起來看看日誌:
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714135644.png)
首先整體執行時間只需要 2s 了,達到了我想要的效果。
另外,我們觀察一個具體的任務:
當前執行緒pool-1-thread-3,---【任務2】開始執行---
當前執行緒pool-2-thread-1,【任務2】開始處理資料=1
當前執行緒pool-2-thread-4,【任務2】開始處理資料=2
當前執行緒pool-1-thread-3,---【任務2】執行完成---
日誌輸出符合我們前面分析的,所有子任務執行完成後,父任務才列印執行完成,且子任務在不同的執行緒中執行。
而使用不同的執行緒池,換一個高大上的說法就叫做:執行緒池隔離。
而且在一個專案中,公用一個執行緒池,也是一個埋坑的邏輯。
至少給你覺得關鍵的邏輯,單獨分配一個執行緒池吧。
避免出現執行緒池的執行緒都在執行非核心邏輯了,反而重要的任務在佇列裡面排隊去了。
這就有點不合理了。
最後,一句話總結這個問題:
如果執行緒池的任務之間存在父子關係,那麼請不要使用同一個執行緒池。如果使用了同一個執行緒池,可能會因為子任務進了佇列,導致父任務一直等待,出現假死現象。
想起從前
寫這篇文章的時候,我想起了之前寫過的這篇文章:
《要我說,多執行緒事務它必須就是個偽命題!》
這篇文章是 2020 年寫的,其中就是使用了父子任務+CountDownLatch 的模式,來實現所謂的“多執行緒事務”。
在文中我還特別強調了:
不能讓任何一個任務進入佇列裡面。一旦進入佇列,程式立馬就涼。
![](https://why-image-1300252878.cos.ap-chengdu.myqcloud.com/img/20220716/20240714142021.png)
這句話背後的原理和本文討論的其實是一樣的。
好吧,原來多年前我就知道這個坑了。
只是多年後再次遇到這個坑的時候,我已經不再是那個二十多歲,喜歡深夜懟文的我了。
那一年的荒腔走板,圖片中的沙發,當年只是想擺拍一下,當個道具,後來覺得坐著還挺舒服,我們就買回家了。
當年為了裝修房子煞費苦心,現在也已經入住了 3 年有餘的時間了。
當我回望幾年前寫的文章,在當時技術部分是最重要的,但是回望的時候這部分已經不重要了。
它已經由一篇技術文章變成了一個生活的錨點,其中的蛛絲馬跡,能讓我從腦海深處想起之前生活中一些不痛不癢的印跡。
一艘輪船,在靠岸之後要下錨,那個點位就是錨點。
錨點可以讓船穩定在海岸邊,不被風浪或者潮汐帶走。
生活也需要錨點,我似乎找到了我的錨點。