1. 程式人生 > >記一次隱藏很深的 JVM 線上慘案的分析、排查、解決

記一次隱藏很深的 JVM 線上慘案的分析、排查、解決

1、本文背景

本文會給大家講解一個比較特殊的JVM優化案例,這個優化案例本身是因為新手工程師對JVM優化可能瞭解了一個半吊子,然後不知道從哪裡找來了一個非常特殊的JVM引數錯誤的設定了一下,就導致線上系統頻繁的出現Full GC的問題。

但是我們後續大量的優化案例其實都是各種各樣奇形怪狀的場景,因為正是各種奇怪場景才能讓大家逐步積累出來較為豐富的JVM優化實戰經驗

瞭解的場景越多,自己未來在處理JVM效能問題的時候才能更是得心應手。

2、問題的產生

這個場景的發生大致如下過程:某天團隊裡一個新手工程師大概是心血來潮,覺得自己網上看到了某個JVM引數,以為學會了絕世武功祕籍,於是就在當天上線一個系統的時候,自作主張設定了一個JVM引數

這個引數是什麼呢?

不用急,跟著看下面的案例分析即可,現在只要知道他設定了一個奇怪的引數,接著事故就發生了。

因為一般中大型公司都是接入類似Zabbix、OpenFalcon或者公司自研的一些監控系統的,監控系統一般都做的很好,可以讓你的系統直接接入進去,然後在上面可以看到每臺機器的CPU、磁碟、記憶體、網路的一些負載。

而且可以看到你的JVM的記憶體使用波動折線圖,還有你的JVM GC發生的頻率折線圖。包括如果你自己上報某個業務指標,也可以在監控系統裡看到。

而且一般都會針對線上執行的機器和系統設定一些報警,比如說,你可以設定如果10分鐘內發現一個系統的JVM發生了超過3次Full GC,就必須傳送報警給你,可以傳送給你的簡訊、郵箱或者是釘釘之類的IM工具。

類似這樣的監控系統不在我們的專欄範疇內,建議大家自己可以去查閱資料,其實基於我們講解的命令列工具,比如jstat,你可以通過linux上的一些命令,讓jstat自動對jvm進行監控,把監控結果可以輸出到機器的某個檔案裡去。

然後第二天你就可以去查閱那個檔案,也可以看到那臺機器的jvm的一些gc統計。

所以說,沒有視覺化工具,用最簡單的命令列工具,其實同樣可以起到類似的效果。

所以那天那個工程師設定了一個JVM引數之後,直接導致線上頻繁接到JVM的Full GC的報警,大家就很奇怪了,於是就開始排查那個系統了。

3、檢視GC日誌

之前已經給大家講解過如何在啟動系統的時候讓他輸出GC日誌,所以一旦發現報警,直接登入到線上機器,然後就看到對應的GC日誌了。

此時我們看到在GC日誌中有大量的Full GC的記錄。

那麼是為什麼導致的Full GC呢?

在日誌裡,看到了一個“Metadata GC Threshold”的字樣,類似於如下日誌:

【Full GC(Metadata GC Threshold)xxxxx, xxxxx】

從這裡就知道,這頻繁的Full GC,實際上是JDK 1.8以後的Metadata元資料區導致的,也就是類似我們之前說的永久代。

這個Metadata區域一般是放一些載入到JVM裡去的類的。

所以此時就很奇怪了,為什麼會因為Metadata區域頻繁的被塞滿,進而觸發Full GC?而且Full GC大家都知道,會帶動CMS回收老年代,還會回收Metadata區域本身。

我們先看看下圖:

 

記一次隱藏很深的 JVM 線上慘案的分析、排查、解決

 

 

4、檢視Metaspace記憶體佔用情況

接著我們當然是想看一看Metaspace區域的記憶體佔用情況了,簡單點你可以通過jstat來觀察,如果有監控系統,他會給你展示出來一個Metaspace記憶體區域佔用的波動曲線圖,類似下面這種。

 

記一次隱藏很深的 JVM 線上慘案的分析、排查、解決

 

 

看起來Metaspace區域的記憶體呈現一個波動的狀態,他總是會先不斷增加,達到一個頂點之後,就會把Metaspace區域給佔滿,然後自然就會觸發一次Full GC,Full GC會帶著Metaspace區域的垃圾回收,所以接下來Metaspace區域的記憶體佔用又變得很小了。

5、一個綜合性的分析思路

看到這裡,相信大家肯定有一點感覺了,這個很明顯是系統在執行過程中,不停的有新的類產生被載入到Metaspace區域裡去,然後不停的把Metaspace區域佔滿,接著觸發一次Full GC回收掉Metaspace區域中的部分類。

然後這個過程反覆的不斷的迴圈,進而造成Metaspace區域反覆被佔滿,然後反覆導致Full GC的發生,如下圖所示。

 

記一次隱藏很深的 JVM 線上慘案的分析、排查、解決

 

 

6、到底是什麼類不停的被載入?

接著我們就有點奇怪了,到底是什麼類不停的被載入到JVM的Metaspace區域裡去?

這個時候就需要在JVM啟動引數中加入如下兩個引數了:

“-XX:TraceClassLoading -XX:TraceClassUnloading”

這兩個引數,顧名思義,就是追蹤類載入和類解除安裝的情況,他會通過日誌打印出來JVM中載入了哪些類,解除安裝了哪些類。

加入這兩個引數之後,我們就可以看到在Tomcat的catalina.out日誌檔案中,輸出了一堆日誌,裡面顯示類似如下的內容:

【Loaded sun.reflect.GeneratedSerializationConstructorAccessor from __JVM_Defined_Class】

明顯可以看到,JVM在執行期間不停的載入了大量的所謂“GeneratedSerializationConstructorAccessor”類到了Metaspace區域裡去

如下圖所示

 

記一次隱藏很深的 JVM 線上慘案的分析、排查、解決

 

 

相信就是因為JVM執行期間不停的載入這種奇怪的類,然後不停的把Metaspace區域佔滿,才會引發不停的執行Full GC的。

這是一個非常實用的技巧,各位同學一定要掌握,頻繁Full GC不光是老年代觸發的,有時候也會因為Metaspace區域的類太多而觸發。

到此為止,已經慢慢接近真相了。

7、為什麼會頻繁載入奇怪的類?

接著遇到類似這種問題,我們就應該找一下Google或者是百度了,當然推薦是用Google。你完全可以看看那種不停載入的類,到底是什麼類,是你自己寫的類?還是說JDK內建的類?

比如上面的那個類,如果你查閱一些資料,很容易就會搞明白,那個類大概是在你使用Java中的反射時載入的,所謂反射程式碼類似如下所示。

Method method = XXX.class.getDeclaredMethod(xx,xx);

method.invoke(target,params);

友情提示一下,反射是Java中最最基礎的一個概念,不懂的朋友自己查一下資料。

簡單來說,就是通過XXX.class獲取到某個類,然後通過geteDeclaredMethod獲取到那個類的方法。

這個方法就是一個Method物件,接著通過Method.invoke可以去呼叫那個類的某個物件的方法,大概就這個意思。

在執行這種反射程式碼時,JVM會在你反射呼叫一定次數之後就動態生成一些類,就是我們之前看到的那種莫名其妙的類

下次你再執行反射的時候,就是直接呼叫這些類的方法,這是JVM的一個底層優化的機制。

看到這裡,有的小夥伴是不是有點蒙?

其實這倒無所謂,這段話看的蒙絲毫不影響你進行JVM優化的

你只要記住一個結論:如果你在程式碼裡大量用了類似上面的反射的東西,那麼JVM就是會動態的去生成一些類放入Metaspace區域裡的。

所以上面看到的那些奇怪的類,就是由於不停的執行反射的程式碼才生成的,如下圖所示。

 

記一次隱藏很深的 JVM 線上慘案的分析、排查、解決

 

 

8、JVM建立的奇怪類有什麼玄機?

那麼接下來我們就很奇怪一件事情,就是JVM為什麼要不停的建立那些奇怪的類然後放入Metaspace中去?

其實這就要從一個點入手來分析一下了,因為上面說的那種JVM自己建立的奇怪的類,他們的Class物件都是SoftReference,也就是軟引用的。

大家可千萬別說連類的Class是什麼都沒聽說過?簡單來說,每個類其實本身自己也是一個物件,就是一個Class物件,一個Class物件就代表了一個類。同時這個Class物件代表的類,可以派生出來很多例項物件。

舉例來說,Class Student,這就是一個類,他本身是由一個Class型別的物件表示的。

但是如果你走一個Student student = new Student(),這就是例項化了這個Student類的一個物件,這是一個Student型別的例項物件。

所以我們這裡所說的Class物件,就是JVM在發射過程中動態生成的類的Class物件,他們都是SoftReference軟引用的。

所謂的軟引用,最早我們再一篇文章裡說過,正常情況下不會回收,但是如果記憶體比較緊張的時候就會回收這些物件。

那麼SoftReference物件到底在GC的時候要不要回收是通過什麼公式來判斷的呢?

是如下的一個公式:

clock - timestamp <= freespace * SoftRefLRUPolicyMSPerMB

這個公式的意思就是說,“clock - timestamp”代表了一個軟引用物件他有多久沒被訪問過了,freespace代表JVM中的空閒記憶體空間,SoftRefLRUPolicyMSPerMB代表每一MB空閒記憶體空間可以允許SoftReference物件存活多久。

舉個例子,假如說現在JVM建立了一大堆的奇怪的類出來,這些類本身的Class物件都是被SoftReference軟引用的。

然後現在JVM裡的空間記憶體空間有3000MB,SoftRefLRUPolicyMSPerMB的預設值是1000毫秒,那麼就意味著,此時那些奇怪的SoftReference軟引用的Class物件,可以存活3000 * 1000 = 3000秒,就是50分鐘左右。

當然上面都是舉例而已,大家都知道,一般來說發生GC時,其實JVM內部或多或少總有一些空間記憶體的,所以基本上如果不是快要發生OOM記憶體溢位了,一般軟引用也不會被回收。

所以大家就知道了,按理說JVM應該會隨著反射程式碼的執行,動態的建立一些奇怪的類,他們的Class物件都是軟引用的,正常情況下不會被回收,但是也不應該快速增長才對。

9、為什麼JVM建立的奇怪的類會不停的變多?

那麼究竟為什麼JVM建立的那些奇怪的類會不停的變多呢?

原因很簡單,因為文章開頭那個新手工程師不知道從哪裡扒出來了SoftRefLRUPolicyMSPerMB這個JVM啟動引數,他直接把這個引數設定為0了。

他想的是,一旦這個引數設定為0,任何軟引用物件就可以儘快釋放掉,不用留存,儘量給記憶體釋放空間出來,這樣不就可以提高記憶體利用效率了麼?

真是想的很傻很天真。

實際上一旦這個引數設定為0之後,直接導致clock - timestamp <= freespace * SoftRefLRUPolicyMSPerMB這個公式的右半邊是0,就導致所有的軟引用物件,比如JVM生成的那些奇怪的Class物件,剛創建出來就可能被一次Young GC給帶著立馬回收掉一些。

如下圖所示。

 

記一次隱藏很深的 JVM 線上慘案的分析、排查、解決

 

 

比如JVM好不容易給你弄出來100個奇怪的類,結果因為你瞎設定軟引用的引數,導致突然一次GC就給你回收掉幾十個類

接著JVM在反射程式碼執行的過程中,就會繼續建立這種奇怪的類,在JVM的機制之下,會導致這種奇怪類越來越多。

也許下一次gc又會回收掉一些奇怪的類,但是馬上JVM還會繼續生成這種類,最終就會導致Metaspace區域被放滿了,一旦Metaspace區域被佔滿了,就會觸發Full GC,然後回收掉很多類,接著再次重複上述迴圈,如下圖所示。

 

記一次隱藏很深的 JVM 線上慘案的分析、排查、解決

 

 

其實很多人會有一個疑問,到底為什麼軟引用的類因為錯誤的引數設定被快速回收之後,就會導致JVM不停建立更多的新的類呢?

其實大家不用去扣這裡的細節,這裡有大量的底層JDK原始碼的實現,異常複雜,要真的說清楚,得好幾篇文章才能講清楚JDK底層原始碼的這些細節。

大家只要記住這個結論,明白這個道理就好。

10、如何解決這個問題?

雖然底層JDK的一些實現細節我們沒分析,但是大致梳理出來了一個思路,大家也很清楚問題所在和原因了

解決方案很簡單。在有大量反射程式碼的場景下,大家只要把

-XX:SoftRefLRUPolicyMSPerMB=0

這個引數設定大一些即可,千萬別讓一些新手同學設定為0,可以設定個1000,2000,3000,或者5000毫秒,都可以。

提高這個數值,就是讓反射過程中JVM自動建立的軟引用的一些類的Class物件不要被隨便回收,當時我們優化這個引數之後,就可以看到系統穩定運行了。

基本上Metaspace區域的記憶體佔用是穩定的,不會來回大幅度波動了。

11、今日思考題

大家思考一下這個線上事故的本質是什麼?

其實說白了不是JVM的問題,是人的問題。

大家可以考慮一下,如果你是公司的架構師,是否應該嚴格稽核各個系統的生產環境JVM引數?

比如完全可以推行一套JVM引數模板,如果有人要做定製的JVM優化,是不是應該先在測試環嘗試一下,然後還得交給你們高級別的架構師來稽核?

如果有人稽核,那麼就不會發生類似