一次頻繁Full GC問題排查過程分享

時間 2019-11-19

標籤一次頻繁問題排查過程分享欄目 Java 简体版

原文原文鏈接

問題描述

應用收到頻繁Full GC告警

問題排查

登陸到對應機器上去，查看GC日誌，發現YGC一分鐘已經達到了15次，比Full GC還要頻繁一些，其中Full GC平均10分鐘超過了4次，以下圖
使用jstat -gcutil 5280 1000查看實時GC狀況，年老代採用的是CMS收集器，發現觸發Full GC的緣由是年老代佔用空間達到指定閾值70%（-XX:CMSInitiatingOccupancyFraction=70）。
這時候猜想是某個地方頻繁建立對象致使，經過jmap -dump:format=b,file=temp.dump 5280 dump文件，而後下載到本地經過jvisualvm分析對象的引用鏈的方式來定位具體頻繁建立對象的地方，dump文件下載下來有5G多，整個導入過程都花了10多分鐘。想查看所佔空間較多對象的引用鏈，直接OOM了，dump對象太大了。這時候就換了種思路，查看佔用空間比較大的一系列對象，看能不能找出什麼端倪。佔用空間最大的幾類對象以下圖

發現排第一的chart[]對象裏面，存在一些metrics監控的具體指標的相關內容，排第二的io.prometheus.client.Collector$MetricFamilySample$Sample和排第9和第13對象都是spring boot中metrics指標監控相關的對象，因此此時懷疑metrics監控的某個地方在頻繁建立對象，首先考慮的是否由於metrics指標太多致使的，因而登陸線上機器curl localhost:8080/mertrics > metrics.log，發現響應內容有50多M，參考其餘相關的正常應用，指標總共內容也就10多M左右，打開指標內容發現了不少相似以下圖的指標

看到了這裏已經能夠肯定代碼中上報這個指標是存在問題的，並無達到咱們想要的效果，因此也懷疑也是這個地方致使的Full GC頻繁。html

問題初步解決
因爲這個指標也可有可無，初步解決方案就把上報該指標的代碼給幹掉。上線後看下Full GC問題是否會獲得改善，果真，上線後Full GC告警問題已經解決。java

初步解決後的思考，爲何會有這個問題？

外部監控系統，每25s會來調用metrics這個接口，這個接口會把全部的metrics指標轉成字符串而後做爲http響應內容響應。監控每來調用一次就會產生一個50多M的字符串，致使了頻繁YGC，進而致使了晉升至年老代的對象也多了起來，最長年老代內存佔用達到70%觸發了Full GC。

根源問題重現

此處採用metrics的做用：統計線程池執行各種任務的數量。爲了簡化代碼，用一個map來統計，重現代碼以下

import java.util.Map;
    import java.util.concurrent.*;
    import java.util.concurrent.atomic.AtomicInteger;
    
    /**
     * 線程池經過submit方式提交任務，會把Runnable封裝成FutureTask。
     * 直接致使了Runnable重寫的toString方法在afterExecute統計的時候沒有起到咱們想要的做用，
     * 最終致使幾乎每個任務（除非hashCode相同）就按照一類任務進行統計。因此這個metricsMap會愈來愈大，調用metrics接口的時候，會把該map轉成一個字符返回
     */
    public class GCTest {
        /**
         * 統計各種任務已經執行的數量
         * 此處爲了簡化代碼，只用map來代替metrics統計
         */
        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<>()){
                /**
                 * 統計各種任務執行的數量
                 * @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()));
                }
            };
            /**
             * 源源不斷的任務添加進線程池被執行
             */
            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用於統計任務數
             * @return
             */
            @Override
            public String toString(){
                return this.getClass().getSimpleName();
            }
        }
    }

最終解決

能夠把submit改爲execute便可

總結

以上重顯代碼能夠看出metricsMap中的元素是會愈來愈多的。若是就這樣下去，最終的結果也會出現OOM。
根本緣由仍是對ThreadPoolExecutor不夠熟悉，因此出現了此次問題。
我的感受Full GC類問題是比較讓人頭疼的。這些問題並不會想代碼語法問題同樣，ide會提示咱們具體錯在哪裏，咱們只要修改對應地方基本都能解決。形成Full GC頻繁的緣由也有不少，好比多是jvm參數設置不合理、Metaspace空間觸發、頻繁建立對象觸發等等。
若是肯定了是頻繁建立對象致使，那麼接下來的目的就是肯定頻繁建立對象的對應代碼處，這時候能夠選擇經過dump線上堆棧，而後下載到本地。選擇一些可視化分析工具進行分析。最終定位到出問題的代碼處，而後解決問題。

版權聲明
做者：wycm
出處：https://www.cnblogs.com/w-y-c-m/p/9919717.html
您的支持是對博主最大的鼓勵，感謝您的認真閱讀。
本文版權歸做者全部，歡迎轉載，但未經做者贊成必須保留此段聲明，且在文章頁面明顯位置給出原文鏈接，不然保留追究法律責任的權利。
程序員