一、驗證GC程式碼

 　　程式並不複雜，我們指定一個運行時間作為退出條件，時間一到自動退出迴圈。在 generateGarbage 方法中，我們用了隨機數來生成各種型別的陣列物件並返回。

　　在 main 方法中，我們用一個數組來隨機存放一部分生成的物件，這樣可以模擬讓部分物件晉升到老年代。具體的持續運行時間和快取物件個數，可以自己進行調整。

　　額外說一句：這個示例除了可以用來進行GC日誌分析之外，稍微修改一下，還可以用作其他用途：

　　　　比如讓快取的物件變多，在限制堆記憶體的情況下，就可以模擬 記憶體溢位 。

　　　　增加運行時長，比如加到30分鐘或者更長，我們就可以用前面介紹過的 VisualVM 等工具來實時監控和觀察。

　　　　當然，我們也可以使用全域性靜態變量來快取，用來模擬 記憶體洩漏 ，以及進行堆記憶體Dump的試驗和分析。

　　　　加大每次生成的陣列的大小，可以用來模擬 大物件/巨無霸物件 

import java.util.Random;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.LongAdder;

public class GCLogAnalysis {
    private static Random random = new Random();
    public static void
 
 main(String[] args) {
        // 當前毫秒時間戳
        long startMillis = System.currentTimeMillis();
        // 持續運行毫秒數; 可根據需要進行修改
        long timeoutMillis = TimeUnit.SECONDS.toMillis(1);
        // 結束時間戳
        long endMillis = startMillis + timeoutMillis;
        LongAdder counter = new LongAdder();
        System.
 
out.println("正在執行...");
        // 快取一部分物件; 進入老年代
        int cacheSize = 2000;
        Object[] cachedGarbage = new Object[cacheSize];
        // 在此時間範圍內,持續迴圈
        while (System.currentTimeMillis() < endMillis) {
            // 生成垃圾物件
            Object garbage = generateGarbage(100*1024);
            counter.increment();
            int randomIndex = random.nextInt(2 * cacheSize);
            if (randomIndex < cacheSize) {
                cachedGarbage[randomIndex] = garbage;
            }
        }
        System.out.println("執行結束!共生成物件次數:" + counter.longValue());
    }

    // 生成物件
    private static Object generateGarbage(int max) {
        int randomSize = random.nextInt(max);
        int type = randomSize % 4;
        Object result = null;
        switch (type) {
            case 0:
                result = new int[randomSize];
                break;
            case 1:
                result = new byte[randomSize];
                break;
            case 2:
                result = new double[randomSize];
                break;
            default:
                StringBuilder builder = new StringBuilder();
                String randomString = "randomString-Anything";
                while (builder.length() < randomSize) {
                    builder.append(randomString);
                    builder.append(max);
                    builder.append(randomSize);
                }
                result = builder.toString();
                break;
        }
        return result;
    }
}

 二、GC基礎配置

　　編譯和執行上述程式碼

conglongli@bogon exercise % javac -g GCLogAnalysis.java
conglongli@bogon exercise % java GCLogAnalysis
正在執行...
執行結束!共生成物件次數:10648 

　　因為沒有指定任何啟動引數，所以輸出的日誌內容也很簡單。

　　1、輸出GC日誌詳情

　　　　然後加上啟動引數 -XX:+PrintGCDetails ，列印GC日誌詳情，再次執行示例：

java -XX:+PrintGCDetails GCLogAnalysis

　　　　　　　　 

 　　PSYoungGen表示年輕代總空間及使用空間，中括號中的內容是記憶體地址資訊，同時還展示了年輕代中Eden、from、to三個區域的空間大小和使用率；ParOldGen表示老年代，展示了老年代的總空間、已用空間、使用率等；Metaspace表示元空間的相關情況，元空間中used表示已使用空間、capacity表示可用容量、commited表示jvm保證可用大小、reserved表示保留空間；class space表示class所用空間。

　　2、輸出到檔案

　　加上啟動引數 -Xloggc:gc.demo.log ， 再次執行。 

java -Xloggc:demogc.log -XX:+PrintGCDetails GCLogAnalysis

　　從JDK8開始，支援使用 %p ， %t 等佔位符來指定GC輸出檔案。分別表示程序pid和啟動時間戳。例如: -Xloggc:gc.%p.log ; -Xloggc:gc-%t.log ;在某些情況下，將每次JVM執行的GC日誌輸出到不同的檔案可以方便排查問題。如果業務訪問量大，導致GC日誌檔案太大，可以開啟GC日誌輪換，分割成多個檔案，可以參考：https://blog.gceasy.io/2016/11/15/rotating-gc-log-fifiles 。

　　輸出檔案：

　　　　　　　　

　　指定 -Xloggc: 引數，自動加上了 -XX:+PrintGCTimeStamps 配置。觀察GC日誌檔案可以看到，每一行前面多了一個時間戳（如 0.310: ），表示JVM啟動後經過的時間（單位秒）。從GC日誌中可以看到，JDK8預設使用的垃圾收集器引數: -XX:+UseParallelGC 

　　3、列印GC事件發生的日期和時間

　　我們在前面的基礎上，加上啟動引數 -XX:+PrintGCDateStamps ，再次執行

java -Xloggc:demogc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis

　　輸出內容：

　　　　　　　　

 　　可以看到，加上 -XX:+PrintGCDateStamps 引數之後，GC日誌每一行前面，都列印了GC發生時的具體時間。如 2022-05-04T14:09:08.828-0800 ，表示的是： 東8區時間2022年05月04日14:09:08秒.828毫秒。

　　4、指定堆記憶體大小

java -Xms512m -Xmx512m -Xloggc:demogc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis

　　5、指定垃圾回收器

# 使用串行垃圾收集器： -XX:+UseSerialGC
-XX:+UseSerialGC
# 使用並行垃圾收集器： -XX:+UseParallelGC 和 -XX:+UseParallelGC -XX:+UseParallelOldGC 是等價的, 可以通過GC日誌檔案中的flags看出來。
-XX:+UseParallelGC
-XX:+UseParallelGC -XX:+UseParallelOldGC
# 使用CMS垃圾收集器： -XX:+UseConcMarkSweepGC 和 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC 是等價的。 但如果只指定 -XX:+UseParNewGC 引數則老年代GC會 使用SerialGC。使用CMS時，命令行引數中會自動計算出年輕代、老年代的初始值和最大值，以及最大晉升閾值等資訊（例如 -XX:MaxNewSize=178958336 -XX:NewSize=178958336 -XX:OldSize=357912576 ）。
-XX:+UseConcMarkSweepGC
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC
# 使用 G1垃圾收集器： -XX:+UseG1GC 。原則上不能指定G1垃圾收集器的年輕代大小，否則不僅是畫蛇添足，更是自廢武功了。因為G1的回收方式是小批量劃定區塊（region）進行，可能一次普通GC中 既有年輕代又有老年代，可能某個區塊一會是老年代，一會又變成年輕代了。
-XX:+UseG1GC

　　如果使用不支援的GC組合，會啟動失敗，報fatal錯誤。

　　6、其他引數與總結

　　JVM里還有一些GC日誌相關的引數， 例如：-XX:+PrintGCApplicationStoppedTime 可以輸出每次GC的持續時間和程式暫停時間；-XX:+PrintReferenceGC 輸出GC清理了多少引用型別等。

　　大部分情況下，配置GC引數並不是越多越好。原則上只配置最重要的幾個引數即可，其他的都保持預設值，除非你對系統的業務特徵有了深入的分析和了解，才需要進行某些細微引數的調整。 畢竟，古語有云：“過早優化是萬惡之源”。

　　需要提醒的是，這些引數是基於JDK8配置的。在JDK9之後的版本中，啟動引數有一些變化，繼續使用原來的引數配置可能會在啟動時報錯。不過也不用擔心，如果碰到，一般都可以從錯誤提示中找到對應的處置措施和解決方案。例如JDK11版本中列印info級別GC日誌的啟動指令碼：

# JDK11環境，輸出info級別的GC日誌 
java -Xms512m -Xmx512m -Xlog:gc*=info:file=gc.log:time:filecount=0 demo.jvm0204.GCLogAnalysis

　　從JDK9開始，可以使用命令 java -Xlog:help 來檢視當前JVM支援的日誌引數。

三、GC事件型別

　　一般來說，垃圾收集事件(Garbage Collection events)可以分為三種類型：Minor GC(小型GC)、Major GC(大型GC)、Full GC(完全GC)。

　　雖然 Minor GC ， Major GC 和 Full GC 這幾個詞彙到處都在用，但官方並沒有給出標準的定義。這些術語出現在官方的各種分析工具和垃圾收集日誌中，並不是很統一。官方的文件和工具之間也常常混淆，這些混淆甚至根植於標準的JVM工具中。

　　Minor GC（小型GC）：Minor GC 清理的是年輕代，又或者說 Minor GC 就是 年輕代GC

　　　　收集年輕代記憶體的GC事件稱為 Minor GC 。關於 Minor GC 事件， 我們需要了解一些相關的內容：

　　　　1. 當JVM無法為新物件分配記憶體空間時就會觸發 Minor GC （ 一般就是 Eden 區用滿了）。 如果物件的分配速率很快， 那麼 Minor GC 的次數也就會很多，頻率也就會很快。

　　　　2. Minor GC 事件不處理老年代， 所以會把所有從老年代指向年輕代的引用都當做 GC Root 。從年輕代指向老年代的引用則在標記階段被忽略。

　　　　3. 與我們一般的認知相反， Minor GC 每次都會引起STW停頓（stop-the-world）， 掛起所有的應用執行緒。 對大部分應用程式來說， Minor GC 的暫停時間可以忽略不計，因為 Eden 區里面的物件大部分都是垃圾，也不怎麼複製到存活區/老年代。 但如果不符合這種情況，那麼很多新建立的物件就不能被GC清理， Minor GC 的停頓時間就會增大，就會產生比較明顯的GC效能影響。 

　　Major GC vs. Full GC ：值得一提的是，這幾個術語都沒有正式的定義--無論是在JVM規範中還是在GC論文中。

　　　　我們知道，除了 Minor GC 外，另外兩種GC事件則是：Major GC(大型GC) ：清理老年代空間（Old Space）的GC事件。

　　　　Full GC(完全GC) ：清理整個堆記憶體空間的GC事件，包括年輕代空間和老年代空間。其實 Major GC 和 Full GC 有時候並不能很好地區分。更複雜的情況是， 很多 Major GC 是由Minor GC 觸發的，所以很多情況下這兩者是不可分離的。另外，像G1這種垃圾收集演算法，是每次找一小部分割槽域來進行清理，這部分割槽域中可能有一部分是年輕代，另一部分割槽域屬於老年代。

　　　　所以我們不要太糾結具體是叫 Major GC 呢還是叫 Full GC ，它們一般都會造成單次較長時間的STW暫停。所以我們需要關注的是：某次GC事件，是暫停了所有執行緒、進而對系統造成了效能影響呢，還是與其他業務執行緒併發執行、暫停時間幾乎可以忽略不計。 

四、序列GC與並行GC日誌分析

（一）序列GC

　　使用序列GC

java -XX:+UseSerialGC -Xms512m -Xmx512m -Xloggc:demogc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis

　　輸出內容：

　　　　　　　　

　　　　日誌的第一行是JVM版本資訊，第二行往後到第一個時間戳之間的部分，展示了記憶體分頁、物理記憶體大小，命令行引數等資訊。仔細觀察，我們發現在這段日誌中發生了兩次GC事件，其中一次清理的是年輕代，另一次清理的是整個堆記憶體。讓我們先來分析前一次年輕代GC事件。

2019-12-15T15:18:36.592-0800: 0.420: [GC (Allocation Failure) 2019-12-15T15:18:36.592-0800: 0.420: 
　　[DefNew: 139776K->17472K(157248K)，0.0364555 secs] 
　　139776K->47032K(506816K)， 0.0365665 secs] 
　　[Times: user=0.02 sys=0.01，real=0.03 secs]

　　從日誌輸出可以看到：

　　　　1、 2019-12-15T15:18:36.592-0800 – GC事件開始的時間點。其中 -0800 表示當前時區為東八區，這只是一個標識，方便我們直觀判斷GC發生的時間點。後面的 0.420 – 是GC事件相對於JVM啟動時間的間隔，單位是秒。

　　　　2、 GC – 用來區分 Minor GC 還是 Full GC 的標誌。 GC 表明這是一次小型GC(Minor GC)，即年輕代GC。 Allocation Failure 表示觸發 GC 的原因。本次GC事件，是由於物件分配失敗，年輕代中沒有空間來存放新生成的物件引起的。

　　　　3、 DefNew – 表示垃圾收集器的名稱。這個名字表示：年輕代使用的單執行緒、標記-複製、STW 垃圾收集器。 139776K->17472K 表示在垃圾收集之前和之後的年輕代使用量。 (157248K) 表示年輕代的總空間大小。進一步分析可知：GC 之後年輕代使用率為11%。

　　　　4、 139776K->47032K(506816K) – 表示在垃圾收集之前和之後整個堆記憶體的使用情況。(506816K) 則表示堆記憶體可用的總空間大小。進一步分析可知: GC 之後堆記憶體使用量為9%。

　　　　5、 0.0365665 secs – GC事件持續的時間，以秒為單位。

　　　　6、 [Times: user=0.02 sys=0.01，real=0.03 secs] – 此次GC事件的持續時間，通過三個部分來衡量： user 部分表示所有 GC執行緒消耗的CPU時間； sys 部分表示系統呼叫和系統等待事件消耗的時間。 real 則表示應用程式暫停的時間。因為串行垃圾收集器(Serial Garbage Collector)只使用單個執行緒，所以這里 real = user + system ，0.03秒也就是30毫秒。

　　憑經驗，這個暫停時間對大部分系統來說可以接受，但對某些延遲敏感的系統就不太理想了，比如實時的遊戲服務、高頻交易業務，30ms暫停導致的延遲可能會要了親命 。

　　這樣解讀之後，我們可以分析JVM 在GC事件中的記憶體使用以及變化情況。

　　　　在此次垃圾收集之前，堆記憶體總的使用量為 139776K ，其中年輕代使用了 139776K 。可以算出，GC之前老年代空間的使用量為 0 。【實際上這是GC日誌中的第一條記錄】

　　這些數字中蘊含了更重要的資訊：

　　　　GC前後對比，年輕代的使用量為 139776K->17472K ，減少了 122304K 。但堆記憶體的總使用量 139776K->47032K 只下降了 92744K 。可以算出，從年輕代提升到老年代的物件佔用了 122304K - 92744K = 29560K 的記憶體空間。當然，另一組數字也能推算出GC之後老年代的使用量 47032K - 17472K = 29560K 。 

　　通過這麼分析下來應該發現，我們關注的主要是兩個資料： GC暫停時間，以及GC之後的記憶體使用量/使用率。

2019-12-15T15:18:37.081-0800: 0.908: [GC (Allocation Failure) 2019-12-15T15:18:37.081-0800: 0.908: 
　　[DefNew: 156152K->156152K(157248K)，0.0000331 secs] 2019-12-15T15:18:37.081-0800: 0.908: 
　　[Tenured: 299394K->225431K(349568K)，0.0539242 secs] 455546K->225431K(506816K)， 
　　[Metaspace: 3431K->3431K(1056768K)]， 0.0540948 secs] [Times: user=0.05 sys=0.00，real=0.05 secs]

　　從日誌輸出可以看到：

　　　　1、 2019-12-15T15:18:37.081-0800 – GC事件開始的時間。

　　　　2、 [DefNew: 156152K->156152K(157248K)，0.0000331 secs] – 前面已經解讀過了，因為記憶體分配失敗，發生了一次年輕代 GC。此次GC同樣用的 DefNew 收集器。注意：此次垃圾收集消耗了 0.0000331秒，基本上確認本次GC事件沒怎麼處理年輕代。

　　　　3、 Tenured – 用於清理老年代空間的垃圾收集器名稱。 Tenured 表明使用的是單執行緒的STW垃圾收集器，使用的演算法為 標記-清除-整理(mark-sweep-compact ) 。 299394K->225431K(349568K) 表示GC前後老年代的使用量，以及老年代的空間大小。 0.0539242 secs是清理老年代所花的時間。

　　　　4、 455546K->225431K(506816K) – 在GC前後整個堆記憶體部分的使用情況，以及可用的堆空間大小。

　　　　5、 [Metaspace: 3431K->3431K(1056768K)] – Metaspace 空間的變化情況。可以看出，此次GC過程中 Metaspace 也沒有什麼變化。

　　　　6、 [Times: user=0.05 sys=0.00，real=0.05 secs] – GC事件的持續時間，分為user ， sys ， real 三個部分。因為串行垃圾收集器只使用單個執行緒，因此 real = user + system 。

　　進一步分析這些資料，GC之後老年代的使用率為： 225431K / 349568K = 64% ，這個比例不算小，但也不能就此說出了什麼問題，畢竟GC後記憶體使用量下降了，還需要後續的觀察。。。

　　和年輕代GC 相比，比較明顯的差別是此次GC事件清理了老年代和Metaspace。

　　總結：FullGC，我們主要關注GC之後記憶體使用量是否下降，其次關注暫停時間。簡單估算，GC後老年代使用量為220MB左右，耗時 50ms。如果記憶體擴大10倍，GC後老年代記憶體使用量也擴大10倍，那耗時可能就是500ms甚至更高，就會系統有很明顯的影響了。這也是我們說串行GC效能弱的一個原因，服務端一般是不會採用串行GC的。

（二）並行GC

　　並行垃圾收集器對年輕代使用 標記-複製(mark-copy) 演算法，對老年代使用 標記-清除-整理(mark-sweep-compact) 演算法。年輕代和老年代的垃圾回收時都會觸發STW事件，暫停所有的應用執行緒，再來執行垃圾收集。在執行 標記 和 複製/整理 階段時都使用多個執行緒，因此得名“ Parallel ”。通過多個GC執行緒並行執行的方式，能使JVM在多CPU平臺上的GC時間大幅減少。通過命令行引數 -XX:ParallelGCThreads=N 可以指定 GC 執行緒的數量，其預設值為CPU核心數量。

　　下面的三組命令行引數都是等價的，都可用來指定並行垃圾收集器： 

-XX:+UseParallelGC
-XX:+UseParallelOldGC
-XX:+UseParallelGC -XX:+UseParallelOldGC

　　使用並行GC：

java -XX:+UseParallelGC -Xms512m -Xmx512m -Xloggc:demogc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis

　　並行垃圾收集器適用於多核服務器，其主要目標是增加系統吞吐量(也就是降低GC總體消耗的時間)。為了達成這個目標，會盡量使用盡可能多的CPU資源：

　　　　在GC事件執行期間，所有 CPU 核心都在並行地清理垃圾，所以暫停時間相對來說更短

　　　　在兩次GC事件中間的間隔期，不會啟動GC執行緒，所以這段時間內不會消耗任何系統資源

　　另一方面，因為並行GC的所有階段都不能中斷，所以並行GC很可能會出現長時間的卡頓。長時間卡頓的意思，就是並行GC啟動後，一次性完成所有的GC操作，所以單次暫停的時間較長。假如系統延遲是非常重要的效能指標，那麼就應該選擇其他垃圾收集器。

　　執行上面的命令行，讓我們看看並行垃圾收集器的GC日誌長什麼樣子： 

　　　　　　　　

　　Minor GC：

2019-12-18T00:37:47.463-0800: 0.690: [GC (Allocation Failure) 
　　[PSYoungGen: 104179K->14341K(116736K)] 383933K->341556K(466432K)，0.0229343 secs] 
　　[Times: user=0.04 sys=0.08，real=0.02 secs]

 　　解讀如下：

　　　　日誌資訊和上面的序列GC基本上一樣，這裡單獨說一下Times：

　　　　在並行GC中，並不是所有的操作過程都能全部並行，所以 real 約等於 user + system /GC執行緒數 。 筆者的機器是8個物理執行緒，所以預設是8個GC執行緒。分析這個時間，可以發現，如果使用串行GC，可能得暫停120毫秒，但並行GC只暫停了 20毫秒，實際上效能是大幅度提升了。

　　full GC：

2019-12-18T00:37:47.486-0800: 0.713: [Full GC (Ergonomics) 
　　[PSYoungGen: 14341K->0K(116736K)] 
　　[ParOldGen: 327214K->242340K(349696K)] 341556K->242340K(466432K)， 
　　[Metaspace: 3322K->3322K(1056768K)]， 0.0656553 secs] 
　　[Times: user=0.30 sys=0.02，real=0.07 secs]

 　　　　日誌資訊和上面的Minor GC基本上一樣，這裡說一下不同點：

　　 　　　　1、Full GC – 完全GC的標誌。 Full GC 表明本次GC清理年輕代和老年代， Ergonomics 是觸發GC的原因，表示JVM內部環境認為此時可以進行一次垃圾收集。

　　　　　　 2、此次GC事件除了處理年輕代，還清理了老年代和Metaspace。

　　總結: 對於年輕代GC，主要關注暫停時間和GC後記憶體使用率是否正常，而不需要關注GC前的記憶體使用量；Full GC時我們更關注老年代的使用量有沒有下降，以及下降了多少。如果FullGC之後記憶體不怎麼下降，使用率還很高，那就說明系統有問題了。

四、CMS GC日誌分析

　　CMS也可稱為 併發標記清除垃圾收集器 。其設計目標是避免在老年代GC時出現長時間的卡頓。預設情況下，CMS 使用的併發執行緒數等於CPU核心數的 1/4 。通過以下選項來指定CMS垃圾收集器： -XX:+UseConcMarkSweepGC。如果CPU資源受限，CMS的吞吐量會比並行GC差一些。

　　示例：

java -XX:+UseConcMarkSweepGC -Xms512m -Xmx512m -Xloggc:demogc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis

　　日誌示例：

　　　　　　　　

 　　Minor GC：

　　最前面的幾行日誌是清理年輕代的Minor GC事件： 　

2019-12-22T00:00:31.865-0800: 1.067： [GC (Allocation Failure) 2019-12-22T00:00:31.865-0800: 1.067： 
　　[ParNew： 136418K->17311K(157248K)，0.0233955 secs] 442378K->360181K(506816K)，0.0234719 secs] 
　　[Times: user=0.10 sys=0.02，real=0.02 secs]

　　GC日誌和並行GC類似，就不再做過多分析。

　　Full GC：

　　實際上這次擷取的年輕代GC日誌和FullGC日誌是緊連著的，我們從間隔時間也能大致看出來， 1.067 +0.02secs ~ 1.091 。CMS的日誌是一種完全不同的格式，並且很長，因為CMS對老年代進行垃圾收集時每個階段都會有自己的日誌。

2019-12-22T00:00:31.889-0800: 1.091: [GC (CMS Initial Mark) [1 CMS-initial-mark: 342870K(349568K)] 363883K(506816K)，0.0002262 secs] [Times: user=0.00 sys=0.00,real=0.00 secs] 
2019-12-22T00:00:31.889-0800: 1.091: [CMS-concurrent-mark-start] 
2019-12-22T00:00:31.890-0800: 1.092: [CMS-concurrent-mark: 0.001/0.001 secs][Times: user=0.00 sys=0.00,real=0.01 secs] 
2019-12-22T00:00:31.891-0800: 1.092: [CMS-concurrent-preclean-start] 
2019-12-22T00:00:31.891-0800: 1.093: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00,real=0.00 secs] 
2019-12-22T00:00:31.891-0800: 1.093: [CMS-concurrent-abortable-preclean-start] 
2019-12-22T00:00:31.891-0800: 1.093: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs] 
2019-12-22T00:00:31.891-0800: 1.093: [GC (CMS Final Remark) [YG occupancy: 26095 K (157248 K)] 
2019-12-22T00:00:31.891-0800: 1.093: [Rescan (parallel) ，0.0002680 secs] 
2019-12-22T00:00:31.891-0800: 1.093: [weak refs processing，0.0000230 secs] 
2019-12-22T00:00:31.891-0800: 1.093: [class unloading，0.0004008 secs] 
2019-12-22T00:00:31.892-0800: 1.094: [scrub symbol table，0.0006072 secs] 
2019-12-22T00:00:31.893-0800: 1.095: [scrub string table，0.0001769 secs] [1 CMS-remark: 342870K(349568K)] 368965K(506816K)，0.0015928 secs] [Times: user=0.01 sys=0.00,real=0.00 secs] 
2019-12-22T00:00:31.893-0800: 1.095: [CMS-concurrent-sweep-start] 
2019-12-22T00:00:31.893-0800: 1.095: [CMS-concurrent-sweep： 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs] 
2019-12-22T00:00:31.893-0800: 1.095: [CMS-concurrent-reset-start] 
2019-12-22T00:00:31.894-0800: 1.096: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]

 　　在實際運行中，CMS在進行老年代的併發垃圾回收時，可能會伴隨著多次年輕代的Minor GC。在這種情況下，Full GC的日誌中可能會摻雜著多次Minor GC事件。

　　階段 1：Initial Mark(初始標記)

　　　　前面文章提到過，這個階段伴隨著STW暫停。初始標記的目標是標記所有的根物件，包括 GC ROOT 直接引用的物件，以及被年輕代中所有存活物件所引用的物件。後面這部分也非常重要，因為老年代是獨立進行回收的。先看這個階段的日誌： 

2019-12-22T00:00:31.889-0800: 1.091: [GC (CMS Initial Mark) [1 CMS-initial-mark: 342870K(349568K)] 363883K(506816K), 0.0002262 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]

　　　　解讀：

　　　　　　1、 CMS Initial Mark – 這個階段的名稱為 “Initial Mark”，會標記所有的 GC Root。

　　　　　　2、[1 CMS-initial-mark: 342870K(349568K)] – 這部分數字表示老年代的使用量，以及老年代的空間大小。

　　　　　　3、 363883K(506816K)，0.0002262 secs – 當前堆記憶體的使用量，以及可用堆的大小、消耗的時間。可以看出這個時間非常短，只有 0.2毫秒左右，因為要標記的這些Roo數量很少。

　　階段 2：Concurrent Mark(併發標記) 

　　　　在併發標記階段，CMS 從前一階段 “Initial Mark” 找到的 ROOT 開始算起，遍歷老年代並標記所有的存活物件。

2019-12-22T00:00:31.889-0800: 1.091: [CMS-concurrent-mark-start] 
2019-12-22T00:00:31.890-0800: 1.092: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00,real=0.01 secs]

　　　　解讀：

　　　　　　1、CMS-concurrent-mark – 指明了是CMS垃圾收集器所處的階段為併發標記("Concurrent Mark")。

　　　　　　2、 0.001/0.001 secs – 此階段的持續時間，分別是GC執行緒消耗的時間和實際消耗的時間。

　　階段 3：Concurrent Preclean(併發預清理) 

　　　　此階段同樣是與應用執行緒併發執行的，不需要停止應用執行緒。

2019-12-22T00:00:31.891-0800: 1.092: [CMS-concurrent-preclean-start] 
2019-12-22T00:00:31.891-0800: 1.093: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]

　　　　解讀：

　　　　　　1、CMS-concurrent-preclean – 表明這是併發預清理階段的日誌，這個階段會統計前面的併發標記階段執行過程中發生了改變的物件。

　　　　　　2、0.001/0.001 secs – 此階段的持續時間，分別是GC執行緒運行時間和實際佔用的時間。

　　階段 4：Concurrent Abortable Preclean(可取消的併發預清理) 

　　　　此階段也不停止應用執行緒，嘗試在會觸發STW 的 Final Remark 階段開始之前，儘可能地多幹一些活。本階段的具體時間取決於多種因素，因為它迴圈做同樣的事情，直到滿足某一個退出條件(如迭代次數，有用工作量，消耗的系統時間等等)。  

2019-12-22T00:00:31.891-0800: 1.093: [CMS-concurrent-abortable-preclean-start] 2019-12-22T00:00:31.891-0800: 1.093: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]

　　　　解讀：

　　　　　　1、CMS-concurrent-abortable-preclean – 指示此階段的名稱：“Concurrent AbortablePreclean”。

　　　　　　2、0.000/0.000 secs – 此階段GC執行緒的運行時間和實際佔用的時間。從本質上講，GC執行緒試圖在執行 STW 暫停之前等待儘可能長的時間。預設條件下，此階段可以持續最長5秒鐘的時間。

　　　　此階段完成的工作可能對STW停頓的時間有較大影響，並且有許多重要的配置選項和失敗模式。

　　階段 5：Final Remark(最終標記) 

　　　　最終標記階段是此次GC事件中的第二次(也是最後一次)STW停頓。本階段的目標是完成老年代中所有存活物件的標記。因為之前的預清理階段是併發執行的，有可能GC執行緒跟不上應用程式的修改速度。所以需要一次 STW 暫停來處理各種複雜的情況。通常CMS會嘗試在年輕代儘可能空的情況下執行 final remark 階段，以免連續觸發多次 STW 事件。

2019-12-22T00:00:31.891-0800: 1.093: [GC (CMS Final Remark) 
　　[YG occupancy: 26095 K (157248 K)] 　
　　　　2019-12-22T00:00:31.891-0800: 1.093: [Rescan (parallel) ，0.0002680 secs] 　　
　　　　　　2019-12-22T00:00:31.891-0800: 1.093: [weak refs processing，0.0000230 secs] 　　
　　　　　　2019-12-22T00:00:31.891-0800: 1.093: [class unloading，0.0004008 secs] 
　　　　　　2019-12-22T00:00:31.892-0800: 1.094: [scrub symbol table，0.0006072 secs] 
　　　　　　2019-12-22T00:00:31.893-0800: 1.095: [scrub string table，0.0001769 secs] 
　[1 CMS-remark: 342870K(349568K)] 368965K(506816K)，0.0015928 secs] 
[Times: user=0.01 sys=0.00,real=0.00 secs]

　　　　解讀：

　　　　　　1、CMS Final Remark – 這是此階段的名稱，最終標記階段，會標記老年代中所有的存活物件，包括此前的併發標記過程中建立/修改的引用。

　　　　　　2、YG occupancy: 26095 K (157248 K) – 當前年輕代的使用量和總容量。

　　　　　　3、 [Rescan (parallel) ，0.0002680 secs] – 在程式暫停後進行重新掃描(Rescan)，以完成存活物件的標記。這部分是並行執行的，消耗的時間為 0.0002680秒 。

　　　　　　4、 weak refs processing，0.0000230 secs – 第一個子階段： 處理弱引用的持續時間。

　　　　　　5、 class unloading，0.0004008 secs – 第二個子階段： 解除安裝不使用的類，以及持續時間。

　　　　　　6、scrub symbol table，0.0006072 secs – 第三個子階段： 清理符號表，即持有class級別metadata 的符號表(symbol tables)。

　　　　　　7、 scrub string table，0.0001769 secs – 第四個子階段： 清理內聯字元串對應的 stringtables。

　　　　　　8、 [1 CMS-remark: 342870K(349568K)] – 此階段完成後老年代的使用量和總容量。

　　　　　　9、 368965K(506816K)，0.0015928 secs – 此階段完成後，整個堆記憶體的使用量和總容量。

　　　　　　10、[Times: user=0.01 sys=0.00,real=0.00 secs] – GC事件的持續時間。

　　　　在這5個標記階段完成後，老年代中的所有存活物件都被標記上了，接下來JVM會將所有不使用的物件清除，以回收老年代空間。 

　　階段 6：Concurrent Sweep(併發清除) 

　　　　此階段與應用程式併發執行，不需要STW停頓。目的是刪除不再使用的物件，並回收他們佔用的記憶體空間。　　

2019-12-22T00:00:31.893-0800: 1.095: [CMS-concurrent-sweep-start] 
2019-12-22T00:00:31.893-0800: 1.095: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]

　　　　解讀：

　　　　　　1、CMS-concurrent-sweep – 此階段的名稱，“Concurrent Sweep”，併發清除老年代中所有未被標記的物件、也就是不再使用的物件，以釋放記憶體空間。

　　　　　　2、 0.000/0.000 secs – 此階段的持續時間和實際佔用的時間，這是一個四捨五入值，只精確到小數點後3位。

　　階段 7：Concurrent Reset(併發重置) 

　　　　此階段與應用程式執行緒併發執行，重置CMS演算法相關的內部資料結構，下一次觸發GC時就可以直接使用。

2019-12-22T00:00:31.893-0800: 1.095: [CMS-concurrent-reset-start] 
2019-12-22T00:00:31.894-0800: 1.096: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]

　　　　解讀：

　　　　　　1、CMS-concurrent-reset – 此階段的名稱，“Concurrent Reset”，重置CMS演算法的內部資料結構，為下一次GC迴圈做準備。

　　　　　　2、0.000/0.000 secs – 此階段的持續時間和實際佔用的時間

　　　　那麼問題來了，CMS 之後老年代記憶體使用量是多少呢? 很抱歉這里分析不了，只能通過後面的Minor GC日誌來分析了。 

　　　　例如本次運行，後面的GC日誌是這樣的：

2019-12-22T00:00:31.921-0800: 1.123: [GC (Allocation Failure) 
2019-12-22T00:00:31.921-0800: 1.123: [ParNew: 153242K->16777K(157248K), 0.0070050 secs] 445134K->335501K(506816K)， 0.0070758 secs] [Times: user=0.05 sys=0.00,real=0.00 secs]

　　　　參照前面年輕代GC日誌的分析方法，我們推算出來，上面的CMS Full GC之後，老年代的使用量應該是：445134K - 153242K = 291892K ，老年代的總容量 506816K - 157248K = 349568K ，所以FullGC之後老年代的使用量佔比是 291892K / 349568K = 83% 。這個佔比不低。說明什麼問題呢？ 一般來說就是分配的記憶體小了，畢竟我們才指定了512MB的最大堆記憶體。 

　　總之，CMS垃圾收集器在減少停頓時間上做了很多給力的工作，很大一部分GC執行緒是與應用執行緒併發運行的，不需要暫停應用執行緒，這樣就可以在一般情況下每次暫停的時候較少。當然，CMS也有一些缺點，其中最大的問題就是老年代的記憶體碎片問題，在某些情況下GC會有不可預測的暫停時間，特別是堆記憶體較大的情況下。 

五、G1 GC日誌分析

　　使用G1 GC

java -XX:+UseG1GC -Xms512m -Xmx512m -Xloggc:demogc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis

　　列印的東西非常多，能會生成上千行的GC日誌：

　　　　　　　　

　　如果只想看GC總的GC步驟，不想看詳細資訊，可以將引數中PrintGCDetails改為PrintGC

　　　　　　　　

（一）Evacuation Pause: young(純年輕代模式轉移暫停) 

　　1、總體日誌

　　　　當年輕代空間用滿後，應用執行緒會被暫停，年輕代記憶體塊中的存活物件被拷貝到存活區。 如果還沒有存活區，則任意選擇一部分空閒的記憶體塊作為存活區。拷貝的過程稱為轉移(Evacuation)，這和前面介紹的其他年輕代收集器是一樣的工作原理。轉移暫停的日誌資訊很長，為簡單起見，我們去除了一些不重要的資訊。在併發階段之後我們會進行詳細的講解。

　　　　此外，由於日誌記錄很多，所以並行階段和“其他”階段的日誌將拆分為多個部分來進行講解。

2019-12-23T01:45:40.605-0800: 0.181: [GC pause (G1 Evacuation Pause) (young)，0.0038577 secs] 
　　[Parallel Time: 3.1 ms，GC Workers: 8] 
　　...... worker執行緒的詳情，下面單獨講解 
　　[Code Root Fixup: 0.0 ms] 
　　[Code Root Purge: 0.0 ms] 
　　[Clear CT: 0.2 ms] 
　　[Other: 0.6 ms] 
　　...... 其他瑣碎任務，下面單獨講解 
　　[Eden: 25.0M(25.0M)->0.0B(25.0M) Survivors: 0.0B->4096.0K Heap: 28.2M(512.0M)->9162.7K(512.0M)] 
　　[Times: user=0.01 sys=0.01，real=0.00 secs]

　　　　（1）[GC pause (G1 Evacuation Pause) (young)，0.0038577 secs] – G1轉移暫停，純年輕代模式; 只清理年輕代空間。這次暫停在JVM啟動之後 181 ms 開始，持續的系統時間為0.0038577秒 ，也就是 3.8ms 。

　　　　（2） [Parallel Time: 3.1 ms，GC Workers: 8] – 表明後面的活動由8個 Worker 執行緒並行執，消耗時間為3.1毫秒(real time); worker 是一種模式，類似於一個老板指揮多個工人幹活。

　　　　（3） …... – 為閱讀方便，省略了部分內容，下面緊接著也會講解。

　　　　（4） [Code Root Fixup: 0.0 ms] – 釋放用於管理並行活動的內部資料，一般都接近於零。這個過程是串行執行的。

　　　　（5） [Code Root Purge: 0.0 ms] – 清理其他部分資料，也是非常快的，如非必要基本上等於零。也是串行執行的過程。

　　　　（6） [Other: 0.6 ms] – 其他活動消耗的時間，其中大部分是並行執行的。

　　　　（7） … – 請參考後文。

　　　　（8） [Eden: 25.0M(25.0M)->0.0B(25.0M) – 暫停之前和暫停之後，Eden 區的使用量/總容量。

　　　　（9） Survivors: 0.0B->4096.0K – GC暫停前後，存活區的使用量。 Heap:28.2M(512.0M)->9162.7K(512.0M)] – 暫停前後，整個堆記憶體的使用量與總容量。

　　　　（10） [Times: user=0.01 sys=0.01，real=0.00 secs] – GC事件的持續時間。

　　　　說明：系統時間(wall clock time/elapsed time)，是指一段程式從運行到終止，系統時鐘走過的時間。一般系統時間都要比CPU時間略微長一點。 

　　2、worker執行緒詳情：

　　　　最繁重的GC任務由多個專用的 worker 執行緒來執行，下面的日誌描述了他們的行為: 

[Parallel Time: 3.1 ms，GC Workers: 8] 
　　[GC Worker Start (ms): Min: 180.6，Avg: 180.6，Max: 180.7，Diff: 0.1] 
　　[Ext Root Scanning (ms): Min: 0.1，Avg: 0.3，Max: 0.6，Diff: 0.4，Sum: 2.1] 
　　[Update RS (ms): Min: 0.0，Avg: 0.0，Max: 0.0，Diff: 0.0，Sum: 0.0] 
　　[Processed Buffers: Min: 0，Avg: 0.0，Max: 0，Diff: 0，Sum: 0] 
　　[Scan RS (ms): Min: 0.0，Avg: 0.0，Max: 0.0，Diff: 0.0，Sum: 0.0] 
　　[Code Root Scanning (ms): Min: 0.0，Avg: 0.0，Max: 0.1，Diff: 0.1，Sum: 0.1] 
　　[Object Copy (ms): Min: 2.2，Avg: 2.5，Max: 2.7，Diff: 0.4，Sum: 19.8] 
　　[Termination (ms): Min: 0.0，Avg: 0.2，Max: 0.4，Diff: 0.4，Sum: 1.5] 
　　[Termination Attempts: Min: 1，Avg: 1.0，Max: 1，Diff: 0，Sum: 8] 
　　[GC Worker Other (ms): Min: 0.0，Avg: 0.0，Max: 0.0，Diff: 0.0，Sum: 0.1] 
　　[GC Worker Total (ms): Min: 2.9，Avg: 3.0，Max: 3.0，Diff: 0.1，Sum: 23.7] 
　　[GC Worker End (ms): Min: 183.6，Avg: 183.6，Max: 183.6，Diff: 0.0]

 　　　　Worker執行緒的日誌資訊解讀：

　　　　（1） [Parallel Time: 3.1 ms，GC Workers: 8] – 前面介紹過，這表明下列活動由8個執行緒並行執行，消耗的時間為3.1毫秒(real time)。

　　　　（2） GC Worker Start (ms) – GC的worker執行緒開始啟動時，相對於 pause 開始時間的毫秒間隔。如果 Min 和 Max 差別很大，則表明本機其他程序所使用的執行緒數量過多，擠佔了GC的可用CPU時間。

　　　　（3） Ext Root Scanning (ms) – 用了多長時間來掃描堆外記憶體(non-heap)的 GC ROOT，如classloaders，JNI引用，JVM系統ROOT等。後面顯示了運行時間，“Sum” 指的是CPU時間。

　　　　（4） Update RS ， Processed Buffers ， Scan RS 這三部分也是類似的， RS 是Remembered Set 的縮寫。

　　　　（5） Code Root Scanning (ms) – 掃描實際程式碼中的 root 用了多長時間：例如執行緒棧中的區域性變量。

　　　　（6） Object Copy (ms) – 用了多長時間來拷貝回收集中的存活物件。

　　　　（7） Termination (ms) – GC的worker執行緒用了多長時間來確保自身可以安全地停止，在這段時間內什麼也不做，完成後GC執行緒就終止運行了，所以叫終止等待時間。

　　　　（8） Termination Attempts – GC的worker 執行緒嘗試多少次 try 和 teminate。如果worker發現還有一些任務沒處理完，則這一次嘗試就是失敗的，暫時還不能終止。

　　　　（9） GC Worker Other (ms) – 其他的小任務， 因為時間很短，在GC日誌將他們歸結在一起。

　　　　（10） GC Worker Total (ms) – GC的worker 執行緒工作時間總計。

　　　　（11） [GC Worker End (ms) – GC的worker 執行緒完成作業時刻，相對於此次GC暫停開始時間的毫秒數。通常來說這部分數字應該大致相等，否則就說明有太多的執行緒被掛起，很可能是因為“壞鄰居效應(noisy neighbor)" 所導致的。

　　3、其他瑣碎任務

　　　　此外，在轉移暫停期間,還有一些瑣碎的小任務。

[Other: 0.6 ms] 
　　[Choose CSet: 0.0 ms] 
　　[Ref Proc: 0.3 ms] 
　　[Ref Enq: 0.0 ms] 
　　[Redirty Cards: 0.1 ms] 
　　[Humongous Register: 0.0 ms] 
　　[Humongous Reclaim: 0.0 ms] 
　　[Free CSet: 0.0 ms]

 　　　　這里只介紹其中的一部分：

　　　　（1） [Other: 0.6 ms] – 其他活動消耗的時間，其中很多是並行執行的。

　　　　（2） Choose CSet - 選擇CSet消耗的時間; CSet 是 Collection Set 的縮寫。

　　　　（3） [Ref Proc: 0.3 ms] – 處理非強引用(non-strong)的時間：進行清理或者決定是否需要清理。

　　　　（4） [Ref Enq: 0.0 ms] – 用來將剩下的 non-strong 引用排列到合適的 ReferenceQueue 中。

　　　　（5） Humongous Register ， Humongous Reclaim 大物件相關的部分。後面進行介紹。

　　　　（6） [Free CSet: 0.0 ms] – 將回收集中被釋放的小堆歸還所消耗的時間，以便他們能用來分配新的物件。

（二）Concurrent Marking(併發標記)

當堆記憶體的總體使用比例達到一定數值時，就會觸發併發標記。 這個預設比例是 45% ，但也可以通過JVM引數 InitiatingHeapOccupancyPercent 來設定。和CMS一樣，G1的併發標記也是由多個階段組成，其中一些階段是完全併發的，還有一些階段則會暫停應用執行緒。 

　　　　階段 1: Initial Mark(初始標記)

　　　　　　可以在 Evacuation Pause 日誌中的第一行看到(initial-mark)暫停，類似這樣: 

2019-12-23T01:45:41.568-0800: 1.144: [GC pause (G1 Humongous Allocation) (young) (initial-mark)， 0.0012116 secs]

 　　　　　　當然，這里引發GC的原因是大物件分配，也可能是其他原因，例如： to-space exhausted ，或者預設GC原因等等. 

　　　　階段 2: Root Region Scan(Root區掃描)

　　　　　　此階段標記所有從 "根區域" 可達的存活物件。根區域包括：非空的區域，以及在標記過程中不得不收集的區域。對應的日誌：

2019-12-23T01:45:41.569-0800: 1.145: [GC concurrent-root-region-scan-start] 
2019-12-23T01:45:41.569-0800: 1.145: [GC concurrent-root-region-scan-end，0.0000360 secs]

 　　　　階段 3: Concurrent Mark(併發標記) 

2019-12-23T01:45:41.569-0800: 1.145: [GC concurrent-mark-start] 
2019-12-23T01:45:41.571-0800: 1.146: [GC concurrent-mark-end，0.0015209 secs]

 　　　　階段 4: Remark(再次標記) 

2019-12-23T01:45:41.571-0800: 1.146: [GC remark 2019-12-23T01:45:41.571-0800: 1.147: [Finalize Marking，0.0002456 secs]
2019-12-23T01:45:41.571-0800: 1.147: [GC ref-proc，0.0000504 secs]2019-12-23T01:45:41.571-0800: 1.147: [Unloading，0.0007297 secs]，0.0021658 secs] [Times: user=0.01 sys=0.00，real=0.00 secs]

 　　　　階段 5: Cleanup(清理) 

　　　　　　最後這個清理階段為即將到來的轉移階段做準備，統計小堆塊中所有存活的物件，並將小堆塊進行排序，以提升GC的效率。此階段也為下一次標記執行必需的所有整理工作(house-keeping activities)：維護併發標記的內部狀態。要提醒的是，所有不包含存活物件的小堆塊在此階段都被回收了。有一部分任務是併發的: 例如空堆區的回收，還有大部分的存活率計算，此階段也需要一個短暫的STW暫停，才能不受應用執行緒的影響並完成作業。

　　　　　　這種STW停頓的對應的日誌如下： 

2019-12-23T01:45:41.573-0800: 1.149: [GC cleanup 366M->366M(512M)，0.0006795 secs] [Times: user=0.00 sys=0.00，real=0.00 secs]

 　　　　如果發現某些小堆塊中只包含垃圾，則日誌格式可能會有點不同，如: 

2019-12-23T21:26:42.411-0800: 0.689: [GC cleanup 247M->242M(512M)，0.0005349 secs] [Times: user=0.00 sys=0.00，real=0.00 secs] 
2019-12-23T21:26:42.412-0800: 0.689: [GC concurrent-cleanup-start] 2019-12-23T21:26:42.412-0800: 0.689: [GC concurrent-cleanup-end，0.0000134 secs]

　　　　如果你在執行示例程式之後沒有看到對應的GC日誌，可以多跑幾遍試試。畢竟GC和記憶體分配屬於運行時動態的，每次運行都可能有些不同。 

 　　　　我們在示例程式中生成的陣列大小和快取哪個物件都是用的隨機數，每次運行結果都不一樣。如果想讓每次的隨機數都一致，請搜尋: " 隨機數種子 "。標記週期一般只在碰到region中一個存活物件都沒有的時候，才會順手處理一把，大多數情況下都不釋放記憶體。

（三）Evacuation Pause (mixed)(轉移暫停: 混合模式)

　　　　併發標記完成之後，G1將執行一次混合收集(mixed collection)，不只清理年輕代，還將一部分老年代區域也加入到 collection set 中。混合模式的轉移暫停(Evacuation pause)不一定緊跟併發標記階段。在併發標記與混合轉移暫停之間，很可能會存在多次 young 模式的轉移暫停。 混合模式 就是指這次GC事件混合著處理年輕代和老年代的region。這也是G1等增量垃圾收集器的特色。而ZGC等最新的垃圾收集器則不使用分代演算法。 當然，以後可能還是會實現分代的，畢竟分代之後效能還會有提升。 

　　　　混合模式下的日誌，和純年輕代模式相比，可以發現一些有趣的地方：

2019-12-23T21:26:42.383-0800: 0.661: [GC pause (G1 Evacuation Pause) (mixed)，0.0029192 secs] 
　　[Parallel Time: 2.2 ms，GC Workers: 8]
　　　　 ...... 
　　　　[Update RS (ms): Min: 0.1，Avg: 0.2，Max: 0.3，Diff: 0.2，Sum: 1.4] 
　　　　　　[Processed Buffers: Min: 0，Avg: 1.8，Max: 3，Diff: 3，Sum: 14] 
　　　　[Scan RS (ms): Min: 0.0，Avg: 0.0，Max: 0.0，Diff: 0.0，Sum: 0.1] 
　　　　...... 
　　[Clear CT: 0.4 ms] 
　　[Other: 0.4 ms] 
　　　　[Choose CSet: 0.0 ms] 
　　　　[Ref Proc: 0.1 ms] 
　　　　[Ref Enq: 0.0 ms] 
　　　　[Redirty Cards: 0.1 ms] 
　　　　[Free CSet: 0.1 ms] 
　　[Eden: 21.0M(21.0M)->0.0B(21.0M) Survivors: 4096.0K->4096.0K Heap: 337.7M(512.0M)->274.3M(512.0M)] 
[Times: user=0.01 sys=0.00，real=0.00 secs]

 　　　　簡單解讀（部分概念和名稱，可以參考G1章節）：

　　　　　　1、 [Update RS (ms) – 因為 Remembered Sets 是併發處理的，必須確保在實際的垃圾收集之前，緩衝區中的 card 得到處理。如果card數量很多，則GC併發執行緒的負載可能就會很高。可能的原因是修改的欄位過多，或者CPU資源受限。

　　　　　　2、 Processed Buffers – 各個 worker 執行緒處理了多少個本地緩衝區(local buffffer)。

　　　　　　3、 Scan RS (ms) – 用了多長時間掃描來自RSet的引用。

　　　　　　4、 [Clear CT: 0.4 ms] – 清理 card table 中 cards 的時間。清理工作只是簡單地刪除“髒”狀態，此狀態用來標識一個欄位是否被更新的，供Remembered Sets使用。

　　　　　　5、 [Redirty Cards: 0.1 ms] – 將 card table 中適當的位置標記為 dirty 所花費的時間。"適當的位置"是由GC本身執行的堆記憶體改變所決定的，例如引用排隊等。

（四）Full GC (Allocation Failure) 

　　G1是一款自適應的增量垃圾收集器。一般來說，只有在記憶體嚴重不足的情況下才會發生Full GC。 比如堆空間不足或者to-space空間不足。在前面的示例程式基礎上，增加快取物件的數量，即可模擬Full GC。

　　　　示例日誌如下：

2020-03-02T18:44:17.814-0800: 2.826: [Full GC (Allocation Failure) 403M->401M(512M)，0.0046647 secs] 
　　[Eden: 0.0B(25.0M)->0.0B(25.0M) Survivors: 0.0B->0.0B Heap: 403.6M(512.0M)->401.5M(512.0M)]， [Metaspace: 2789K->2789K(1056768K)] 
　[Times: user=0.00 sys=0.00，real=0.00 secs]

 　　在堆記憶體較大的情況下【8G+】，如果G1發生了FullGC，暫停時間可能會退化，達到幾十秒甚至更多。如下面這張圖片所示： 　　　　

　　　　　　　　

　　從其中的OldGen部分可以看到， 118 次 Full GC 消耗了31分鐘，平均每次達到 20 秒，按影象比例可粗略得知，吞吐率不足 30% 。這張圖片所表示的場景是在壓測Flink按時間視窗進行聚合計算時發生的，主要原因是物件太多，堆記憶體空間不足而導致的，修改物件型別為原生資料型別之後問題得到緩解，加大堆記憶體空間，滿足批處理/流計算的需求之後GC問題不再復現。

　　發生持續時間很長的FullGC暫停時，就需要我們進行排查和分析，確定是否需要修改GC配置，或者增加記憶體，還是需要修改程式的業務邏輯。