JVM記憶體GC的騙局

網易雲社群發表於2018-10-30
JVM記憶體GC

此文已由作者堯飄海授權網易雲社群釋出。

歡迎訪問網易雲社群，瞭解更多網易技術產品運營經驗。



概述

在日常程式開發中，很多JAVA程度員不太關心記憶體的使用情況。當然，如果程式設計師運氣較好或者系統沒有大規模的被測試或者被使用者使用時，這個問題或許永遠不出現，使得程式設計師一直認為記憶體反正是無限的，可以一直使用。確實，JVM的垃圾回收器會幫我們處理好所有的事情，可如果運氣不是那麼好，不幸就有可能發生在我們的身上，比如：程式會丟擲OOM異常，不再接收新的請求；響應時間在固定時間段內變長，超時或者不響應，CPU使用率時常像過山車一樣等。記憶體使用在大部分的工作時間可以正常工作，這樣會導致很多的人對JAVA應用的記憶體使用情況不明瞭或者得不到充分的效能測試，而導致程式無法正常工作。出現上面的情況程式設計師一般會比較好的較快的發現問題或能總結一定的規律。


問題

有時候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命令看看伺服器發生了什麼。

JVM記憶體GC的騙局


觀察一段時間後，CPU一直執行在100%，於是想當然的認為可能是那段程式裡面觸發了BUG,有可能是正規表示式或者某段程式碼裡面有個死迴圈的坑跳進去，沒有出來。這不是很簡單的事嗎？直接使用jstack + pid 把堆疊打出來即可，直接操作吧，介面上馬上輸出操作日誌，由於日誌過多並且其他的日誌類似，幫只擷取部分如下：

JVM記憶體GC的騙局

從上面的堆疊日誌可以看出，所有的執行緒都被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把分析後的檔案開啟即可，操作結果如下：

JVM記憶體GC的騙局

第四行裡面看不出實際的業務相關的，第五行到六行還是可以看出來的，那就先看第四行的物件包括什麼具體的例項吧。

JVM記憶體GC的騙局

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


總結

從上面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 版本參考。

參考資料：

JVM http://docs.oracle.com/javase/8/docs/technotes/guides/vm/gc-ergonomics.html

HotSpot JVM就是個龐氏騙局 http://it.deepinmind.com/gc/2014/04/01/hotspot-jvm-ponzi-scheme.html

Java記憶體洩露分析 doc.hz.netease.com/pages/viewp…


免費體驗雲安全(易盾)內容安全、驗證碼等服務

更多網易技術、產品、運營經驗分享請點選。


相關文章：
【推薦】 使用者體驗從業者需瞭解的兩大商業分析工具—BusinessModelCanvas和AARRR模型
【推薦】 Jmeter壓測Thrift服務介面


相關文章