分析G1 GC日志

29 Jun 2021 | Java |

测试环境：

jdk1.8，win10，4核8线程，16G内存

演示代码：程序在1秒内生成许多对象，每个对象随机放在数组里。有的位置就会被重置，就会存在未被使用的对象，等待被回收。

import java.util.Random;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.LongAdder;
/*
演示GC日志生成与解读
*/
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;
    }
}

编译代码：

javac GCLogAnalysis.java

G1 – Garbage First(垃圾优先算法)，G1 GC最主要的设计目标是：将STW停顿的时间和分布变成可预期以及可配置。

G1适合大内存，需要低延迟的场景。G1 GC的日志信息太多了，这里只给出一种配置进行分析。

案例（ -Xms4g -Xmx4g）

D:\>java -XX:+UseG1GC -Xms4g -Xmx4g -XX:+PrintGCDetails GCLogAnalysis
正在执行...
[GC pause (G1 Evacuation Pause) (young), 0.0099569 secs]
   [Parallel Time: 7.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 180.0, Avg: 180.1, Max: 180.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.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.1, Diff: 0.1, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 7.3, Avg: 7.4, Max: 7.5, Diff: 0.3, Sum: 59.3]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.4]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [GC Worker Total (ms): Min: 7.8, Avg: 7.8, Max: 7.8, Diff: 0.1, Sum: 62.4]
      [GC Worker End (ms): Min: 187.9, Avg: 187.9, Max: 187.9, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 1.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.5 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 204.0M(204.0M)->0.0B(178.0M) Survivors: 0.0B->26.0M Heap: 204.0M(4096.0M)->65.2M(4096.0M)]
 [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0116306 secs]
   [Parallel Time: 9.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 215.6, Avg: 215.7, Max: 215.7, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Processed Buffers: Min: 0, Avg: 1.0, Max: 3, Diff: 3, Sum: 8]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 9.4, Avg: 9.5, Max: 9.6, Diff: 0.2, Sum: 75.8]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.9]
         [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: 9.7, Avg: 9.7, Max: 9.8, Diff: 0.1, Sum: 77.8]
      [GC Worker End (ms): Min: 225.4, Avg: 225.4, Max: 225.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 1.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.7 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 178.0M(178.0M)->0.0B(178.0M) Survivors: 26.0M->26.0M Heap: 243.2M(4096.0M)->123.6M(4096.0M)]
 [Times: user=0.02 sys=0.00, real=0.03 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0130914 secs]
   [Parallel Time: 11.0 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 268.1, Avg: 268.1, Max: 268.2, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.7, Diff: 0.6, Sum: 1.2]
         [Processed Buffers: Min: 1, Avg: 1.4, Max: 2, Diff: 1, Sum: 11]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 9.9, Avg: 10.4, Max: 10.7, Diff: 0.7, Sum: 83.3]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 1.8]
         [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: 10.8, Avg: 10.9, Max: 10.9, Diff: 0.1, Sum: 87.1]
      [GC Worker End (ms): Min: 279.0, Avg: 279.0, Max: 279.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 1.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.8 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 178.0M(178.0M)->0.0B(178.0M) Survivors: 26.0M->26.0M Heap: 301.6M(4096.0M)->183.8M(4096.0M)]
 [Times: user=0.06 sys=0.06, real=0.03 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0114275 secs]
   [Parallel Time: 10.2 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 320.3, Avg: 320.5, Max: 321.0, Diff: 0.7]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
      [Update RS (ms): Min: 0.0, Avg: 0.2, Max: 1.1, Diff: 1.1, Sum: 1.4]
         [Processed Buffers: Min: 0, Avg: 1.3, Max: 2, Diff: 2, Sum: 10]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 8.7, Avg: 9.6, Max: 9.8, Diff: 1.1, Sum: 76.6]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
         [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: 9.4, Avg: 9.9, Max: 10.1, Diff: 0.7, Sum: 79.5]
      [GC Worker End (ms): Min: 330.4, Avg: 330.4, Max: 330.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.6 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 178.0M(178.0M)->0.0B(178.0M) Survivors: 26.0M->26.0M Heap: 361.8M(4096.0M)->236.2M(4096.0M)]
 [Times: user=0.00 sys=0.00, real=0.02 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0119627 secs]
   [Parallel Time: 9.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 369.7, Avg: 369.8, Max: 369.9, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
         [Processed Buffers: Min: 1, Avg: 1.3, Max: 2, Diff: 1, Sum: 10]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 9.3, Avg: 9.4, Max: 9.6, Diff: 0.4, Sum: 75.3]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.7]
         [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: 9.7, Avg: 9.8, Max: 9.9, Diff: 0.1, Sum: 78.3]
      [GC Worker End (ms): Min: 379.6, Avg: 379.6, Max: 379.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 1.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.9 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 178.0M(178.0M)->0.0B(178.0M) Survivors: 26.0M->26.0M Heap: 414.2M(4096.0M)->283.9M(4096.0M)]
 [Times: user=0.00 sys=0.00, real=0.03 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0125605 secs]
   [Parallel Time: 11.1 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 420.1, Avg: 420.2, Max: 420.3, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
         [Processed Buffers: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 10.3, Avg: 10.5, Max: 10.7, Diff: 0.4, Sum: 84.1]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.2]
         [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: 10.8, Avg: 10.8, Max: 10.9, Diff: 0.2, Sum: 86.5]
      [GC Worker End (ms): Min: 431.0, Avg: 431.0, Max: 431.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.7 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 178.0M(178.0M)->0.0B(178.0M) Survivors: 26.0M->26.0M Heap: 461.9M(4096.0M)->343.5M(4096.0M)]
 [Times: user=0.11 sys=0.02, real=0.03 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0114717 secs]
   [Parallel Time: 10.4 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 473.3, Avg: 473.4, Max: 473.8, Diff: 0.5]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.8]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
         [Processed Buffers: Min: 0, Avg: 1.1, Max: 3, Diff: 3, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 9.7, Avg: 9.9, Max: 10.2, Diff: 0.5, Sum: 79.5]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, 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: 9.9, Avg: 10.3, Max: 10.4, Diff: 0.5, Sum: 82.3]
      [GC Worker End (ms): Min: 483.7, Avg: 483.7, Max: 483.7, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 178.0M(178.0M)->0.0B(210.0M) Survivors: 26.0M->26.0M Heap: 521.5M(4096.0M)->398.9M(4096.0M)]
 [Times: user=0.06 sys=0.05, real=0.02 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0128721 secs]
   [Parallel Time: 11.6 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 526.4, Avg: 526.5, Max: 526.6, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.7]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
         [Processed Buffers: Min: 0, Avg: 1.3, Max: 3, Diff: 3, Sum: 10]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 11.0, Avg: 11.1, Max: 11.2, Diff: 0.2, Sum: 89.0]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.0]
         [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: 11.4, Avg: 11.5, Max: 11.5, Diff: 0.1, Sum: 91.6]
      [GC Worker End (ms): Min: 538.0, Avg: 538.0, Max: 538.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 0.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 210.0M(210.0M)->0.0B(622.0M) Survivors: 26.0M->30.0M Heap: 608.9M(4096.0M)->465.1M(4096.0M)]
 [Times: user=0.00 sys=0.00, real=0.02 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0231822 secs]
   [Parallel Time: 21.5 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 698.9, Avg: 699.0, Max: 699.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.7]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
         [Processed Buffers: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 20.9, Avg: 21.0, Max: 21.1, Diff: 0.2, Sum: 167.9]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.8]
         [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.1, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 21.3, Avg: 21.3, Max: 21.4, Diff: 0.1, Sum: 170.4]
      [GC Worker End (ms): Min: 720.3, Avg: 720.3, Max: 720.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.6 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 622.0M(622.0M)->0.0B(212.0M) Survivors: 30.0M->82.0M Heap: 1087.1M(4096.0M)->628.2M(4096.0M)]
 [Times: user=0.03 sys=0.06, real=0.08 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0155001 secs]
   [Parallel Time: 14.3 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 814.4, Avg: 814.5, Max: 814.6, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.6]
         [Processed Buffers: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 13.6, Avg: 13.8, Max: 13.9, Diff: 0.3, Sum: 110.2]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.2]
         [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: 14.1, Avg: 14.1, Max: 14.2, Diff: 0.2, Sum: 112.9]
      [GC Worker End (ms): Min: 828.6, Avg: 828.6, Max: 828.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 1.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.5 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 212.0M(212.0M)->0.0B(390.0M) Survivors: 82.0M->38.0M Heap: 840.2M(4096.0M)->685.6M(4096.0M)]
 [Times: user=0.05 sys=0.08, real=0.04 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0155628 secs]
   [Parallel Time: 14.6 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 905.1, Avg: 905.2, Max: 905.2, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.7]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 0.8]
         [Processed Buffers: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 13.8, Avg: 14.1, Max: 14.3, Diff: 0.5, Sum: 112.6]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.2]
         [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: 14.4, Avg: 14.4, Max: 14.5, Diff: 0.1, Sum: 115.6]
      [GC Worker End (ms): Min: 919.6, Avg: 919.6, Max: 919.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 0.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 390.0M(390.0M)->0.0B(502.0M) Survivors: 38.0M->54.0M Heap: 1075.6M(4096.0M)->785.2M(4096.0M)]
 [Times: user=0.01 sys=0.11, real=0.03 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0216765 secs]
   [Parallel Time: 19.7 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 997.7, Avg: 997.7, Max: 997.8, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.7]
      [Update RS (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8]
         [Processed Buffers: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 19.1, Avg: 19.2, Max: 19.3, Diff: 0.2, Sum: 153.9]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
         [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: 19.5, Avg: 19.6, Max: 19.6, Diff: 0.1, Sum: 156.4]
      [GC Worker End (ms): Min: 1017.3, Avg: 1017.3, Max: 1017.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 1.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.8 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 502.0M(502.0M)->0.0B(760.0M) Survivors: 54.0M->70.0M Heap: 1287.2M(4096.0M)->920.4M(4096.0M)]
 [Times: user=0.05 sys=0.08, real=0.11 secs]
执行结束!共生成对象次数:11931
Heap
 garbage-first heap   total 4194304K, used 1003944K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
  region size 2048K, 66 young (135168K), 35 survivors (71680K)
 Metaspace       used 2619K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

对G1 GC日志中的字段进行解释：

[GC pause (G1 Evacuation Pause) (young), 0.0099569 secs]:G1转移暂停，只清理年轻代空间。持续的系统时间为0.0099569秒。
[Parallel Time: 7.9 ms, GC Workers: 8]：表明后面的活动由8个 Worker 线程并行执行, 消耗时间为7.9毫秒。
GC Worker Start (ms)：相对于 pause 开始的时间戳，GC的worker线程开始启动所用时间。如果 Min 和 Max 差别很大，则表明本机其他进程所使用的线程数量过多，挤占了GC的CPU时间。
Ext Root Scanning (ms)：用了多长时间来扫描堆外(non-heap)的root，如classloaders, JNI引用, JVM的系统root等。后面显示了运行时间, “Sum” 指的是CPU时间。
Update RS (ms)：更新Remembered Sets使用的时间。
Processed Buffers：每个 worker 线程处理了多少个本地缓冲区(local buffer)。
Scan RS (ms)：用了多长时间扫描来自RSet的引用。
Code Root Scanning (ms)：用了多长时间来扫描实际代码中的 root。
Object Copy (ms)：用了多长时间来拷贝收集区内的存活对象。
Termination (ms)：GC的worker线程用了多长时间来确保自身可以安全地停止，这段时间什么也不用做， stop 之后该线程就终止运行了。
Termination Attempts：GC的worker 线程尝试多少次 try 和 teminate。如果worker发现还有一些任务没处理完，则这一次尝试就是失败的，暂时还不能终止。
GC Worker Other (ms)：处理一些琐碎的小活动所用的时间，在GC日志中不值得单独列出来。
GC Worker Total (ms)：GC的worker 线程的工作时间总计。
GC Worker End (ms)：相对于 pause 开始的时间戳，GC的worker 线程完成作业的时间。通常来说这部分数字应该大致相等，否则就说明有太多的线程被挂起，很可能是因为坏邻居效应(noisy neighbor) 所导致的。
Code Root Fixup：释放用于管理并行活动的内部数据。一般都接近于零。这是串行执行的过程。
Code Root Purge：清理其他部分数据，也是非常快的，但如非必要则几乎等于零。这是串行执行的过程。
Clear CT：清理 card table 中 cards 的时间。清理工作只是简单地删除“脏”状态，此状态用来标识一个字段是否被更新的，供Remembered Sets使用。
Other：其他活动消耗的时间，其中有很多也是并行执行的。
Choose CSet：选择CSet使用时间，CSet是指Collection Set，和RSet(Remembered Set)一样，用于辅助GC，用空间换时间。
Ref Proc：处理非强引用(non-strong)的时间: 进行清理或者决定是否需要清理。
Ref Enq：用来将剩下的 non-strong 引用排列到合适的 ReferenceQueue中。
Redirty Cards：重新脏化卡片。排队引用可能会更新RSet，所以需要对关联的Card重新脏化。
Humongous Register和Humongous Reclaim：主要是对巨型对象回收的信息，youngGC阶段会对RSet中有引用的短命的巨型对象进行回收，巨型对象会直接回收而不需要进行转移（转移代价巨大，也没必要）。
Free CSet：释放CSet中的region到free list使用时间。
Eden: 204.0M(204.0M)->0.0B(178.0M) Survivors: 0.0B->26.0M Heap: 204.0M(4096.0M)->65.2M(4096.0M)：暂停之前和暂停之后， Eden 区的使用量/总容量。暂停之前和暂停之后，存活区的使用量。暂停之前和暂停之后，整个堆内存的使用量与总容量。
Times: user=0.00 sys=0.00, real=0.01 secs： GC事件的持续时间, 通过三个部分（用户线程，系统调用，应用程序暂停的时间）来衡量。

小结：

G1是一个有整理内存过程的垃圾收集器，不会产生很多内存碎片。
在实现高吞吐量的同时，G1的Stop The World(STW)更可控，在停顿时间上添加了预测机制，用户可以指定期望停顿时间。
G1能与应用程序线程并发执行。

如何选择GC

参考资料：

Midnight

分析G1 GC日志

如何选择GC

Related Posts...

从0到1手写缓存cache之实现list命令 22 Jun 2024

从0到1手写缓存cache之实现string命令 19 Jun 2024

从0到1手写缓存cache之初步实现缓存框架 18 Jun 2024