快捷導(dǎo)航

JVM完全解讀之GC日志記錄分析

更新時(shí)間：2022年01月24日 15:28:41 作者：Idea的技術(shù)分享

這篇文章主要介紹了JVM完全解讀之GC日志記錄分析，有需要的朋友可以借鑒參考下，希望能夠有所幫助，祝大家多多進(jìn)步

相信大家在系統(tǒng)學(xué)習(xí)jvm的時(shí)候都會(huì)有遇到過這樣的問題，散落的jvm知識(shí)點(diǎn)知道很多，但是真正在線上環(huán)境遇到一些莫名其妙的gc異常時(shí)候卻無從下手去分析。

關(guān)于這塊的苦我也表示能夠理解，之前光是JVM相關(guān)的八股文就整理了許多，但是經(jīng)常是不知道如何在實(shí)戰(zhàn)中使用。最近也嘗試在模擬一些案例來訓(xùn)練自己的JVM相關(guān)知識(shí)，本文特意記錄下這段調(diào)優(yōu)經(jīng)歷。

Java應(yīng)用的GC評(píng)估

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

模擬場景

有一個(gè)應(yīng)用程序（暫且稱呼為moment服務(wù)）準(zhǔn)備在小程序上開展社交動(dòng)態(tài)推送功能，大概就是每次用戶刷新頁面時(shí)候便會(huì)按照一定規(guī)則推送出20條用戶動(dòng)態(tài)數(shù)據(jù)。由于該產(chǎn)品的c端用戶數(shù)量比較多，于是便在上線該產(chǎn)品之前進(jìn)行了相應(yīng)的壓測，判斷該功能的承載能力。

在壓測開始的初期，接口響應(yīng)速度都還可以，但是漸漸地開始加壓的時(shí)候，發(fā)現(xiàn)程序出現(xiàn)了OOM。經(jīng)過排查后，排除數(shù)據(jù)庫層的問題。于是開始懷疑是否是Java應(yīng)用內(nèi)部出現(xiàn)了異常。

應(yīng)用的啟動(dòng)參數(shù)：

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

單節(jié)點(diǎn)壓測，壓力測試10w次請(qǐng)求，1000并發(fā)。使用ab工具進(jìn)行壓力測試：

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

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

jstat -gc 5673 5000 20

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

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

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

https://www.gceasy.io/

GC日志的可視化分析

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

然后是整個(gè)系統(tǒng)的GC耗時(shí)分析：

從整體來看，大部分的GC耗時(shí)都是在0-100ms內(nèi)，極端情況下的GC耗時(shí)可能會(huì)達(dá)到700ms。

接下來是看看GC回收對(duì)堆內(nèi)存整體的一個(gè)影響。觀測發(fā)現(xiàn)，基本每次GC都能夠回收達(dá)改200mb左右的內(nèi)存。

再繼續(xù)分析，可以發(fā)現(xiàn)CMS回收器在回收的各個(gè)階段中所消耗的時(shí)間：初始標(biāo)記，并發(fā)標(biāo)記，修正標(biāo)記，并發(fā)清除

除了單純分析GC回收的耗時(shí)之外，這款工具還有個(gè)非常贊的功能，可以幫助我們分析這段時(shí)間內(nèi)，該Java程序產(chǎn)生對(duì)象的速率：

可以發(fā)現(xiàn)，一秒大概要產(chǎn)生445mb的對(duì)象，大概一秒就會(huì)有2.5mb對(duì)象晉升到老年代。

內(nèi)存逃逸分析沒有發(fā)現(xiàn)異常記錄。

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

于是嘗試使用jvisualVM這款工具進(jìn)行深入分析，通過對(duì)CPU樣例的監(jiān)控，發(fā)現(xiàn)了一些異常信息：

似乎這個(gè)方法對(duì)CPU的消耗比較高，接著是內(nèi)存的一個(gè)監(jiān)控：

此時(shí)大概可以定位出異常方法所在的位置了，接下來便是對(duì)系統(tǒng)內(nèi)部的業(yè)務(wù)代碼進(jìn)行分析了。

最后排查結(jié)果發(fā)現(xiàn)，其實(shí)是系統(tǒng)內(nèi)部的一個(gè)方法調(diào)用，加載了5k個(gè)User對(duì)象到內(nèi)存中做計(jì)算，而每個(gè)User對(duì)象里存放了一個(gè)大小為1kb的byte數(shù)組。大概的代碼邏輯為：