JVM內存GC的騙局——JVM不拋出OOM但內存已經泄露

概述

在平常測試中，咱們會去重點觀察java的內存使用狀況，好比：進程會拋出OOM異常，再也不接收新的請求；響應時間在固定時間段內變長，超時或者不響應，CPU使用率時常像過山車同樣等。有時候JVM還會發生欺騙你的場景， JVM不停的在垃圾回收，但是每次回收完後堆卻仍是滿的，很明顯程序內存被使用完了，已經沒法正常工做了，但JVM就是不拋出OutOfMemoryError(OOM)這個異常來告訴程序員內部發出了什麼，只是不停的作老好人嘗試幫咱們作垃圾回收，把服務器的資源耗光了，可是此時服務器已經沒法響應用戶的正常請求了，讓咱們一塊兒來看看這些狀況發生時候的現象，體會一下被欺騙的感受。

現狀：

       同事在模擬用戶不停的發送請求給某系統，在運行一段時間後，忽然，系統上郵件報告測試用例請求失敗，登陸測試系統的服務器，首先看下JVM的參數設置，以下：

-server –Xms4g –Xmx4g -XX:MaxPermSize=256m  -verbose:gc -XX:+PrintGCDetails -Xloggc:$CATALINA_BASE/logs/gc.log -XX:+PrintGCTimeStamp，再使用TOP命令看看服務器發生了什麼。

觀察一段時間後，CPU一直運行在100%，因而想固然的認爲多是那段程序裏面觸發了BUG,有多是正則表達式或者某段代碼裏面有個死循環的坑跳進去，沒有出來。這不是很簡單的事嗎？直接使用jstack + pid 把堆棧打出來便可，直接操做吧，界面上立刻輸出操做日誌，因爲日誌過多而且其餘的日誌相似，幫只截取部分以下：

從上面的堆棧日誌能夠看出，全部的線程都被BLOCKED住了，而後堆棧裏面也找不到任何業務的相關代碼，難道直覺出錯了，感受一會兒不太好了，可是至少能夠排查到不是上面的二種緣由了，好吧，那再看看應用的GC的狀況，部分日誌以下。

1403682.561: [GC [PSYoungGen: 1375104K->11376K(1386176K)] 4145665K->2782002K(4182400K), 0.0174410 secs] [Times: user=0.27 sys=0.00, real=0.02 secs]

1407799.743: [GC [PSYoungGen: 1386160K->11632K(1386432K)] 4156786K->2793538K(4182656K), 0.0285330 secs] [Times: user=0.48 sys=0.00, real=0.03 secs]

1409230.024: [GC [PSYoungGen: 1386416K->10688K(1377984K)] 4168322K->2803822K(4174208K), 0.0265000 secs] [Times: user=0.43 sys=0.00, real=0.02 secs]

1409230.051: [Full GC [PSYoungGen: 10688K->7014K(1377984K)] [PSOldGen: 2793134K->2796224K(2796224K)] 2803822K->2803238K(4174208K) [PSPermGen: 48439K->48439K(262144K)], 7.8892780 secs] [Times: user=7.92 sys=0.00, real=7.89 secs]

1410502.582: [Full GC [PSYoungGen: 1366336K->85344K(1377984K)] [PSOldGen: 2796224K->2796224K(2796224K)] 4162560K->2881568K(4174208K) [PSPermGen: 48577K->48577K(262144K)], 8.2720110 secs] [Times: user=8.29 sys=0.00, real=8.27 secs]

 

解釋一下：

第一行：
1403682.561: [GC [PSYoungGen: 1375104K->11376K(1386176K)] 4145665K->2782002K(4182400K), 0.0174410 secs] [Times: user=0.27 sys=0.00, real=0.02 secs]

發生的時間點，：JVM運行的時間長度，以度爲單位，也能夠格式化成固定的時間格式

PSYoungGen：發生了何種類型的GC，此處表明發生了年輕代的GC

1375104K：回收前的大小

11376K：回收後的大小

1386176K：YOUNG代的大小

4145665 K：回收前總的佔用大小

2782002K：回收後的佔用大小

4182400K：總佔用大小

0.27和0.00：表明在用戶態(user)和系統狀(sys)的CPU運行時間

0.02 secs：表明實際的GC的運行時間

注：上面總的運行時間小於用戶態和系統態的時間總和，是因爲後者僅指CPU的運行時間，包括等待或IO阻塞的時間，並且如今的GC是採用多線程收集的，同時機器也是多個CPU，所以，大部分是兩者之和要比前面的值大，若是是採用串形化收集器( serial collector)的話，兩者時間幾乎相差很少。關於各類收集器的差異，後續有時間再安排詳細總結。

接下來的二行，再也不重複說明，第四行有Full字樣，表明JVM發生了Full GC，不過多了二個分區的收集，PSOldGen：老生代的回收先後空間大小及總空間；PSPermGen：持久代的回收先後空間大小和總空間。從第三行，能夠看出老空間的使用率達到飽和，從而觸發了FULL GC，可是很遺憾的是第五行後又接着發生了FULL GC，後面的都是一直在持續進行，可是系統一直不拋出OOM異常或者進程退出，致使這臺機器服務進程一直存在，可是基本沒法正常工做。

GC，不管Young GC仍是Full GC，每次都會致使JVM STW(STOP WORLD)暫停用戶的業務工做，來處理垃圾回收任務，短期內沒法響應用戶請求，特別是大量的Full GC會致使系統響應速度下降，另外還有OOM的巨大風險。Young GC頻繁，就算GC採用多線程回收方式，儘管回收的時候很是短，可是若是GC次數和頻率很高，所以對應用的影響是不可忽視的。 Full GC 包括整個分區的垃圾回收，包括新生代、舊生代、持久代等。所以其回收成本高，應用也會暫停更長時間，沒法及時響應用戶的請求，因此須要特別注意這個種狀況，通常來說，排除主動的調用GC操做外，JVM會在如下幾種狀況發生Full GC。  

1. 舊生代內存不足

2. 持久代內存不足

3. 統計新生代 GC晉升到舊生代的平均大小大於舊生代的剩餘空間

  

解決

       知道發生的緣由後，就可使用JMAP -heap直接看一下JVM內存的對像值，或者使用JMAP -dump直接JVM的堆棧DUMP出來，使用MAT打開分析就行。若是這種現像發生以後，DUMP出來的文件會較大，有些會達到十多個G，由於通常不直接在工做機器上進行，須要把文件轉發到其餘的非線上服務而且內存足夠的機器上分析，最後能夠用MAT把分析後的文件打開便可，操做結果以下：

第四行裏面看不出實際的業務相關的，第五行到六行仍是能夠看出來的，那就先看第四行的對象包括什麼具體的實例吧。

打開後，首頁會給出可疑的建議對象實例，直接跳轉到列表中，打開摺疊細節便可看到真面目，裏面包括了三十多萬個對象，找相關的人員對根據業務須要，直接把不須要的實例在使用完後移除，其餘幾行的問題相似處理就便可。

總結

       從上面GC的發生的狀況來看，JVM一次次不停的努力的幫咱們進行GC操做，直接把CPU所有佔光，可是就是不直接拋出異常直接告訴咱們內存不夠了，感受把咱們帶了到一個巨大的龐氏騙局，也許咱們把JVM的內存加大，這個坑還將幫咱們隱藏下去，若是程序設置了定時重啓之類的操做，這個坑就永遠發現不了。通常產品開發人員很是但願應用程序能在用戶發覺以前發現這個問題，JVM沒法判斷出這個問題，也就不能幫咱們拋出幾乎OOM的異常，不過能夠經過調整GCTimeLimit和GCHeapFreeLimit參數來從新定義什麼時候拋出OutOfMemoryError錯誤。GCTimeLimit 的默認值是98%，也就是說若是98%時間都用花在GC上，則會拋出OutOfMemoryError。GCHeapFreeLimit 是回收後可用堆的大小。默認值是2%。固然最好的辦法就是開發工程師開始就很清楚如何使用相關的容器類的正確用法，而且在上線前能通過充分的測試或運行。本文只是引用GC方面的一個具體的安全來講明GC是怎麼騙人的，關於GC和JVM內存相關的細節如何及時的發現此類的問題，有機會再經過示例和你們探討學習。

 

注：以上資料僅以HOTSPOT VM 1.7.65 版本參考。

 

 

本文章爲做者原創

🈲禁止🈲

其餘公衆帳號轉載，如有轉載，請標明出處