揪出一個導致GC慢慢變長的JVM設計缺陷
今天要給大家分享的內容和 YGC(Young GC)有關,是我最近碰到的一個案例,希望將排查思路分享給大家,如果大家后面碰到類似的問題,可以直接作為一個經驗來排查。
我之前里寫過幾篇 YGC 的文章,也許其中有人已經看過了,沒看過的可以去看看,那兩個坑在這里就不再描述,大家可以直接當經驗使用。
Java 堆分為新生代和老生代,YGC 其實就是針對新生代的垃圾回收,對象都是優先在新生代分配的,因此當新生代內存不夠分配的時候就會觸發垃圾回收,正常情況下可能觸發一次 YGC 就可以解決問題并正常分配的,當然也有極端情況可能要進行大掃除,對整個堆進行回收,也就是我們說的 Full GC,這種情況發生就會比較悲劇了。
這里再提一下,YGC 也是會 STW(stop the world) 的,也就是會暫停整個應用,不要覺得 YGC 發生頻繁不是問題。
說實話我比較不喜歡排查 YGC 的問題,因為 YGC 的日志太簡單了,正常情況下只能知道新生代內存從多少變到了多少,花了多長時間,再無其它信息了。
所以當有人來咨詢為什么我的程序 YGC 越來越長的問題的時候,我其實是抗拒的,不過也無奈,總得嘗試去幫人家解決,包括前面說的那兩個問題,也是費了不少精力查出來的,希望大家珍惜。。。
有些時候你越想逃避,偏偏就會找上你,YGC 的問題最近說實話找我的挺多的,不過有好些都是踩過的坑,所以能順利幫人家解決,但是今天要說的這個問題是之前從未碰到過的,是一個全新的問題,所以也費了我不少精力,也因為其他問題要查被拖延了幾天。
這個問題最終排查下來其實是 JVM 本身設計上面的一個缺陷,我改天也會提到 openjdk 社區去和大家一起討論下這個設計,希望能徹底***這個問題。
這個問題現象也很明顯,就是發現 YGC 的時間越來越長,從 20ms 慢慢增加到100ms+,甚至還一直在漲。
不過這個增長過程還是挺緩慢的,其實 YGC 時間在幾十毫秒我個人認為算正常現象,沒必要去深究,再說了還是經過壓測了一個晚上才漲上來的,所以平時應該也不是啥問題吧,不過這次正巧趕上年中大促,所以大家對時間也比較敏感,便接手來排查這個案例了。
首先排除了之前碰到的幾種情況,然后我要同事加了一個我們 alijdk 特定的參數,可以打印 YGC 過程里具體各個階段的耗時情況,可惜的是并沒有找出問題,因為我們漏掉了一些點,導致沒有直接定位出來。
于是我懷疑那些沒跟蹤到的邏輯,首先懷疑的就是引用這塊的處理,所以叫同事加上了 -XX:+PrintReferenceGC 這個參數,這個參數會打印各種引用的處理時間,大概如下:
點擊下面圖片進入小程序查看PrintReferenceGC參數詳情
從當時的那個日志里,我發現了一個現象,就是隨著 YGC 時間的增長,JNI Weak Reference 的處理耗時也在不斷增長,所以基本就定位到了 YGC 增長的直接原因。
JNI Weak Reference 到底是什么呢?大家都知道 Java 層面有各種引用,包括 SoftReference,WeakReference 等,其中 WeakReference 可以保證在 GC 的時候不會阻礙其引用對象的回收,同樣的在 native 代碼里,我們也可以做類似的事情,有個叫做 JNIHandles::make_weak_global 的方法來達到這樣的效果。
于是我開始修改 JVM,嘗試打印一些信息出來,不知道大家注意過,我們 dump 線程的時候,使用 jstack 命令,***一條輸出里會看到類似 JNI global references: 328 的日志,這里其實就是打印了 JNI 里的兩種全局引用總數,分別是 _global_handles 和 _weak_global_handles。
于是嘗試將這兩種情況分開來,看具體哪種有多少個,于是改了***個版本,從修改之后的輸出來看,_global_handles 的引用個數基本穩定不變,但是 _weak_global_handles 的變化卻比較明顯。
至此也算佐證了 JNI Weak Reference的問題,于是我想再次修改 JVM,打印了這些 JNI Weak Reference 引用的具體對象是什么對象。
在每次我執行 jstack 時,就會順帶把那些對象都打印出來,當然那個時候是為了性能,畢竟程序還跑在線上,不敢動太大,比如要是大量輸出日志不可控,那就麻煩了,所以就借助 jstack 來手動觸發這個邏輯。
從輸出來看,看到了大量的下面的內容:
于是詢問同事是不是存在大量的 Java 對 JavaScript 的調用,被告知確實有使用,那問題點基本算定位到了,我馬上要同事針對他們的用法寫一個簡單的 demo 出來復現下問題。
沒想到很快就寫好,而且真的很容易復現,大概邏輯如下:
于是我開始 debug,最終確認和上面的 demo 完全等價于下面的 demo。
所以大家直接運行上面的 demo 就能復現問題,JVM 參數如下:
- -Xmx300M -Xms300M -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintReferenceGC
對了,運行平臺是 JDK 8,JDK 6 是不存在這個問題的,因為 invokedynamic 指令以及 nashorn 是在 JDK 6 里不存在的。
上面的 demo 看起來是不是沒毛病,但是卻真的會讓你的 GC 越來越慢,通過對 JVM 進行 debug 的方式抓出了下面的類似堆棧。
在 JDK 層面的棧如下:
最上面的 resolve 方法是一個 native 方法,這個方法發現可以直接調用到上面提到的 JNIHandles::make_weak_global 方法。
JNIHandles::make_weak_global 方法其實就是創建了一個 JNI Weak Reference。
在這里我要稍微描述下了,因為太繁瑣就不準備貼代碼了。
JVM 里有個數據結構叫做 JNIHandleBlock,之前提到了 global_handles 和 _weak_global_handles,其實他們都是一個 JNIHandleBlock 鏈表。
可以想象下里面有個 next 字段鏈到下一個 JNIHandleBlock,同時里面還有一個數組 _handle[],長度是 32,當我們要分配一個 JNI Weak Reference 的時候,就相當于在這個 JNIHandleBlock 鏈表里找一個空閑的位置(就是那些 _handle 數組),如果發現每個 JNIHandleBlock 的 _handle 數組都滿了,就會創建一個新的 JNIHandleBlock,然后加到鏈里,注意這個鏈可以***長,所以問題就來了,假如我們上層代碼不斷觸發底層調用 JNIHandles::make_weak_global 來創建一個 JNI Weak Reference,那是不是意味著這個 JNIHandleBlock 鏈會不斷增長,那會不會無窮增長呢,答案是肯定的,既然有創建 JNI Weak Reference 的 API,是不是也存在銷毀 JNI Weak Reference 的 API?
當然是存在的,可以看到有 JNIHandles::destroy_weak_global 方法,這個實現其實很簡單,就是相當于設計一個標記,表示這個數組里的這個位置是可以重用的了,在 GC 發生的時候,如果發現這個坑被標記了,于是就將這個坑加入到一個 free_list 里,當我們下面再想要分配一個 JNI Weak Reference 的時候,就可以有機會從 free_list 里去分配一個重用了。
但是這個 api 是在什么情況下才能調用的呢,其實只有在類卸載的時候才會去調用這個 api,那到底是什么類被卸載了,那就是調用了 MethodHandles.lookup() 這個方法的那個類,從我們上面的 demo 來看,就是 MHTest 這個主類本身,從同事給我的 demo 來看,其實是 jdk.nashorn.internal.runtime.Context 這個類,但是這個類其實是被 ext_classloader 加載的,也就是說這個類根本就不會被卸載,不能卸載那問題就嚴重了,意味著 GC 發生的時候并不能將那些引用對象已經死掉的坑置空,這樣在我們需要再次分配 JNI Weak Reference 的時候,沒有機會來重用那些坑,最終的結果就是不斷地創建新的 JNIHandleBlock 加到鏈表里,導致鏈表越來越長,然而 GC 的時候是會去不斷掃描這個鏈表的,因此看到 GC 的時候也會越來越長。
那還有一個問題,假如說調用 MethodHandles.lookup() 的類真的被卸載了還存在這個問題嗎,答案是 GC 時間不會再惡化了,但是之前已經達到的惡化結果已經無法再修復了。
所以,這算是一個 JVM 設計上的缺陷吧,只要 Java 層面能觸發不斷調用到JNIHandles::make_weak_global,那這個問題將會立馬重現。
其實解決方案我也想了一個,就是在遍歷這些 JNIHandleBlock 的時候,如果發現對應的_handle數組全是空的話,那就直接將 JNIHandleBlock 回收掉,這樣在 GC 發生的過程中并不會掃描到很多的 JNIHandleBlock 而耗時掉。
至于同事的那個問題的解決方案,其實也簡單,對于同一個 JavaScript 腳本,不要每次都去調用 eval 方法,可以緩存起來,這樣就減少了不斷去觸發調用 JNIHandles::make_weak_global 的動作從而可以避免 JNIHandleBlock 不斷增長的問題。
【本文是51CTO專欄作者李嘉鵬的原創文章,轉載請通過微信公眾號(你假笨,id:lovestblog)聯系作者本人獲取授權】