問題描述
- 應(yīng)用收到頻繁Full GC告警
問題排查
- 登錄到對應(yīng)機器上去，查看GC日志恰响，發(fā)現(xiàn)YGC一分鐘已經(jīng)達到了15次凫佛，比Full GC還要頻繁一些语婴，其中Full GC平均10分鐘超過了4次，如下圖
image - 使用jstat -gcutil 5280 1000查看實時GC情況溶握，年老代采用的是CMS收集器杯缺，發(fā)現(xiàn)觸發(fā)Full GC的原因是年老代占用空間達到指定閾值70%（-XX:CMSInitiatingOccupancyFraction=70）。
- 這時候猜測是某個地方頻繁創(chuàng)建對象導(dǎo)致睡榆，通過
jmap -dump:format=b,file=temp.dump 5280dump文件萍肆，然后下載到本地通過jvisualvm分析對象的引用鏈的方式來定位具體頻繁創(chuàng)建對象的地方袍榆，dump文件下載下來有5G多，整個導(dǎo)入過程都花了10多分鐘塘揣。想查看所占空間較多對象的引用鏈包雀，直接OOM了，dump對象太大了亲铡。這時候就換了種思路馏艾，查看占用空間比較大的一系列對象，看能不能找出什么端倪奴愉。占用空間最大的幾類對象如下圖
image
發(fā)現(xiàn)排第一的chart[]對象里面琅摩，存在一些metrics監(jiān)控的具體指標(biāo)的相關(guān)內(nèi)容，排第二的io.prometheus.client.Collector$MetricFamilySample$Sample和排第9和第13對象都是spring boot中metrics指標(biāo)監(jiān)控相關(guān)的對象锭硼，所以此時懷疑metrics監(jiān)控的某個地方在頻繁創(chuàng)建對象房资，首先考慮的是否因為metrics指標(biāo)太多導(dǎo)致的，于是登錄線上機器curl localhost:8080/mertrics > metrics.log檀头，發(fā)現(xiàn)響應(yīng)內(nèi)容有50多M轰异，參考其他相關(guān)的正常應(yīng)用，指標(biāo)總共內(nèi)容也就10多M左右暑始，打開指標(biāo)內(nèi)容發(fā)現(xiàn)了很多類似如下圖的指標(biāo)
image
看到了這里已經(jīng)可以確定代碼中上報這個指標(biāo)是存在問題的搭独，并沒有達到我們想要的效果，所以也懷疑也是這個地方導(dǎo)致的Full GC頻繁廊镜。
問題初步解決
- 由于這個指標(biāo)也無關(guān)緊要牙肝，初步解決方案就把上報該指標(biāo)的代碼給干掉。上線后看下Full GC問題是否會得到改善嗤朴，果然配椭，上線后Full GC告警問題已經(jīng)解決。
初步解決后的思考雹姊，為什么會有這個問題股缸？
- 外部監(jiān)控系統(tǒng)，每25s會來調(diào)用metrics這個接口吱雏，這個接口會把所有的metrics指標(biāo)轉(zhuǎn)成字符串然后作為http響應(yīng)內(nèi)容響應(yīng)敦姻。監(jiān)控每來調(diào)用一次就會產(chǎn)生一個50多M的字符串，導(dǎo)致了頻繁YGC歧杏，進而導(dǎo)致了晉升至年老代的對象也多了起來镰惦，最終年老代內(nèi)存占用達到70%觸發(fā)了Full GC。
根源問題重現(xiàn)
- 此處采用metrics的作用：統(tǒng)計線程池執(zhí)行各類任務(wù)的數(shù)量得滤。為了簡化代碼陨献，用一個map來統(tǒng)計，重現(xiàn)代碼如下
import java.util.Map;
import java.util.concurrent.*;
import java.util.concurrent.atomic.AtomicInteger;
/**
* 線程池通過submit方式提交任務(wù)懂更，會把Runnable封裝成FutureTask眨业。
* 直接導(dǎo)致了Runnable重寫的toString方法在afterExecute統(tǒng)計的時候沒有起到我們想要的作用急膀，
* 最終導(dǎo)致幾乎每一個任務(wù)（除非hashCode相同）就按照一類任務(wù)進行統(tǒng)計。所以這個metricsMap會越來越大龄捡，調(diào)用metrics接口的時候卓嫂，會把該map轉(zhuǎn)成一個字符返回
*/
public class GCTest {
/**
* 統(tǒng)計各類任務(wù)已經(jīng)執(zhí)行的數(shù)量
* 此處為了簡化代碼，只用map來代替metrics統(tǒng)計
*/
private static Map<String, AtomicInteger> metricsMap = new ConcurrentHashMap<>();
public static void main(String[] args) throws InterruptedException {
ThreadPoolExecutor threadPoolExecutor = new ThreadPoolExecutor(10, 10, 0, TimeUnit.SECONDS, new LinkedBlockingQueue<>()){
/**
* 統(tǒng)計各類任務(wù)執(zhí)行的數(shù)量
* @param r
* @param t
*/
@Override
protected void afterExecute(Runnable r, Throwable t) {
super.afterExecute(r, t);
metricsMap.compute(r.toString(), (s, atomicInteger) ->
new AtomicInteger(atomicInteger == null ? 0 : atomicInteger.incrementAndGet()));
}
};
/**
* 源源不斷的任務(wù)添加進線程池被執(zhí)行
*/
for (int i =0; i < 1000; i++) {
threadPoolExecutor.submit(new SimpleRunnable());
}
Thread.sleep(1000 * 2);
System.out.println(metricsMap);
threadPoolExecutor.shutdownNow();
}
static class SimpleRunnable implements Runnable{
@Override
public void run() {
System.out.println("SimpleRunnable execute success");
}
/**
* 重寫toString用于統(tǒng)計任務(wù)數(shù)
* @return
*/
@Override
public String toString(){
return this.getClass().getSimpleName();
}
}
}
最終解決
- 把submit改成execute即可
總結(jié)
- 以上重顯代碼可以看出metricsMap中的元素是會越來越多的聘殖。如果就這樣下去晨雳，最終的結(jié)果也會出現(xiàn)OOM。
- 根本原因還是對ThreadPoolExecutor不夠熟悉奸腺，所以出現(xiàn)了這次問題餐禁。
- 個人感覺Full GC類問題是比較讓人頭疼的。這些問題并不會想代碼語法問題一樣突照，ide會提示我們具體錯在哪里帮非，我們只要修改對應(yīng)地方基本都能解決。造成Full GC頻繁的原因也有很多讹蘑，比如可能是jvm參數(shù)設(shè)置不合理末盔、Metaspace空間觸發(fā)、頻繁創(chuàng)建對象觸發(fā)等等座慰。
- 如果確定了是頻繁創(chuàng)建對象導(dǎo)致陨舱，那么接下來的目的就是確定頻繁創(chuàng)建對象的對應(yīng)代碼處，這時候可以選擇通過dump線上堆棧版仔，然后下載到本地游盲。選擇一些可視化分析工具進行分析。最終定位到出問題的代碼處邦尊，然后解決問題背桐。
版權(quán)聲明
作者：wycm
github：https://github.com/wycm
出處：http://www.reibang.com/p/3f7a4d33b121
您的支持是對博主最大的鼓勵，感謝您的認真閱讀蝉揍。
本文版權(quán)歸作者所有，歡迎轉(zhuǎn)載畦娄，但未經(jīng)作者同意必須保留此段聲明又沾，且在文章頁面明顯位置給出原文連接，否則保留追究法律責(zé)任的權(quán)利熙卡。
