JVM的GC日志記錄實(shí)例分析

本文小編為大家詳細(xì)介紹“JVM的GC日志記錄實(shí)例分析”，內(nèi)容詳細(xì)，步驟清晰，細(xì)節(jié)處理妥當(dāng)，希望這篇“JVM的GC日志記錄實(shí)例分析”文章能幫助大家解決疑惑，下面跟著小編的思路慢慢深入，一起來(lái)學(xué)習(xí)新知識(shí)吧。

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

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

模擬場(chǎng)景

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

在壓測(cè)開(kāi)始的初期，接口響應(yīng)速度都還可以，但是漸漸地開(kāi)始加壓的時(shí)候，發(fā)現(xiàn)程序出現(xiàn)了OOM。經(jīng)過(guò)排查后，排除數(shù)據(jù)庫(kù)層的問(wèn)題。于是開(kāi)始懷疑是否是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)壓測(cè)，壓力測(cè)試10w次請(qǐng)求，1000并發(fā)。使用ab工具進(jìn)行壓力測(cè)試：

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

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

jstat -gc 5673 5000 20

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

通過(guò)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)存幾乎占滿，元空間基本沒(méi)有變動(dòng)過(guò)。

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

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

接下來(lái)是看看GC回收對(duì)堆內(nèi)存整體的一個(gè)影響。觀測(cè)發(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)存逃逸分析沒(méi)有發(fā)現(xiàn)異常記錄。

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

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

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

此時(shí)大概可以定位出異常方法所在的位置了，接下來(lái)便是對(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ù)組。大概的代碼邏輯為：

于是便需要從業(yè)務(wù)層面對(duì)該方法進(jìn)行優(yōu)化，例如調(diào)小5k這個(gè)數(shù)值，同時(shí)對(duì)User對(duì)象內(nèi)的byte數(shù)組進(jìn)行過(guò)濾（因?yàn)閷?shí)際使用不到這個(gè)字段）。

調(diào)整后發(fā)現(xiàn)GC的頻率降低了許多，比較正常。

讀到這里，這篇“JVM的GC日志記錄實(shí)例分析”文章已經(jīng)介紹完畢，想要掌握這篇文章的知識(shí)點(diǎn)還需要大家自己動(dòng)手實(shí)踐使用過(guò)才能領(lǐng)會(huì)，如果想了解更多相關(guān)內(nèi)容的文章，歡迎關(guān)注億速云行業(yè)資訊頻道。