從一個BUG說起

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

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

memory leak，內(nèi)存泄漏。

是誰導致的內(nèi)存泄漏呢？

ConcurrentLinkedQueue，這個隊列。

這個 BUG 里面說，在 jetty 項目里面也爆出了這個 BUG：

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

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

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

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

他說：在 Java 項目里面，錯誤的使用 ConcurrentLinkedQueue（文章后面用縮寫 CLQ 代替）會導致內(nèi)存泄漏的問題。

在 jetty 的 QueuedThreadPool 這個線程池里面，使用了 CLQ 這個隊列，它會導致內(nèi)存緩慢增長，最終引發(fā)內(nèi)存泄漏。

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

然后他給了一個附件，附件里面是一段程序，可以演示這個問題。

我們先不看他的程序，后面我們統(tǒng)一演示這個問題。

先給大家看一下 jetty 的 QueuedThreadPool 線程池。

看哪個版本的 jetty 呢？

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

于是我找了一個 2015 年 9 月 3 日發(fā)布的? maven 版本：

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

可以看到，它確實使用了 CLQ 隊列。

而從這個對象所有被調(diào)用的地方來看，jetty 只使用了這個隊列的 size、add、remove(obj) 方法：

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

然后這個 max 同學給了幾張圖片，來佐證他的論點：

主要關注我框起來的地方，就是說他展示了一張圖片。可以從這圖片中看出內(nèi)存泄漏的問題，而這個圖片的來源是他們真實的項目。

這個項目已經(jīng)運行了大約兩天，每五分鐘就會有一個 web 請求過來。

下面是他給出的圖片：

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

但是他說了，他這個項目請求量并不大，用的 jetty 框架也不應該創(chuàng)建這么多的 node 出來。

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

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

Greg Wilkins，何許人也？

我找到了他的領英地址：

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

jetty 項目的領導者，短短的幾個單詞，就足以讓你直呼牛逼。

高端的食材，往往只需要最簡單的烹飪。高端的人才，往往只需要寥寥數(shù)語的介紹。

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

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

?

好了，我們看一下這個 jetty 項目的領導者是怎么回答這個問題的：

首先他用 stupefied 表示了非常的震驚！然后，用到了 Ouch 語氣詞。相當于我們常說的：

他說：臥槽，我發(fā)現(xiàn)它不僅導致內(nèi)存泄漏，而且會隨著時間的推移，導致隊列越來越慢。太TM震驚了。

這個問題一定會對使用大量線程的服務器產(chǎn)生影響......希望不是所有的服務器都會有影響。

但不管是不是所有的服務器都有這個問題，只要出現(xiàn)了這個問題，對于某些服務器來說，它一定是一個非常嚴重的 BUG。
然后他說了一個 Great catch！我理解這是一個語氣助詞。就類似于：太牛逼了。

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

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

最后他說：我正在修復這個問題。

然后，在 7 分 37 秒之后， Greg 又回復了一次：

可以看出，過了快 8 分鐘，他還在持續(xù)震驚。我懷疑這 8 分鐘里面他一直在搖頭。

他說：我還在為這個 BUG 搖頭，它怎么這么久都沒被發(fā)現(xiàn)呢！對于 jetty 來說修復起來非常的簡單，使用 set 結(jié)構代替 queue 隊列即可實現(xiàn)一樣的效果。

那我們看一下修復之后的 jetty 中的 QueuedThreadPool 是怎樣的，這里我用的是 2015 年 10 月 6 日發(fā)布的一個包，也就是這個 BUG 爆出之后的最近的一個包：

里面對應的代碼是這樣的：

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

因為這個 BUG 在 JDK 中是已經(jīng)修復了，出于好奇，我想看看 CLQ 還有沒有機會重新站出來。

于是我看了一下今年發(fā)布的最新版本里面的代碼：

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

而是 JDK 8 的 ConcurrentHashMap 里面的 newKeySet 方法，C 位出道：

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

回到 Greg 的回復中，這次的回復里面，他還給了一個修復的演示實例，下一小節(jié)我會針對這個實例進行解讀。

在 23 分鐘之后，他就提交代碼修復完成了。

從第一次回復帖子，到定位問題，再到提交代碼，用了 30 分鐘的時間。

然后在凌晨 2 點 57 分（這個時間點，大佬都是不用睡覺的嗎？還是說剛修完福報，下班了）， max 回復到：

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

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

為什么沒有在 API 文檔里面說明呢？

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

Greg 連著回復了兩條，并且直接指出了解決方案：

問題的原因是 remove 方法的源碼里面，有上圖中標號為 ① 的這樣一行代碼。

這行代碼會去取消被移除的這個 node （其值已經(jīng)被替換為 null）和 list 之間的鏈接，然后可以讓 GC 回收這個 node。

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

所以就會出現(xiàn)這個需要移除的節(jié)點已經(jīng)被置為 null 了，但卻沒有取消和隊列之間的連接，導致 GC 線程不會回收這個節(jié)點。

他給出的解決方案也很簡單，就是標號為②、③的地方。總之，只需要讓代碼執(zhí)行 pred.casNext 方法就行。

總之一句話，導致內(nèi)存泄漏的原因是一個被置為 null 的 node，由于代碼問題，導致該 node 節(jié)點，既不會被使用，也不會被 GC 回收掉。

如果你還沒理解到這個 BUG 的原因，說明你對 CLQ 這個隊列的結(jié)構還不太清晰。

那么我建議你讀一下《Java并發(fā)編程的藝術》這一本書，里面有一小節(jié)專門講這個隊列的，圖文并茂，寫的還是非常清晰。

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

然后，我們再回到 JDK BUG 的這個鏈接中去：

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

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

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

Demo跑起來

這一小節(jié)里面，我們跑一下 Greg 給的那個修復 Demo，親手去摸一下這個 BUG 的樣子。

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

你可以打開上面那個鏈接，直接復制粘貼到你的 IDEA 里面去：

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

這個 Demo 就是在死循環(huán)里面調(diào)用 queue 的 add(obj) 和 remove(obj) 方法。每循環(huán) 10000 次，就打印出時間間隔、隊列大小、最大內(nèi)存、剩余內(nèi)存、總內(nèi)存的值。

最終運行起來的效果是這樣的（JDK 版本是 1.7.0_71）：

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

后面三個內(nèi)存相關的參數(shù)可以先不關心，下一小節(jié)我們用圖形化工具來看。

你知道上面這個程序，到我寫文章寫到這里的時候，我跑了多久了嗎？

61 小時 32 分 53 秒。

最新一次循環(huán) 10000 次所需要的時間間隔是 575615ms，快接近 10?分鐘：

這就是 Greg 說的：不僅僅是內(nèi)存泄漏，而且越來越慢。

但是，同樣的程序，我用 JDK 1.8.0_212 版本跑的時候情況卻是這樣的：

時間間隔很穩(wěn)定，不會隨著時間的推移而增加。

說明這個版本是修復了這個 BUG 的，我?guī)Т蠹铱纯丛创a：

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 沒有發(fā)現(xiàn)內(nèi)存泄漏的問題，我看了對應的 remove(obj)?方法的源碼確實是修復了。

在 JDK 1.7.0_71 中可以看到內(nèi)存泄漏的問題。

unlink，一個簡簡單單的詞，背后原來藏了這么多故事。

jconsole、VisualVM、jmc

既然都說到內(nèi)存泄漏了，那必須得介紹幾個可視化的故障排除工具。

前面說了，這個程序跑了 61 個小時了，給大家看一下這個時間段里面堆內(nèi)存的使用情況：

可以看到整個堆內(nèi)存的使用量是一個明顯的、緩慢的上升趨勢。

上面這個圖就是來自 jconsole。

結(jié)合程序，通過圖片我們可以分析出，這種情況一定是內(nèi)存泄漏了，這是一個非常經(jīng)典的內(nèi)存泄漏的走勢。

接下來，我們再看一下 jmc 的監(jiān)控情況：

上面展示的是已經(jīng)使用的堆內(nèi)存的大小，走勢和 jconsole 的走勢一樣。

然后再看看 VisualVM 的圖：

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

在 VisualVM 里面，我們可以直接 Dump 堆，然后進行分析：

可以清楚的看到， CLQ 的 Node 的大小占據(jù)了 94.2%。

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

你說，這不是內(nèi)存泄漏是什么。

內(nèi)存泄漏最終會導致 OOM。

所以當發(fā)生 OOM 的時候，我們需要分析是不是有內(nèi)存泄漏。也就是看內(nèi)存里面的對象到底應不應該存活，如果都應該存活那就不是內(nèi)存泄漏，是內(nèi)存不足了。需要檢查一下 JVM 的參數(shù)配置（-Xmx/-Xms），根據(jù)機器內(nèi)存情況，判斷是否還能再調(diào)大一點。

同時，也需要檢查一下代碼，是否存在生命周期過程的對象，是否有數(shù)據(jù)結(jié)構使用不合理的地方，盡量減少程序運行期的內(nèi)存消耗。

我們可以通過把堆內(nèi)存設置的小一點，來模擬一下內(nèi)存泄漏導致的 OOM。

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

然后把代碼跑起來，同時通過 VisualVM 、jconsole、jmc 這三個工具監(jiān)控起來，為了我們有足夠的時候準備好檢測工具，我在第 8 行加入休眠代碼，其他的代碼和之前的一樣：

加入 -Xmx20m 參數(shù)：

運行起來之后，我們同時通過工具來查看內(nèi)存變化，下面三個圖從上到下的工具分別是 VisualVM、jconsole、jmc：

從圖片的走勢來看，和我們之前分析的是一樣的，內(nèi)存一直在增長。

程序運行 19 分 06 秒后，發(fā)生 OOM 異常：

那正常的走勢圖應該是怎么樣的呢？

我們在 JDK 1.8.0_121 版本中（已經(jīng)修復了 remove 方法），用相同的 JVM 參數(shù)（-Xmx20m）再跑一下：

首先從上面的日志中可以看出，時間間隔并沒有遞增，程序運行的非常的快。

然后用 VisualVM 檢測內(nèi)存，同樣跑 19 分鐘后截圖如下：

可以看到堆內(nèi)存的使用量并沒有隨著時間的推移而越來越高。但是還是有非常頻繁的 GC 操作。

這個不難理解，因為 CLQ 的數(shù)據(jù)結(jié)構用的是鏈表。而鏈表又是由不同的 node 節(jié)點組成。

由于調(diào)用 remove 方法后，node 節(jié)點具備被回收的條件，所以頻繁的調(diào)用 remove 方法對節(jié)點進行刪除，會觸發(fā) JVM 的 min GC。

這種 JDK BUG 導致的內(nèi)存泄漏其實挺讓人崩潰的。首先你第一次感知到它是因為程序發(fā)生了 OOM。

也許你會先無腦的加大堆內(nèi)存空間，恰好你的程序運行了一周之后又要上線了，所以涉及到重啟應用。

然后很長一段時間內(nèi)沒有發(fā)生 OOM 了。你就想這個問題可能解決了。

但是它還是在繼續(xù)發(fā)生著，很可能由于節(jié)假日前后不能上線，比如國慶七天，加上前后幾天，大概有半個月的樣子應用沒有上線，所以沒有重啟，程序越來越慢，最終導致第二次 OOM 的出現(xiàn)。

這個時候，你覺得可能不是內(nèi)存溢出這么簡單了。

會不會是內(nèi)存泄漏了？

然后你再次重啟。這次重啟之后，你開始時不時的 Dump 一下內(nèi)存，拿出來分析分析。

突然發(fā)現(xiàn)，這個 node 怎么這么多呢？

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

原來是 JDK 的 BUG。

你就會發(fā)出和 Greg 一樣的感嘆：臥槽，震驚，這么牛皮！？

我這個運行了 60 多小時的程序到現(xiàn)在堆內(nèi)存使用了 233m，但是我整個堆的大小是接近 2G。

通過 jmc 同時展示堆的整體大小和已經(jīng)使用的堆大小你可以發(fā)現(xiàn)，距離內(nèi)存泄漏可以說是道阻且長了：

我粗略的算了一下，這個程序大概還得運行 475 個小時左右，也就是 19 天之后才會出現(xiàn)由于內(nèi)存泄漏，導致的 OOM。

我會盡量跑下去，但是聽到我電腦嗡嗡嗡的風扇聲，我不知道它還能不能頂?shù)米　?/p>

如果它頂住了，我在后面的文章里面通知大家。

好了，圖形化工具這一小節(jié)就到這里了。

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

如果你不太了解它們的功能，建議你看看《深入理解JVM虛擬機（第3版）》，里面有一章節(jié)專門講這幾個工具的。

最后說一句

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

要是股市的總體走勢也像內(nèi)存泄露那么單純而直接就好了。

只要在 OOM 之前落袋為安就行?？上в械娜司褪窃?OOM 的前一刻滿倉殺入，真是個悲傷的故事。

總結(jié)

以上是生活随笔為你收集整理的我的程序跑了60多小时，就是为了让你看一眼JDK的BUG导致的内存泄漏。的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。