刺激,線程池的一個BUG直接把CPU干到100%了。
你好呀,我是歪歪。
給大家分享一個關(guān)于 ScheduledExecutorService 線程池的 BUG 啊,這個 BUG 能直接把 CPU 給飚到 100%,希望大家永遠(yuǎn)踩不到。
但是,u1s1,一般來說也很難踩到。
到底咋回事呢,讓我給你細(xì)細(xì)嗦嗦。
Demo
老規(guī)矩,按照慣例,先搞個 Demo 出來玩玩:
項目里面使用到了 ScheduledThreadPoolExecutor 線程池,該線程池對應(yīng)的核心線程數(shù)放在配置文件里面,通過 @Value 注解來讀取配置文件。
然后通過接口觸發(fā)這個線程池里面的任務(wù)。
具體來說就是在上面的示例代碼中,在調(diào)用 testScheduledPool 接口之后,程序會在 60 秒之后輸出“執(zhí)行業(yè)務(wù)邏輯”。
這個代碼的邏輯還是非常簡單清晰的,但是上面的代碼有一個問題,不知道你看出來沒有?
沒看出來也沒關(guān)系,我這里都是鼓勵式教學(xué)的,不打擊同學(xué)的積極性。
所以,別著急,我先給你跑起來,你瞅一眼立馬就能看出問題是啥:
為什么 coreSize 是 0 呢,我們配置文件里面明明寫的是 2 ?。?/p>
因為 setCoreSize 方法是 static 的,導(dǎo)致 @Value 注解失效。
如果去掉 static 那么就能正確讀取到配置文件中的配置:
雖然這里面也大有學(xué)問,但是這并不是本文的重點,這只是一個引子,
為的是引出為什么會在項目里面出現(xiàn)下面這種 coreSize 等于 0 的奇怪的代碼:
ScheduledExecutorService executor = Executors.newScheduledThreadPool(0);
如果我直接給出上面的代碼,一點有人說只有小(大)可(傻)愛(逼)才會這樣寫。
但是鋪墊一個背景之后,就容易接受的多了。
你永遠(yuǎn)可以相信我的行文結(jié)構(gòu),老司開車穩(wěn)得很,你放心。
好,經(jīng)過前面的鋪墊,其實我們的 Demo 能直接簡化到這個樣子:
這個代碼是可以正常運行的,你粘過去直接就能跑,60 秒后是會正常輸出的。
如果你覺得 60 秒太長了,那么你可以改成 3 秒運行一下,看看程序是不是正常運行并結(jié)束了。
但是就這個看起來問題不大的代碼,會導(dǎo)致 CPU 飚到 100% 去。
真的,兒豁嘛。
咋回事呢
到底咋回事呢?
這個其實就是 JDK 的 BUG 導(dǎo)致的,我?guī)愠虺颍?/p>
https://bugs.openjdk.org/browse/JDK-8065320
首先,你看 Fix Version 那個地方是 9,也就是說明這個 BUG 是在 JDK 9 里面修復(fù)了。JDK 8 里面是可以復(fù)現(xiàn)的。
其次,這個標(biāo)題其實就包含了非常多的信息了,它說對于 ScheduledExecutorService 來說 getTask 方法里面存在頻繁的循環(huán)。
那么問題就來了:頻繁的循環(huán),比如 for(;;) ,while(true) 這樣的代碼,長時間從循環(huán)里面走不出來,會導(dǎo)致什么現(xiàn)象?
那不就是導(dǎo)致 CPU 飆高嗎。
注意,這里我說的是“長時間從循環(huán)里面走不出來”,而不是死循環(huán),這兩者之間的差異還是很大的。
我代碼里面的示例就是使用的提出 BUG 的哥們給出的實例:
他說,在這個示例下,如果你在一個只有單核的服務(wù)器上跑,然后使用 TOP 命令,會看到持續(xù) 60 秒的 CPU 使用率為 100%。
為什么呢?
答案就藏在前面提到的 getTask 方法中:
java.util.concurrent.ThreadPoolExecutor#getTask
這個方法里面果然是有一個類似于無線循環(huán)的代碼,但是它為什么不停的執(zhí)行呢?
現(xiàn)在趕緊想一想線程池的基本運行原理。當(dāng)沒有任務(wù)處理的時候,核心線程在干啥?
是不是就阻塞在這個地方,等著任務(wù)過來進行處理的,這個能理解吧:
那我再問你一個問題,這行代碼的作用是干啥:
workQueue.poll(keepAliveTime, TimeUnit.NANOSECONDS)
是不是在指定時間內(nèi)如果沒有從隊列里面拉取到任務(wù),則拋出 InterruptedException。
那么它什么時候會被觸發(fā)呢?
在 timed 參數(shù)為 true 的時候。
timed 參數(shù)什么時候會為 true 呢?
當(dāng) allowCoreThreadTimeOut 為 true 或者當(dāng)前工作的線程大于核心線程數(shù)的時候。
而 allowCoreThreadTimeOut 默認(rèn)為 false:
那么也就是在這個案例下滿足了當(dāng)前工作的線程大于核心線程數(shù)這個條件:
wc > corePoolSize
通過 Debug 知道,wc 是 1,corePoolSize 為 0:
所以 timed 變成了 true。
好,這里要注意了,朋友。
經(jīng)過前面的分析,我們已經(jīng)知道了在當(dāng)前的案例下,會觸發(fā) for(;;)這個邏輯:
workQueue.poll(keepAliveTime, TimeUnit.NANOSECONDS)
那么這個 keepAliveTime 到底是多少呢?
來,大聲的喊出這個數(shù)字:0,這是一個意想不到的、詭計多端的 0。
所以,這個地方每次都會拋出 InterruptedException(有誤,見評論區(qū)),再次開啟循環(huán)。
對于正常的線程池來說,觸發(fā)了這個邏輯,代表沒有任務(wù)要執(zhí)行了,可以把對應(yīng)線程進行回收了。
回收,對應(yīng)的就是這部分代碼會返回一個 null:
然后在外面 runWorker 方法中的,由于 getTask 返回了 null,從而執(zhí)行了 finally 代碼里面的邏輯,也就是從當(dāng)前線程池移除線程的邏輯:
但是,朋友,我要說但是了。
在我們的案例下,你看 if 判斷的條件:
wc 參數(shù)前面我們知道了,值為 1。
那么 maximumPoolSize 是多少呢?
所以這個 if 條件不可能成立(描述有誤,見評論區(qū)),那么它又走到了 poll 這里:
workQueue.poll(keepAliveTime, TimeUnit.NANOSECONDS)
由于這里的 keepAliveTime 是 0,所以馬不停蹄的的開啟下一輪循環(huán)。
那么這個循環(huán)什么時候結(jié)束呢?
就是在從隊列里面獲取到任務(wù)的時候。
那么隊列里面什么時候才會有任務(wù)呢?
在我們的案例里面,是 60 秒之后。
所以,在這 60 秒內(nèi),這部分代碼相當(dāng)于是一個“死循環(huán)”,導(dǎo)致 CPU 持續(xù)飆高到 100%。
這就是 BUG,這就是根本原因。
但是看到這里是不是覺得還差點意思?
我說 100% 就 100% 嗎?
得拿出石錘來才行啊。
所以,為了拿出實錘,眼見為實,我把核心流程拿出來,然后稍微改動一點點代碼:
就是把線程綁定到指定 CPU 上去執(zhí)行,減少 CPU 抖動帶來的損耗, 具體我就不介紹了,有興趣去看我之前的文章。
把這個程序跑起來之后,打開資源監(jiān)視器,你可以看到 5 號 CPU 立馬就飚到 100% 了:
停止運行之后,立馬就下來了:
這就是眼見為實,這真是 JDK 的 BUG,我真沒騙你。
怎么修復(fù)
在 JDK 9 里面是怎么修復(fù)這個 BUG 的呢?
在前面提到的 BUG 的鏈接中,有這樣的一個鏈接,里面就是 JDK 9 版本里面針對上述的 BUG 進行的修復(fù):
??http://hg.openjdk.java.net/jdk9/jdk9/jdk/rev/6dd59c01f011??
點開這個鏈接之后,你可以找到這個地方:
首先對比一下標(biāo)號為 ① 和 ② 的地方,默認(rèn)值從 0 納秒修改為了 DEFAULT_KEEPALIVE_MILLIS 毫秒。
而 DEFAULT_KEEPALIVE_MILLIS 的值為在標(biāo)號為 ③ 的地方, 10L。
也就是默認(rèn)從 0 納秒修改為了 10 毫秒。而這一處的改動,就是為了防止出現(xiàn) coreSize 為 0 的情況。
我們重點關(guān)注一下 DEFAULT_KEEPALIVE_MILLIS 上面的那一坨注釋。
我給你翻譯一下,大概是這樣的:
這個值呢一般來說是用不上的,因為在 ScheduledThreadPoolExecutor 線程池里面的線程都是核心線程。
但是,如果用戶創(chuàng)建的線程池的時候,不聽勸,頭鐵,要把 corePoolSize 設(shè)置為 0 會發(fā)生什么呢?
因為 keepAlive 參數(shù)設(shè)置的為 0,那么就會導(dǎo)致線程在 getTask 方法里面非常頻繁的循環(huán),從而導(dǎo)致 CPU 飆高。
那怎么辦呢?
很簡單,設(shè)置一個小而非零的值就可以,而這個小是相對于 JVM 的運行時間而言的。
所以這個 10 毫秒就是這樣來的。
再來一個
在研究前面提到的編號為 8065320 的 BUG 的時候,我還發(fā)現(xiàn)一個意外收獲,編號為 8051859 的 BUG,它們是挨著的,排排坐。
有點意思,也很簡單,所以分享一波:https://bugs.openjdk.org/browse/JDK-8051859
這個 BUG 又說的是啥事兒呢:
看截圖這個 BUG 也是在 JDK 9 版本之后修復(fù)的。
這個 BUG 的標(biāo)題說的是 ScheduledExecutorService 線程池的 scheduleWithFixedDelay 方法,遇到大延遲時會執(zhí)行失敗。
具體啥意思呢?
我們還是先拿著 Demo 說:
你把這個代碼粘過去之后,發(fā)現(xiàn)輸出是這樣的:
只有第一個任務(wù)執(zhí)行了,第二個任務(wù)沒有輸出結(jié)果。
正常來說,第一個任務(wù)的延遲時間,也就是 initialDelay 參數(shù)是 0,所以第一次執(zhí)行的時候是立即執(zhí)行:
比如我改成這樣,把周期執(zhí)行的時間單位,由微秒修改為納秒,就正常了:
神奇不神奇?你說這不是 BUG 這是啥?
提出 BUG 的這個哥們在描述里面介紹了 BUG 的原因,主要是提到了一個字段和兩個方法:
一個字段是指 period,兩個方法分別是 TimeUnit.toNanos(-delay) 和 ScheduledFutureTask.setNextRunTime()。
首先,在 ScheduledThreadPoolExecutor 里面 period 字段有三個取值范圍:
- 正數(shù),代表的是按照固定速率執(zhí)行(scheduleAtFixedRate)。
- 負(fù)數(shù),代表的是按照固定延時執(zhí)行(scheduleWithFixedDelay)。
- 0,代表的是非重復(fù)性任務(wù)。
比如我們的示例代碼中調(diào)用的是 scheduleWithFixedDelay 方法,它里面就會在調(diào)用 TimeUnit.toNanos 方法的時候取反,讓 period 字段為負(fù)數(shù):
好,此時我們開始 Debug 我們的 Demo,先來一個正常的。
比如我們來一個每 30ms 執(zhí)行一次的周期任務(wù),請仔細(xì)看:
在執(zhí)行 TimeUnit.toNanos(-delay) 這一行代碼的時候,把 30 微秒轉(zhuǎn)化為了 -30000 納秒,也就是把 period 設(shè)置為 -30000。
然后來到 setNextRunTime 方法的時候,計算任務(wù)下一次觸發(fā)時間的時候,又把 period 轉(zhuǎn)為正數(shù),沒有任何毛?。?/p>
但是,當(dāng)我們把 30 修改為 Long.MAX_VALUE 的時候,有意思的事情就出現(xiàn)了:
delay=9223372036854775807
-delay=-9223372036854775807
unit.toNanos(-delay)=-9223372036854775808
直接給干溢出了,變成了 Long.MIN_VALUE:
當(dāng)來到 setNextRunTime 方法的時候,你會發(fā)現(xiàn)由于我們的 p 已經(jīng)是 Long.MIN_VALUE 了。
那么 -p 是多少呢?
給你跑一下:
Long.MIN_VALUE 的絕對值,還是 Long.MIN_VALUE。一個神奇的小知識點送給你,不客氣。
所以 -p 還是 Long.MIN_VALUE:
我們來算一下啊,一秒等于 10 億納秒:
那么下一次觸發(fā)時間就變成了這樣:
292 年之前。
這就是在 BUG 描述中提到的:
This results in triggerTime returning a time in the distant past.
the distant past,就是 long long ago,就是 292 年之前。就是 1731 年,雍正九年,那個時候的皇帝還是九子奪嫡中一頓亂殺,沖出重圍的胤禛大佬。
確實是很久很久以前了。
那么這個 BUG 怎么修復(fù)呢?
其實很簡單:
把 unit.toNanos(-delay) 修改為 -unit.toNanos(delay),搞定。
我給你盤一下:
這樣就不會溢出,時間就變成了 292 年之后。
那么問題就來了,誰特么會設(shè)置一個每 292 年執(zhí)行一次的 Java 定時任務(wù)呢?
好,你看到這里了,本文就算結(jié)束了,我來問你一個問題:你知道了這兩個 BUG 之后,對你來說有什么收獲嗎?
沒有,是的,除了浪費了幾分鐘時間外,沒有任何收獲。
那么恭喜你,又在我這里學(xué)到了兩個沒有卵用的知識點。
匯總
這個小節(jié)為什么叫做匯總呢?
因為我發(fā)現(xiàn)這里出現(xiàn)的一串 BUG,除了本文提到的 2 個外,還有 3 個我都寫過了,所以在這里匯個總,充點字?jǐn)?shù),湊個篇幅:
8054446: Repeated offer and remove on ConcurrentLinkedQueue lead to an OutOfMemoryError