我的程式跑了60多小時,就是為了讓你看一眼JDK的BUG導致的記憶體洩漏。

why技術發表於2020-07-21

這次的文章從JDK的J.U.C包下的ConcurrentLinkedQueue佇列的一個BUG講起。jetty框架裡面的執行緒池用到了這個佇列,導致了記憶體洩漏。

同時通過jconsole、VisualVM、jmc這三個視覺化監控工具,讓你看見“記憶體洩漏”的發生。有點意思,大家一起看看。

從一個BUG說起

前段時間翻到了一個 JDK 有點意思的 BUG,帶大家一起瞅瞅。

https://bugs.java.com/bugdatabase/view_bug.do?bug_id=8137185

memory leak,記憶體洩漏。

是誰導致的記憶體洩漏呢?

ConcurrentLinkedQueue,這個佇列。

這個 BUG 裡面說,在 jetty 專案裡面也爆出了這個 BUG:

我看了一下,覺得 jetty 的這個寫的挺有意思的。

我按照 jetty 的這個講吧,反正都是同一個 JDK BUG 導致的。地址如下:

https://bugs.eclipse.org/bugs/show_bug.cgi?id=477817

我用我八級半的蹩腳英語給大家翻譯一下這個叫做 max 的同學說了些什麼。

他說:在 Java 專案裡面,錯誤的使用 ConcurrentLinkedQueue(文章後面用縮寫 CLQ 代替)會導致記憶體洩漏的問題。

在 jetty 的 QueuedThreadPool 這個執行緒池裡面,使用了 CLQ 這個佇列,它會導致記憶體緩慢增長,最終引發記憶體洩漏。

雖然 QueuedThreadPool 僅僅使用了這個佇列的 add 方法和 remove 方法。但不幸的是,remove 方法不會把佇列的大小變小,只會使佇列裡面被刪除的 node 為空。因此,該列表將增長到無窮大。

然後他給了一個附件,附件裡面是一段程式,可以演示這個問題。

我們先不看他的程式,後面我們統一演示這個問題。

先給大家看一下 jetty 的 QueuedThreadPool 執行緒池。

看哪個版本的 jetty 呢?

可以看到這個 BUG 是在 2015 年 9 月 18 日被爆出來的。所以,我們找一個這個日期之前的版本就行。

於是我找了一個 2015 年 9 月 3 日釋出的 maven 版本:

在這個版本里面的 QueuedThreadPool 是這樣的:

可以看到,它確實使用了 CLQ 佇列。

而從這個物件所有被呼叫的地方來看,jetty 只使用了這個佇列的 size、add、remove(obj) 方法:

和前面 max 同學描述的一致。

然後這個 max 同學給了幾張圖片,來佐證他的論點:

主要關注我框起來的地方,就是說他展示了一張圖片。可以從這圖片中看出記憶體洩漏的問題,而這個圖片的來源是他們真實的專案。

這個專案已經執行了大約兩天,每五分鐘就會有一個 web 請求過來。

下面是他給出的圖片:

從他的這個圖片中,我就只看出了 CLQ 的 node 很多。

但是他說了,他這個專案請求量並不大,用的 jetty 框架也不應該建立這麼多的 node 出來。

好了,我們前面分析了 max 同學說的這個問題,接下來就是大佬出場,來解惑了:

我們先不看回答,先看看回答問題的人是誰。

Greg Wilkins,何許人也?

我找到了他的領英地址:

https://www.linkedin.com/in/gregwilkins/?originalSubdomain=au

jetty 專案的領導者,短短的幾個單詞,就足以讓你直呼牛逼。

高階的食材,往往只需要最簡單的烹飪。高階的人才,往往只需要寥寥數語的介紹。

大佬的簡歷就是這麼樸實無華,且枯燥。

而且,你看這個頭像。哎,酸了酸了。果然再次印證了這句話:變禿了,也變強了,並不適用於外國的神仙。

好了,我們看一下這個 jetty 專案的領導者是怎麼回答這個問題的:

首先他用 stupefied 表示了非常的震驚!然後,用到了 Ouch 語氣詞。相當於我們常說的:

他說:臥槽,我發現它不僅導致記憶體洩漏,而且會隨著時間的推移,導致佇列越來越慢。太TM震驚了。

這個問題一定會對使用大量執行緒的伺服器產生影響......希望不是所有的伺服器都會有影響。

但不管是不是所有的伺服器都有這個問題,只要出現了這個問題,對於某些伺服器來說,它一定是一個非常嚴重的 BUG。

然後他說了一個 Great catch!我理解這是一個語氣助詞。就類似於:太牛逼了。

這個不好翻譯,我貼一個例句,大家自己去體會一下吧:

我也是沒想到,在技術文裡面還給大家教起了英文。

最後他說:我正在修復這個問題。

然後,在 7 分 37 秒之後, Greg 又回覆了一次:

可以看出,過了快 8 分鐘,他還在持續震驚。我懷疑這 8 分鐘裡面他一直在搖頭。

他說:我還在為這個 BUG 搖頭,它怎麼這麼久都沒被發現呢!對於 jetty 來說修復起來非常的簡單,使用 set 結構代替 queue 佇列即可實現一樣的效果。

那我們看一下修復之後的 jetty 中的 QueuedThreadPool 是怎樣的,這裡我用的是 2015 年 10 月 6 日釋出的一個包,也就是這個 BUG 爆出之後的最近的一個包:

裡面對應的程式碼是這樣的:

簡單粗暴的用 CurrentHashSet 代替了 CLQ。

因為這個 BUG 在 JDK 中是已經修復了,出於好奇,我想看看 CLQ 還有沒有機會重新站出來。

於是我看了一下今年釋出的最新版本里面的程式碼:

既不是用的 CurrentHashSet ,也沒有給 CLQ 機會。

而是 JDK 8 的 ConcurrentHashMap 裡面的 newKeySet 方法,C 位出道:

這是一個小小的 jetty 執行緒池的演變過程。恭喜你,又學到了一個基本上不會用到的知識點。

回到 Greg 的回覆中,這次的回覆裡面,他還給了一個修復的演示例項,下一小節我會針對這個例項進行解讀。

在 23 分鐘之後,他就提交程式碼修復完成了。

從第一次回覆帖子,到定位問題,再到提交程式碼,用了 30 分鐘的時間。

然後在凌晨 2 點 57 分(這個時間點,大佬都是不用睡覺的嗎?還是說剛修完福報,下班了), max 回覆到:

我不敢相信 CLQ 使用起來會有這樣的問題,他們至少應該在 API 文件裡面說明一下。

這裡的他們,應該指的是 JDK 團隊的成員,特指 Doug Lea,畢竟是他老爺子的作品。

為什麼沒有在 API 文件裡面說明呢?

因為他們自己也不知道有這個 BUG 啊。

Greg 連著回覆了兩條,並且直接指出瞭解決方案:

問題的原因是 remove 方法的原始碼裡面,有上圖中標號為 ① 的這樣一行程式碼。

這行程式碼會去取消被移除的這個 node (其值已經被替換為 null)和 list 之間的連結,然後可以讓 GC 回收這個 node。

但是,當集合裡面只有一個元素的時候, next != null 這個判斷是不成立的。

所以就會出現這個需要移除的節點已經被置為 null 了,但卻沒有取消和佇列之間的連線,導致 GC 執行緒不會回收這個節點。

他給出的解決方案也很簡單,就是標號為②、③的地方。總之,只需要讓程式碼執行 pred.casNext 方法就行。

總之一句話,導致記憶體洩漏的原因是一個被置為 null 的 node,由於程式碼問題,導致該 node 節點,既不會被使用,也不會被 GC 回收掉。

如果你還沒理解到這個 BUG 的原因,說明你對 CLQ 這個佇列的結構還不太清晰。

那麼我建議你讀一下《Java併發程式設計的藝術》這一本書,裡面有一小節專門講這個佇列的,圖文並茂,寫的還是非常清晰。

這個 BUG 在 jetty 裡面的來龍去脈算是說清楚了。

然後,我們再回到 JDK BUG 的這個連結中去:

他這裡寫的原因就是我前面說的原因,沒有 unlink,所以不能被回收。

而且他說到:這個 BUG 在最新的JDK 7、8和9版本中都存在。

他說的最新是指截止這個 BUG 被提出來之前:

Demo跑起來

這一小節裡面,我們跑一下 Greg 給的那個修復 Demo,親手去摸一下這個 BUG 的樣子。

https://bugs.eclipse.org/bugs/attachment.cgi?id=256704

你可以開啟上面那個連結,直接複製貼上到你的 IDEA 裡面去:

注意第 13 行,因為 Greg 給的是修復 Demo,所以用的是 ConcurrentHashSet,由於我們要演示這個bug,所以使用 CLQ。

這個 Demo 就是在死迴圈裡面呼叫 queue 的 add(obj) 和 remove(obj) 方法。每迴圈 10000 次,就列印出時間間隔、佇列大小、最大記憶體、剩餘記憶體、總記憶體的值。

最終執行起來的效果是這樣的(JDK 版本是 1.7.0_71):

可以看到每次列印 duration 這個時間間隔是越來越大,佇列大小始終為 1。

後面三個記憶體相關的引數可以先不關心,下一小節我們用圖形化工具來看。

你知道上面這個程式,到我寫文章寫到這裡的時候,我跑了多久了嗎?

61 小時 32 分 53 秒。

最新一次迴圈 10000 次所需要的時間間隔是 575615ms,快接近 10 分鐘:

這就是 Greg 說的:不僅僅是記憶體洩漏,而且越來越慢。

但是,同樣的程式,我用 JDK 1.8.0_212 版本跑的時候情況卻是這樣的:

時間間隔很穩定,不會隨著時間的推移而增加。

說明這個版本是修復了這個 BUG 的,我帶大家看看原始碼:

JDK 1.8.0_212 版本的原始碼裡面,在 CLQ 的 remove(obj) 方法的 502 行末尾註釋了一個 unlink。

官方的修復方法可以看這裡:

http://hg.openjdk.java.net/jdk8u/jdk8u-dev/jdk/rev/8efe549f3c87

改動比較多,但是原理還是和之前分析的一樣:

我僅僅在兩個 JDK 版本中跑過示例程式碼。

在 JDK 1.8.0_212 沒有發現記憶體洩漏的問題,我看了對應的 remove(obj) 方法的原始碼確實是修復了。

在 JDK 1.7.0_71 中可以看到記憶體洩漏的問題。

unlink,一個簡簡單單的詞,背後原來藏了這麼多故事。

jconsole、VisualVM、jmc

既然都說到記憶體洩漏了,那必須得介紹幾個視覺化的故障排除工具。

前面說了,這個程式跑了 61 個小時了,給大家看一下這個時間段裡面堆記憶體的使用情況:

可以看到整個堆記憶體的使用量是一個明顯的、緩慢的上升趨勢。

上面這個圖就是來自 jconsole。

結合程式,通過圖片我們可以分析出,這種情況一定是記憶體洩漏了,這是一個非常經典的記憶體洩漏的走勢。

接下來,我們再看一下 jmc 的監控情況:

上面展示的是已經使用的堆記憶體的大小,走勢和 jconsole 的走勢一樣。

然後再看看 VisualVM 的圖:

VisualVM 的圖,我不知道怎麼看整個執行了 60 多小時的走勢圖,但是從上面的圖也是能看出是有上升趨勢的。

在 VisualVM 裡面,我們可以直接 Dump 堆,然後進行分析:

可以清楚的看到, CLQ 的 Node 的大小佔據了 94.2%。

但是,從我們的程式來看,我們根本就沒有用到這麼多 Node。我們只是用了一個而已。

你說,這不是記憶體洩漏是什麼。

記憶體洩漏最終會導致 OOM。

所以當發生 OOM 的時候,我們需要分析是不是有記憶體洩漏。也就是看記憶體裡面的物件到底應不應該存活,如果都應該存活那就不是記憶體洩漏,是記憶體不足了。需要檢查一下 JVM 的引數配置(-Xmx/-Xms),根據機器記憶體情況,判斷是否還能再調大一點。

同時,也需要檢查一下程式碼,是否存在生命週期過程的物件,是否有資料結構使用不合理的地方,儘量減少程式執行期的記憶體消耗。

我們可以通過把堆記憶體設定的小一點,來模擬一下記憶體洩漏導致的 OOM。

還是用之前的測試案例,但是我們指定 -Xmx 為 20m,即最大可用的堆大小為 20m。

然後把程式碼跑起來,同時通過 VisualVM 、jconsole、jmc 這三個工具監控起來,為了我們有足夠的時候準備好檢測工具,我在第 8 行加入休眠程式碼,其他的程式碼和之前的一樣:

加入 -Xmx20m 引數:

執行起來之後,我們同時通過工具來檢視記憶體變化,下面三個圖從上到下的工具分別是 VisualVM、jconsole、jmc:

從圖片的走勢來看,和我們之前分析的是一樣的,記憶體一直在增長。

程式執行 19 分 06 秒後,發生 OOM 異常:

那正常的走勢圖應該是怎麼樣的呢?

我們在 JDK 1.8.0_121 版本中(已經修復了 remove 方法),用相同的 JVM 引數(-Xmx20m)再跑一下:

首先從上面的日誌中可以看出,時間間隔並沒有遞增,程式執行的非常的快。

然後用 VisualVM 檢測記憶體,同樣跑 19 分鐘後截圖如下:

可以看到堆記憶體的使用量並沒有隨著時間的推移而越來越高。但是還是有非常頻繁的 GC 操作。

這個不難理解,因為 CLQ 的資料結構用的是連結串列。而連結串列又是由不同的 node 節點組成。

由於呼叫 remove 方法後,node 節點具備被回收的條件,所以頻繁的呼叫 remove 方法對節點進行刪除,會觸發 JVM 的 min GC。

這種 JDK BUG 導致的記憶體洩漏其實挺讓人崩潰的。首先你第一次感知到它是因為程式發生了 OOM。

也許你會先無腦的加大堆記憶體空間,恰好你的程式執行了一週之後又要上線了,所以涉及到重啟應用。

然後很長一段時間內沒有發生 OOM 了。你就想這個問題可能解決了。

但是它還是在繼續發生著,很可能由於節假日前後不能上線,比如國慶七天,加上前後幾天,大概有半個月的樣子應用沒有上線,所以沒有重啟,程式越來越慢,最終導致第二次 OOM 的出現。

這個時候,你覺得可能不是記憶體溢位這麼簡單了。

會不會是記憶體洩漏了?

然後你再次重啟。這次重啟之後,你開始時不時的 Dump 一下記憶體,拿出來分析分析。

突然發現,這個 node 怎麼這麼多呢?

最終,找到這個問題的原因。

原來是 JDK 的 BUG。

你就會發出和 Greg 一樣的感嘆:臥槽,震驚,這麼牛皮!?

我這個執行了 60 多小時的程式到現在堆記憶體使用了 233m,但是我整個堆的大小是接近 2G。

通過 jmc 同時展示堆的整體大小和已經使用的堆大小你可以發現,距離記憶體洩漏可以說是道阻且長了:

我粗略的算了一下,這個程式大概還得執行 475 個小時左右,也就是 19 天之後才會出現由於記憶體洩漏,導致的 OOM。

我會盡量跑下去,但是聽到我電腦嗡嗡嗡的風扇聲,我不知道它還能不能頂得住。

如果它頂住了,我在後面的文章裡面通知大家。

好了,圖形化工具這一小節就到這裡了。

我們只是展示了它們非常小的一個功能,合理的使用它們常常能達到事半功倍的作用。

如果你不太瞭解它們的功能,建議你看看《深入理解JVM虛擬機器(第3版)》,裡面有一章節專門講這幾個工具的。

最後說一句(求關注)

這是我昨天晚上寫文章的時候拍的 ,女朋友說一眼望去感覺我是一個盯盤的人,在看股票走勢圖,這隻股票太牛逼了。

要是股市的總體走勢也像記憶體洩露那麼單純而直接就好了。

只要在 OOM 之前落袋為安就行。可惜有的人就是在 OOM 的前一刻滿倉殺入,真是個悲傷的故事。

文中提到的兩本書,都是非常優秀的值得學習的書籍。作為一個 Java 程式設計師,如果你還沒有擁有這兩本書,我強烈建議你買來看看。

買不了吃虧,買不了上當,只會覺得相見恨晚。你會發現原來這麼多 JVM、多執行緒相關的面試題都是出自這兩本書:

才疏學淺,難免會有紕漏,如果你發現了錯誤的地方,還請你留言指出來,我對其加以修改。

感謝您的閱讀,我堅持原創,十分歡迎並感謝您的關注。

我是 why,一個被程式碼耽誤的文學創作者,不是大佬,但是喜歡分享,是一個又暖又有料的四川好男人。

相關文章