刺激,線程池的一個BUG直接把CPU幹到100%了。

語言: CN / TW / HK

你好呀,我是歪歪。

給大家分享一個關於 ScheduledExecutorService 線程池的 BUG 啊,這個 BUG 能直接把 CPU 給飈到 100%,希望大家永遠踩不到。

但是,u1s1,一般來説也很難踩到。

到底咋回事呢,讓我給你細細嗦嗦。

Demo

老規矩,按照慣例,先搞個 Demo 出來玩玩:

項目裏面使用到了 ScheduledThreadPoolExecutor 線程池,該線程池對應的核心線程數放在配置文件裏面,通過 @Value 註解來讀取配置文件。

然後通過接口觸發這個線程池裏面的任務。

具體來説就是在上面的示例代碼中,在調用 testScheduledPool 接口之後,程序會在 60 秒之後輸出“執行業務邏輯”。

這個代碼的邏輯還是非常簡單清晰的,但是上面的代碼有一個問題,不知道你看出來沒有?

沒看出來也沒關係,我這裏都是鼓勵式教學的,不打擊同學的積極性。

所以,彆着急,我先給你跑起來,你瞅一眼立馬就能看出問題是啥:

為什麼 coreSize 是 0 呢,我們配置文件裏面明明寫的是 2 啊?

因為 setCoreSize 方法是 static 的,導致 @Value 註解失效。

如果去掉 static 那麼就能正確讀取到配置文件中的配置:

雖然這裏面也大有學問,但是這並不是本文的重點,這只是一個引子,

為的是引出為什麼會在項目裏面出現下面這種 coreSize 等於 0 的奇怪的代碼:

ScheduledExecutorService executor = Executors.newScheduledThreadPool(0);

如果我直接給出上面的代碼,一點有人説只有小(大)可(傻)愛(逼)才會這樣寫。

但是鋪墊一個背景之後,就容易接受的多了。

你永遠可以相信我的行文結構,老司開車穩得很,你放心。

好,經過前面的鋪墊,其實我們的 Demo 能直接簡化到這個樣子:

public static void main(String[] args){     ScheduledExecutorService e = Executors.newScheduledThreadPool(0);     e.schedule(() -> {         System.out.println("業務邏輯");     }, 60, TimeUnit.SECONDS);     e.shutdown(); }

這個代碼是可以正常運行的,你粘過去直接就能跑,60 秒後是會正常輸出的。

如果你覺得 60 秒太長了,那麼你可以改成 3 秒運行一下,看看程序是不是正常運行並結束了。

但是就這個看起來問題不大的代碼,會導致 CPU 飈到 100% 去。

真的,兒豁嘛。

咋回事呢

到底咋回事呢?

這個其實就是 JDK 的 BUG 導致的,我帶你瞅瞅:

https://bugs.openjdk.org/browse/JDK-8065320

首先,你看 Fix Version 那個地方是 9,也就是説明這個 BUG 是在 JDK 9 裏面修復了。JDK 8 裏面是可以復現的。

其次,這個標題其實就包含了非常多的信息了,它説對於 ScheduledExecutorService 來説 getTask 方法裏面存在頻繁的循環。

那麼問題就來了:頻繁的循環,比如 for(;;) ,while(true) 這樣的代碼,長時間從循環裏面走不出來,會導致什麼現象?

那不就是導致 CPU 飆高嗎。

注意,這裏我説的是“長時間從循環裏面走不出來”,而不是死循環,這兩者之間的差異還是很大的。

我代碼裏面的示例就是使用的提出 BUG 的哥們給出的實例:

他説,在這個示例下,如果你在一個只有單核的服務器上跑,然後使用 TOP 命令,會看到持續 60 秒的 CPU 使用率為 100%。

為什麼呢?

答案就藏在前面提到的 getTask 方法中:

java.util.concurrent.ThreadPoolExecutor#getTask

這個方法裏面果然是有一個類似於無線循環的代碼,但是它為什麼不停的執行呢?

現在趕緊想一想線程池的基本運行原理。當沒有任務處理的時候,核心線程在幹啥?

是不是就阻塞在這個地方,等着任務過來進行處理的,這個能理解吧:

那我再問你一個問題,這行代碼的作用是幹啥:

workQueue.poll(keepAliveTime, TimeUnit.NANOSECONDS)

是不是在指定時間內如果沒有從隊列裏面拉取到任務,則拋出 InterruptedException。

那麼它什麼時候會被觸發呢?

在 timed 參數為 true 的時候。

timed 參數什麼時候會為 true 呢?

當 allowCoreThreadTimeOut 為 true 或者當前工作的線程大於核心線程數的時候。

而 allowCoreThreadTimeOut 默認為 false:

那麼也就是在這個案例下滿足了當前工作的線程大於核心線程數這個條件:

wc > corePoolSize

通過 Debug 知道,wc 是 1,corePoolSize 為 0:

所以 timed 變成了 true。

好,這裏要注意了,朋友。

經過前面的分析,我們已經知道了在當前的案例下,會觸發 for(;;)這個邏輯:

workQueue.poll(keepAliveTime, TimeUnit.NANOSECONDS)

那麼這個 keepAliveTime 到底是多少呢?

來,大聲的喊出這個數字:0,這是一個意想不到的、詭計多端的 0。

所以,這個地方中的 r 每次都會返回一個 null,然後再次開啟循環。

對於正常的線程池來説,觸發了這個邏輯,代表沒有任務要執行了,可以把對應線程進行回收了。

回收,對應的就是這部分代碼會返回一個 null:

然後在外面 runWorker 方法中的,由於 getTask 返回了 null,從而執行了 finally 代碼裏面的邏輯,也就是從當前線程池移除線程的邏輯:

但是,朋友,我要説但是了。

在我們的案例下,你看 if 判斷的條件:

這裏面的 wc > 1 || workQueue.isEmpty()) 是 false

所以這個 if 條件不成立,那麼它又走到了 poll 這裏:

workQueue.poll(keepAliveTime, TimeUnit.NANOSECONDS)

由於這裏的 keepAliveTime 是 0,所以馬不停蹄的的開啟下一輪循環。

那麼這個循環什麼時候結束呢?

就是在從隊列裏面獲取到任務的時候。

那麼隊列裏面什麼時候才會有任務呢?

在我們的案例裏面,是 60 秒之後。

所以,在這 60 秒內,這部分代碼相當於是一個“死循環”,導致 CPU 持續飆高到 100%。

這就是 BUG,這就是根本原因。

但是看到這裏是不是覺得還差點意思?

我説 100% 就 100% 嗎?

得拿出石錘來才行啊。

所以,為了拿出實錘,眼見為實,我把核心流程拿出來,然後稍微改動一點點代碼:

public static void main(String[] args) {     ArrayBlockingQueue<Runnable> workQueue =             new ArrayBlockingQueue<>(100);     //綁定到 5 號 CPU 上執行     try (AffinityLock affinityLock = AffinityLock.acquireLock(5)) {         for (; ; ) {             try {                 Runnable r = workQueue.poll(0, TimeUnit.NANOSECONDS);                 if (r != null)                     break;             } catch (InterruptedException retry) {             }         }     } }

AffinityLock 這個類在之前的文章裏面出現過:《面試官:Java如何綁定線程到指定CPU上執行?》

就是把線程綁定到指定 CPU 上去執行,減少 CPU 抖動帶來的損耗, 具體我就不介紹了,有興趣去看我之前的文章。

把這個程序跑起來之後,打開資源監視器,你可以看到 5 號 CPU 立馬就飈到 100% 了,停止運行之後,立馬就下來了:

這就是眼見為實,這真是 JDK 的 BUG,我真沒騙你。

怎麼修復

在 JDK 9 裏面是怎麼修復這個 BUG 的呢?

在前面提到的 BUG 的鏈接中,有這樣的一個鏈接,裏面就是 JDK 9 版本里面針對上述的 BUG 進行的修復:

http://hg.openjdk.java.net/jdk9/jdk9/jdk/rev/6dd59c01f011

點開這個鏈接之後,你可以找到這個地方:

首先對比一下標號為 ① 和 ② 的地方,默認值從 0 納秒修改為了 DEFAULT_KEEPALIVE_MILLIS 毫秒。

而 DEFAULT_KEEPALIVE_MILLIS 的值為在標號為 ③ 的地方, 10L。

也就是默認從 0 納秒修改為了 10 毫秒。而這一處的改動,就是為了防止出現 coreSize 為 0 的情況。

我們重點關注一下 DEFAULT_KEEPALIVE_MILLIS 上面的那一坨註釋。

我給你翻譯一下,大概是這樣的:

這個值呢一般來説是用不上的,因為在 ScheduledThreadPoolExecutor 線程池裏面的線程都是核心線程。

但是,如果用户創建的線程池的時候,不聽勸,頭鐵,要把 corePoolSize 設置為 0 會發生什麼呢?

因為 keepAlive 參數設置的為 0,那麼就會導致線程在 getTask 方法裏面非常頻繁的循環,從而導致 CPU 飆高。

那怎麼辦呢?

很簡單,設置一個小而非零的值就可以,而這個小是相對於 JVM 的運行時間而言的。

所以這個 10 毫秒就是這樣來的。

再來一個

在研究前面提到的編號為 8065320 的 BUG 的時候,我還發現一個意外收穫,編號為 8051859 的 BUG,它們是挨着的,排排坐。

有點意思,也很簡單,所以分享一波:

https://bugs.openjdk.org/browse/JDK-8051859

這個 BUG 又説的是啥事兒呢:

看截圖這個 BUG 也是在 JDK 9 版本之後修復的。

這個 BUG 的標題説的是 ScheduledExecutorService 線程池的 scheduleWithFixedDelay 方法,遇到大延遲時會執行失敗。

具體啥意思呢?

我們還是先拿着 Demo 説:

``` public class ScheduledTaskBug {     static public void main(String[] args) throws InterruptedException {         ScheduledExecutorService executor = Executors.newSingleThreadScheduledExecutor();         //第一個任務         executor.scheduleWithFixedDelay(new Runnable() {             @Override             public void run() {                 System.out.println("running scheduled task with delay: " + new Date());             }         }, 0, Long.MAX_VALUE, TimeUnit.MICROSECONDS);

//第二個任務         executor.submit(new Runnable() {             @Override             public void run() {                 System.out.println("running immediate task: " + new Date());             }         });         Thread.sleep(5000);         executor.shutdownNow();     } } ```

你把這個代碼粘過去之後,發現輸出是這樣的:

只有第一個任務執行了,第二個任務沒有輸出結果。

正常來説,第一個任務的延遲時間,也就是 initialDelay 參數是 0,所以第一次執行的時候是立即執行:

比如我改成這樣,把週期執行的時間單位,由微秒修改為納秒,就正常了:

神奇不神奇?你説這不是 BUG 這是啥?

提出 BUG 的這個哥們在描述裏面介紹了 BUG 的原因,主要是提到了一個字段和兩個方法:

一個字段是指 period,兩個方法分別是 TimeUnit.toNanos(-delay) 和 ScheduledFutureTask.setNextRunTime()。

首先,在 ScheduledThreadPoolExecutor 裏面 period 字段有三個取值範圍:

  • 正數,代表的是按照固定速率執行(scheduleAtFixedRate)。
  • 負數,代表的是按照固定延時執行(scheduleWithFixedDelay)。
  • 0,代表的是非重複性任務。

比如我們的示例代碼中調用的是 scheduleWithFixedDelay 方法,它裏面就會在調用 TimeUnit.toNanos 方法的時候取反,讓 period 字段為負數:

好,此時我們開始 Debug 我們的 Demo,先來一個正常的。

比如我們來一個每 30ms 執行一次的週期任務,請仔細看:

在執行 TimeUnit.toNanos(-delay) 這一行代碼的時候,把 30 微秒轉化為了 -30000 納秒,也就是把 period 設置為 -30000。

然後來到 setNextRunTime 方法的時候,計算任務下一次觸發時間的時候,又把 period 轉為正數,沒有任何毛病:

但是,當我們把 30 修改為 Long.MAX_VALUE 的時候,有意思的事情就出現了:

delay=9223372036854775807
-delay=-9223372036854775807
unit.toNanos(-delay)=-9223372036854775808

直接給幹溢出了,變成了 Long.MIN_VALUE:

當來到 setNextRunTime 方法的時候,你會發現由於我們的 p 已經是 Long.MIN_VALUE 了。

那麼 -p 是多少呢?

給你跑一下:

Long.MIN_VALUE 的絕對值,還是 Long.MIN_VALUE。一個神奇的小知識點送給你,不客氣。

所以 -p 還是 Long.MIN_VALUE:

我們來算一下啊,一秒等於 10 億納秒:

那麼下一次觸發時間就變成了這樣:

292 年之前。

這就是在 BUG 描述中提到的:

This results in triggerTime returning a time in the distant past.

the distant past,就是 long long ago,就是 292 年之前。就是 1731 年,雍正九年,那個時候的皇帝還是九子奪嫡中一頓亂殺,衝出重圍的胤禛大佬。

確實是很久很久以前了。

那麼這個 BUG 怎麼修復呢?

其實很簡單:

把 unit.toNanos(-delay) 修改為 -unit.toNanos(delay),搞定。

我給你盤一下:

這樣就不會溢出,時間就變成了 292 年之後。

那麼問題就來了,誰特麼會設置一個每 292 年執行一次的 Java 定時任務呢?

好,你看到這裏了,本文就算結束了,我來問你一個問題:你知道了這兩個 BUG 之後,對你來説有什麼收穫嗎?

沒有,是的,除了浪費了幾分鐘時間外,沒有任何收穫。

那麼恭喜你,又在我這裏學到了兩個沒有卵用的知識點。

彙總

這個小節為什麼叫做彙總呢?

因為我發現這裏出現的一串 BUG,除了本文提到的 2 個外,還有 3 個我都寫過了,所以在這裏匯個總,充點字數,湊個篇幅:

8054446: Repeated offer and remove on ConcurrentLinkedQueue lead to an OutOfMemoryError

《我的程序跑了60多小時,就是為了讓你看一眼JDK的BUG導致的內存泄漏。》

這篇文章就是從 ConcurrentLinkedQueue 隊列的一個 BUG 講起。jetty 框架裏面的線程池用到了這個隊列,導致了內存泄漏。

同時通過 jconsole、VisualVM、jmc 這三個可視化監控工具,讓你看見“內存泄漏”的發生。

8062841: ConcurrentHashMap.computeIfAbsent stuck in an endless loop

《震驚!ConcurrentHashMap裏面也有死循環,作者留下的“彩蛋”瞭解一下?》

這個 BUG 在 Dubbo 和 Seata 裏面都有提到過,也被 Seata 官方的一篇博客中被引用過:

https://seata.io/zh-cn/blog/seata-dsproxy-deadlock.html

8073704: FutureTask.isDone returns true when task has not yet completed

《Doug Lea在J.U.C包裏面寫的BUG又被網友發現了。》

這個 BUG 也是在 JDK 9 版本里面修復的,邏輯彎彎繞繞的,但是理解之後,對於 FutureTask 狀態流轉就能有一個比較深刻的認知了。有興趣可以看看。