概述
在日常測試中，我們會去重點觀察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 版本參考。
本文章為作者原創
🈲禁止🈲
其他公眾賬號轉載，若有轉載，請標明出處
文章列表
留言列表
