JVM的GC日志記錄實例分析

本文小編為大家詳細介紹“JVM的GC日志記錄實例分析”，內容詳細，步驟清晰，細節處理妥當，希望這篇“JVM的GC日志記錄實例分析”文章能幫助大家解決疑惑，下面跟著小編的思路慢慢深入，一起來學習新知識吧。

Java應用的GC評估

可能大多數程序員在開發完某個需求之后，往線上環境一丟，然后就基本不怎么關注后續的變化了。但是是否有考慮過，這些新引入的代碼會對原有系統造成的影響呢？下邊我們通過一段實戰來帶各位讀者較好地去深入理解這個過程。

模擬場景

有一個應用程序（暫且稱呼為moment服務）準備在小程序上開展社交動態推送功能，大概就是每次用戶刷新頁面時候便會按照一定規則推送出20條用戶動態數據。由于該產品的c端用戶數量比較多，于是便在上線該產品之前進行了相應的壓測，判斷該功能的承載能力。

在壓測開始的初期，接口響應速度都還可以，但是漸漸地開始加壓的時候，發現程序出現了OOM。經過排查后，排除數據庫層的問題。于是開始懷疑是否是Java應用內部出現了異常。

應用的啟動參數：

java
 -Xmx1512m
 -Xms1512m
 -Xmn1024m 
 -XX:+UseConcMarkSweepGC 
 -XX:+UseParNewGC  
 -XX:+HeapDumpOnOutOfMemoryError  
 -XX:+PrintGCDetails 
 -XX:+PrintGCTimeStamps 
 -Xloggc:log/gc.log 
 -jar qiyu-framework-demo-jvm.jar

單節點壓測，壓力測試10w次請求，1000并發。使用ab工具進行壓力測試：

ab -n100000 -c1000 http://localhost:8080/user/batch-query

jstat 查看GC，每隔5秒打印一次，持續20次

jstat -gc 5673 5000 20

經過一段時間的施壓，在施壓的持續了1分鐘之后，YGC的頻率讓人感覺著實有些高。通常一個健康的系統ygc應該是20-30min左右一次，full gc可能是好幾周才一次。

通過jstat可以看出，年輕代的gc會比較頻繁，并且停頓時間嚴重影響了正常的業務使用。為了得到更加精準的數據，我嘗試將gc日志放到GCeasy工具上進行可視化分析：

這是一款非常不錯的gc日志分析工具

https://www.gceasy.io/

GC日志的可視化分析

首先是JVM內存中的占用分析，很清晰地可以看出，年輕代的內存和老年代的內存幾乎占滿，元空間基本沒有變動過。

然后是整個系統的GC耗時分析：

從整體來看，大部分的GC耗時都是在0-100ms內，極端情況下的GC耗時可能會達到700ms。

接下來是看看GC回收對堆內存整體的一個影響。觀測發現，基本每次GC都能夠回收達改200mb左右的內存。

再繼續分析，可以發現CMS回收器在回收的各個階段中所消耗的時間：初始標記，并發標記，修正標記，并發清除

除了單純分析GC回收的耗時之外，這款工具還有個非常贊的功能，可以幫助我們分析這段時間內，該Java程序產生對象的速率：

可以發現，一秒大概要產生445mb的對象，大概一秒就會有2.5mb對象晉升到老年代。

內存逃逸分析沒有發現異常記錄。

通過對這份報告分析完畢之后，我的第一直覺告訴我，年輕代不足，需要對年輕代內存進行增加。但是仔細觀察下，產生對象的速率竟然高達445mb/s，這感覺非常不正常啊，極度懷疑是程序內部存在大對象的情況。

于是嘗試使用jvisualVM這款工具進行深入分析，通過對CPU樣例的監控，發現了一些異常信息：

似乎這個方法對CPU的消耗比較高，接著是內存的一個監控：

此時大概可以定位出異常方法所在的位置了，接下來便是對系統內部的業務代碼進行分析了。

最后排查結果發現，其實是系統內部的一個方法調用，加載了5k個User對象到內存中做計算，而每個User對象里存放了一個大小為1kb的byte數組。大概的代碼邏輯為：

于是便需要從業務層面對該方法進行優化，例如調小5k這個數值，同時對User對象內的byte數組進行過濾（因為實際使用不到這個字段）。

調整后發現GC的頻率降低了許多，比較正常。

讀到這里，這篇“JVM的GC日志記錄實例分析”文章已經介紹完畢，想要掌握這篇文章的知識點還需要大家自己動手實踐使用過才能領會，如果想了解更多相關內容的文章，歡迎關注億速云行業資訊頻道。