海边别墅

# GC日志专题

所有对象的创建，生命周期中的使用，到最后销毁的整个过程，都是由GC模块管理的，真正应该称之为内存管理器。

# GC日志打印常用参数

打印GC日志： java -XX:+PrintGCDetails xxxclass 执行时，会打印gc的详细日志

-XX:+PrintGCDateStamps 日志会打印时间戳

-Xloggc:gc.demo.log 将gc日志输出到指定文件gc.demo.log

# 解析GC日志

下面会使用同一段程序，切换多个GC，来解析GC日志

执行的代码：

/*
演示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;
    }
}

# 并行GC

Java8默认的GC

下面是产生YoungGC时的日志示例：

jesse$ java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xmx2g -Xms2g javaclass

2021-05-15T15:57:00.829+0800: [GC (Allocation Failure) [PSYoungGen: 524800K->87022K(611840K)] 524800K->153159K(2010112K), 0.0405788 secs] [Times: user=0.19 sys=0.12, real=0.04 secs] 
2021-05-15T15:57:00.971+0800: [GC (Allocation Failure) [PSYoungGen: 611822K->87024K(611840K)] 677959K->266402K(2010112K), 0.0534516 secs] [Times: user=0.23 sys=0.20, real=0.05 secs] 
2021-05-15T15:57:01.120+0800: [GC (Allocation Failure) [PSYoungGen: 611495K->87035K(611840K)] 790873K->382782K(2010112K), 0.0576040 secs] [Times: user=0.36 sys=0.09, real=0.06 secs] 
2021-05-15T15:57:01.270+0800: [GC (Allocation Failure) [PSYoungGen: 611835K->87027K(611840K)] 907582K->497519K(2010112K), 0.0584238 secs] [Times: user=0.36 sys=0.11, real=0.06 secs] 
2021-05-15T15:57:01.421+0800: [GC (Allocation Failure) [PSYoungGen: 611827K->87029K(611840K)] 1022319K->621339K(2010112K), 0.0617433 secs] [Times: user=0.34 sys=0.15, real=0.06 secs] 
2021-05-15T15:57:01.577+0800: [GC (Allocation Failure) [PSYoungGen: 611711K->87035K(321024K)] 1146020K->733392K(1719296K), 0.0685264 secs] [Times: user=0.31 sys=0.19, real=0.08 secs] 
执行结束!共生成对象次数:11859
Heap
 PSYoungGen      total 321024K, used 96528K [0x00000000d5580000, 0x0000000100000000, 0x0000000100000000)
  eden space 233984K, 4% used [0x00000000d5580000,0x00000000d5ec53c8,0x00000000e3a00000)
  from space 87040K, 99% used [0x00000000fab00000,0x00000000ffffeea0,0x0000000100000000)
  to   space 232448K, 0% used [0x00000000e3a00000,0x00000000e3a00000,0x00000000f1d00000)
 ParOldGen       total 1398272K, used 646357K [0x0000000080000000, 0x00000000d5580000, 0x00000000d5580000)
  object space 1398272K, 46% used [0x0000000080000000,0x00000000a7735530,0x00000000d5580000)
 Metaspace       used 2546K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 273K, capacity 386K, committed 512K, reserved 1048576K

接下来我们分析下GC日志具体有什么内容：先看日志第一行

日志 含义
2021-05-15T15:57:00.829+0800 是-XX:+PrintGCDateStamps加上后打印出来的时间戳
GC (Allocation Failure) 表示gc执行的原因，此处意为分配失败
PSYoungGen: 524800K->87022K(611840K) PSYoungGen：并行young GC
表示young区占用的内存（对象）从524800K压缩到了87022K，括号里的611840K代表整个young区的最大容量
524800K->153159K(2010112K) 后面这段表示整个堆内存的内存占用，这里与上面young区差的就是old区
0.0405788 secs YoungGC的时间
[Times: user=0.19 sys=0.12, real=0.04 secs] youngGC的用户耗时、系统耗时、实际耗时

可以看出第一次垃圾回收时young区和整个堆内存的内存占用是一致的，这是因为最开始还没有对象晋升到old区。

图文示例：

youngGC日志释义

下面是FullGC日志：

2021-05-17T23:01:02.587+0800: [Full GC (Ergonomics) [PSYoungGen: 17594K->0K(113664K)] [ParOldGen: 308012K->265261K(341504K)] 325607K->265261K(455168K), [Metaspace: 2540K->2540K(1056768K)], 0.0694247 secs] [Times: user=0.52 sys=0.01, real=0.06 secs] 
2021-05-17T23:01:02.668+0800: [GC (Allocation Failure) [PSYoungGen: 56832K->17484K(113664K)] 322093K->282745K(455168K), 0.0064969 secs] [Times: user=0.05 sys=0.00, real=0.00 secs] 
2021-05-17T23:01:02.685+0800: [GC (Allocation Failure) [PSYoungGen: 74213K->18540K(113664K)] 339474K->300211K(455168K), 0.0120198 secs] [Times: user=0.09 sys=0.00, real=0.01 secs] 
2021-05-17T23:01:02.706+0800: [GC (Allocation Failure) [PSYoungGen: 75341K->25265K(113664K)] 357011K->323768K(455168K), 0.0140829 secs] [Times: user=0.11 sys=0.00, real=0.01 secs] 
2021-05-17T23:01:02.721+0800: [Full GC (Ergonomics) [PSYoungGen: 25265K->0K(113664K)] [ParOldGen: 298502K->282852K(341504K)] 323768K->282852K(455168K), [Metaspace: 2540K->2540K(1056768K)], 0.0725073 secs] [Times: user=0.56 sys=0.00, real=0.07 secs]

分析FullGC日志：第一行

  1. Full GC (Ergonomics)代表执行的是FullGC，Ergonomics的中文意思是人体工程学，也就是根据算法估算下次可能会无法分配内存，提前执行一次FullGC。

出现FullGC的常见原因：

  • Full GC (Allocation Failure)

  • Full GC (Ergonomics)

  • Full GC (Metadata GC Threshold)

在JVM中的垃圾收集器中的Ergonomics就是负责自动的调解gc暂停时间和吞吐量之间的平衡，然后你的虚拟机性能更好的一种做法。

  1. [PSYoungGen: 17594K->0K(113664K)]young区在FullGC时会清空掉。
  2. [ParOldGen: 308012K->265261K(341504K)]old区在FullGC时会进行压缩。
  3. [Metaspace: 2540K->2540K(1056768K)]元数据区执行FullGC时没有变化，jdk7是PSPermGen（永久代），jdk8更改为meta区（元空间）。
  4. 0.0694247 secs代表FullGC的耗时
  5. [Times: user=0.52 sys=0.01, real=0.06 secs]与youngGC一样。

图文示例：

FullGC日志详解

# 串行GC

jesse$ java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseSerialGC  -Xmx100m -Xms100m GCLogAnalysis

2021-05-18T23:47:27.922+0800: [GC (Allocation Failure) 2021-05-18T23:47:27.922+0800: [DefNew: 26896K->3392K(30720K), 0.0044572 secs] 26896K->8430K(99008K), 0.0045628 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2021-05-18T23:47:27.936+0800: [GC (Allocation Failure) 2021-05-18T23:47:27.936+0800: [DefNew: 30443K->3391K(30720K), 0.0076210 secs] 35482K->17402K(99008K), 0.0076747 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
2021-05-18T23:47:27.957+0800: [GC (Allocation Failure) 2021-05-18T23:47:27.957+0800: [DefNew: 30719K->3372K(30720K), 0.0048223 secs] 44730K->25250K(99008K), 0.0048821 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2021-05-18T23:47:27.970+0800: [GC (Allocation Failure) 2021-05-18T23:47:27.970+0800: [DefNew: 30700K->3381K(30720K), 0.0050724 secs] 52578K->33409K(99008K), 0.0051447 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-05-18T23:47:27.982+0800: [GC (Allocation Failure) 2021-05-18T23:47:27.982+0800: [DefNew: 30709K->3389K(30720K), 0.0073571 secs] 60737K->44768K(99008K), 0.0074114 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2021-05-18T23:47:27.996+0800: [GC (Allocation Failure) 2021-05-18T23:47:27.996+0800: [DefNew: 30453K->3391K(30720K), 0.0061754 secs] 71832K->53531K(99008K), 0.0062303 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
2021-05-18T23:47:28.009+0800: [GC (Allocation Failure) 2021-05-18T23:47:28.009+0800: [DefNew: 30550K->3389K(30720K), 0.0062526 secs] 80690K->62820K(99008K), 0.0063055 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-18T23:47:28.020+0800: [GC (Allocation Failure) 2021-05-18T23:47:28.020+0800: [DefNew: 30622K->30622K(30720K), 0.0000235 secs]2021-05-18T23:47:28.020+0800: [Tenured: 59431K->68237K(68288K), 0.0158607 secs] 90053K->71211K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0159623 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2021-05-18T23:47:28.042+0800: [Full GC (Allocation Failure) 2021-05-18T23:47:28.042+0800: [Tenured: 68237K->68246K(68288K), 0.0152800 secs] 98730K->79069K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0153404 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2021-05-18T23:47:28.061+0800: [Full GC (Allocation Failure) 2021-05-18T23:47:28.061+0800: [Tenured: 68246K->67959K(68288K), 0.0149245 secs] 98878K->84519K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0149797 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

可以看出UseSerialGC在young区使用了DefNew垃圾收集器，Tenured则是代表old区，并且在某一次非FullGC时，同时执行了young区和old区的垃圾回收。其他与并行GC区别不大。

# CMS GC

jesse$ java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC  -Xmx100m -Xms100m GCLogAnalysis

2021-05-19T00:11:15.132+0800: [GC (Allocation Failure) 2021-05-19T00:11:15.132+0800: [ParNew: 27229K->3391K(30720K), 0.0037007 secs] 27229K->10610K(99008K), 0.0037781 secs] [Times: user=0.01 sys=0.02, real=0.00 secs] 
-------此处发生多次GC (Allocation Failure)-------
2021-05-19T00:11:15.192+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 41471K(68288K)] 45517K(99008K), 0.0002588 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.193+0800: [CMS-concurrent-mark-start]
2021-05-19T00:11:15.193+0800: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.193+0800: [CMS-concurrent-preclean-start]
2021-05-19T00:11:15.194+0800: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.194+0800: [CMS-concurrent-abortable-preclean-start]
2021-05-19T00:11:15.198+0800: [GC (Allocation Failure) 2021-05-19T00:11:15.198+0800: [ParNew: 30667K->3376K(30720K), 0.0064299 secs] 72138K->54772K(99008K), 0.0064830 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
2021-05-19T00:11:15.210+0800: [GC (Allocation Failure) 2021-05-19T00:11:15.210+0800: [ParNew: 30704K->3391K(30720K), 0.0049883 secs] 82100K->62027K(99008K), 0.0050630 secs] [Times: user=0.04 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.221+0800: [GC (Allocation Failure) 2021-05-19T00:11:15.221+0800: [ParNew: 30708K->30708K(30720K), 0.0000506 secs]2021-05-19T00:11:15.221+0800: [CMS2021-05-19T00:11:15.221+0800: [CMS-concurrent-abortable-preclean: 0.001/0.028 secs] [Times: user=0.10 sys=0.00, real=0.03 secs] 
 (concurrent mode failure): 58635K->65869K(68288K), 0.0192665 secs] 89344K->65869K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0194171 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2021-05-19T00:11:15.247+0800: [GC (Allocation Failure) 2021-05-19T00:11:15.247+0800: [ParNew: 27072K->27072K(30720K), 0.0000383 secs]2021-05-19T00:11:15.247+0800: [CMS: 65869K->68067K(68288K), 0.0169597 secs] 92942K->72852K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0171223 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2021-05-19T00:11:15.264+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 68067K(68288K)] 73863K(99008K), 0.0004737 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.264+0800: [CMS-concurrent-mark-start]
2021-05-19T00:11:15.265+0800: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.265+0800: [CMS-concurrent-preclean-start]
2021-05-19T00:11:15.266+0800: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.266+0800: [CMS-concurrent-abortable-preclean-start]
2021-05-19T00:11:15.266+0800: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.266+0800: [GC (CMS Final Remark) [YG occupancy: 9697 K (30720 K)]2021-05-19T00:11:15.266+0800: [Rescan (parallel) , 0.0002076 secs]2021-05-19T00:11:15.266+0800: [weak refs processing, 0.0000140 secs]2021-05-19T00:11:15.266+0800: [class unloading, 0.0002604 secs]2021-05-19T00:11:15.266+0800: [scrub symbol table, 0.0003168 secs]2021-05-19T00:11:15.267+0800: [scrub string table, 0.0002255 secs][1 CMS-remark: 68067K(68288K)] 77765K(99008K), 0.0010911 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2021-05-19T00:11:15.267+0800: [CMS-concurrent-sweep-start]
2021-05-19T00:11:15.267+0800: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.267+0800: [CMS-concurrent-reset-start]
2021-05-19T00:11:15.267+0800: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.271+0800: [GC (Allocation Failure) 2021-05-19T00:11:15.271+0800: [ParNew: 30694K->30694K(30720K), 0.0001260 secs]2021-05-19T00:11:15.271+0800: [CMS: 68067K->68203K(68288K), 0.0138106 secs] 98761K->81654K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0140288 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

----------------此处省略多行类似GC日志----------------

2021-05-19T00:11:15.337+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 68117K(68288K)] 92674K(99008K), 0.0006324 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.338+0800: [CMS-concurrent-mark-start]
2021-05-19T00:11:15.338+0800: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.338+0800: [CMS-concurrent-preclean-start]
2021-05-19T00:11:15.339+0800: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2021-05-19T00:11:15.339+0800: [CMS-concurrent-abortable-preclean-start]
2021-05-19T00:11:15.339+0800: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.339+0800: [Full GC (Allocation Failure) 2021-05-19T00:11:15.339+0800: [CMS (concurrent mode failure): 68117K->68261K(68288K), 0.0082180 secs] 98833K->92954K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0082750 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2021-05-19T00:11:15.349+0800: [Full GC (Allocation Failure) 2021-05-19T00:11:15.349+0800: [CMS: 68261K->68227K(68288K), 0.0194007 secs] 98965K->94020K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0194681 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2021-05-19T00:11:15.368+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 68227K(68288K)] 94301K(99008K), 0.0003624 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.369+0800: [CMS-concurrent-mark-start]
2021-05-19T00:11:15.369+0800: [Full GC (Allocation Failure) 2021-05-19T00:11:15.369+0800: [CMS2021-05-19T00:11:15.371+0800: [CMS-concurrent-mark: 0.001/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 (concurrent mode failure): 68227K->68281K(68288K), 0.0221579 secs] 98721K->95980K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0222169 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2021-05-19T00:11:15.392+0800: [Full GC (Allocation Failure) 2021-05-19T00:11:15.392+0800: [CMS: 68281K->68213K(68288K), 0.0216581 secs] 98827K->96411K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0217184 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2021-05-19T00:11:15.414+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 68213K(68288K)] 96995K(99008K), 0.0004368 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.415+0800: [CMS-concurrent-mark-start]
2021-05-19T00:11:15.415+0800: [Full GC (Allocation Failure) 2021-05-19T00:11:15.415+0800: [CMS2021-05-19T00:11:15.417+0800: [CMS-concurrent-mark: 0.001/0.002 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
 (concurrent mode failure): 68213K->68198K(68288K), 0.0213393 secs] 98855K->96402K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0214075 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2021-05-19T00:11:15.437+0800: [Full GC (Allocation Failure) 2021-05-19T00:11:15.437+0800: [CMS: 68198K->68143K(68288K), 0.0054181 secs] 98795K->97051K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0055051 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2021-05-19T00:11:15.443+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 68143K(68288K)] 97426K(99008K), 0.0007019 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.444+0800: [CMS-concurrent-mark-start]
2021-05-19T00:11:15.444+0800: [Full GC (Allocation Failure) 2021-05-19T00:11:15.444+0800: [CMS2021-05-19T00:11:15.446+0800: [CMS-concurrent-mark: 0.001/0.002 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
 (concurrent mode failure): 68143K->68143K(68288K), 0.0032796 secs] 98614K->97544K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0033336 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2021-05-19T00:11:15.448+0800: [Full GC (Allocation Failure) 2021-05-19T00:11:15.448+0800: [CMS: 68143K->68143K(68288K), 0.0013556 secs] 98839K->98223K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0014120 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.449+0800: [Full GC (Allocation Failure) 2021-05-19T00:11:15.450+0800: [CMS: 68143K->68143K(68288K), 0.0011270 secs] 98546K->98546K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0011929 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.451+0800: [Full GC (Allocation Failure) 2021-05-19T00:11:15.451+0800: [CMS: 68143K->68125K(68288K), 0.0152224 secs] 98546K->98527K(99008K), [Metaspace: 2540K->2540K(1056768K)], 0.0152626 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2021-05-19T00:11:15.466+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 68125K(68288K)] 98527K(99008K), 0.0002910 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-05-19T00:11:15.467+0800: [CMS-concurrent-mark-start]
Exception in thread "main" 2021-05-19T00:11:15.467+0800: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2021-05-19T00:11:15.467+0800: [CMS-concurrent-preclean-start]
java.lang.OutOfMemoryError: Java heap space
	at GCLogAnalysis.generateGarbage(GCLogAnalysis.java:42)
	at GCLogAnalysis.main(GCLogAnalysis.java:25)

可以看出CMS GC在young区使用的是ParNew垃圾收集器，在老年代就是使用CMS垃圾收集器了，可以发现CMS垃圾收集会执行很多步骤。

# G1 GC

jesse$ java -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+UseG1GC  -Xmx100m -Xms100m GCLogAnalysis

2021-05-19T00:45:29.601+0800: [GC pause (G1 Evacuation Pause) (young) 29M->10093K(100M), 0.0032925 secs]
2021-05-19T00:45:29.621+0800: [GC pause (G1 Evacuation Pause) (young) 45M->24M(100M), 0.0048468 secs]
2021-05-19T00:45:29.642+0800: [GC pause (G1 Evacuation Pause) (young)-- 75M->49M(100M), 0.0049933 secs]
2021-05-19T00:45:29.647+0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 50M->48M(100M), 0.0021580 secs]
2021-05-19T00:45:29.650+0800: [GC concurrent-root-region-scan-start]
2021-05-19T00:45:29.650+0800: [GC concurrent-root-region-scan-end, 0.0000263 secs]
2021-05-19T00:45:29.650+0800: [GC concurrent-mark-start]
2021-05-19T00:45:29.651+0800: [GC concurrent-mark-end, 0.0012330 secs]
2021-05-19T00:45:29.651+0800: [GC remark, 0.0010260 secs]
2021-05-19T00:45:29.652+0800: [GC cleanup 54M->54M(100M), 0.0003197 secs]
2021-05-19T00:45:29.658+0800: [GC pause (G1 Evacuation Pause) (young)-- 82M->69M(100M), 0.0033098 secs]
2021-05-19T00:45:29.661+0800: [GC pause (G1 Evacuation Pause) (mixed) 70M->63M(100M), 0.0017333 secs]
2021-05-19T00:45:29.665+0800: [GC pause (G1 Evacuation Pause) (young) 75M->67M(100M), 0.0018694 secs]
2021-05-19T00:45:29.667+0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 68M->67M(100M), 0.0012085 secs]
2021-05-19T00:45:29.669+0800: [GC concurrent-root-region-scan-start]
2021-05-19T00:45:29.669+0800: [GC concurrent-root-region-scan-end, 0.0001312 secs]
2021-05-19T00:45:29.669+0800: [GC concurrent-mark-start]
2021-05-19T00:45:29.670+0800: [GC concurrent-mark-end, 0.0009429 secs]
2021-05-19T00:45:29.670+0800: [GC remark, 0.0010988 secs]
2021-05-19T00:45:29.671+0800: [GC cleanup 75M->74M(100M), 0.0003737 secs]
2021-05-19T00:45:29.672+0800: [GC concurrent-cleanup-start]
2021-05-19T00:45:29.672+0800: [GC concurrent-cleanup-end, 0.0000206 secs]
2021-05-19T00:45:29.673+0800: [GC pause (G1 Evacuation Pause) (young) 82M->70M(100M), 0.0015186 secs]
2021-05-19T00:45:29.675+0800: [GC pause (G1 Evacuation Pause) (mixed) 78M->64M(100M), 0.0022592 secs]
2021-05-19T00:45:29.679+0800: [GC pause (G1 Evacuation Pause) (mixed) 70M->65M(100M), 0.0014884 secs]
2021-05-19T00:45:29.680+0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 66M->66M(100M), 0.0006846 secs]
2021-05-19T00:45:29.681+0800: [GC concurrent-root-region-scan-start]
2021-05-19T00:45:29.681+0800: [GC concurrent-root-region-scan-end, 0.0000456 secs]
2021-05-19T00:45:29.681+0800: [GC concurrent-mark-start]
2021-05-19T00:45:29.682+0800: [GC concurrent-mark-end, 0.0008500 secs]
2021-05-19T00:45:29.682+0800: [GC remark, 0.0010961 secs]
2021-05-19T00:45:29.683+0800: [GC cleanup 72M->72M(100M), 0.0003134 secs]
2021-05-19T00:45:29.684+0800: [GC pause (G1 Evacuation Pause) (young) 75M->68M(100M), 0.0017291 secs]
2021-05-19T00:45:29.687+0800: [GC pause (G1 Evacuation Pause) (mixed) 77M->70M(100M), 0.0025035 secs]
2021-05-19T00:45:29.691+0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 73M->71M(100M), 0.0014056 secs]
2021-05-19T00:45:29.692+0800: [GC concurrent-root-region-scan-start]
2021-05-19T00:45:29.692+0800: [GC concurrent-root-region-scan-end, 0.0001464 secs]
2021-05-19T00:45:29.692+0800: [GC concurrent-mark-start]
2021-05-19T00:45:29.693+0800: [GC concurrent-mark-end, 0.0009321 secs]
2021-05-19T00:45:29.693+0800: [GC remark, 0.0011006 secs]
2021-05-19T00:45:29.694+0800: [GC cleanup 78M->78M(100M), 0.0003301 secs]
2021-05-19T00:45:29.695+0800: [GC pause (G1 Evacuation Pause) (young) 79M->74M(100M), 0.0013411 secs]
2021-05-19T00:45:29.698+0800: [GC pause (G1 Evacuation Pause) (mixed) 81M->73M(100M), 0.0018896 secs]
2021-05-19T00:45:29.700+0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 74M->73M(100M), 0.0007626 secs]
2021-05-19T00:45:29.700+0800: [GC concurrent-root-region-scan-start]
2021-05-19T00:45:29.700+0800: [GC concurrent-root-region-scan-end, 0.0000164 secs]
2021-05-19T00:45:29.700+0800: [GC concurrent-mark-start]
2021-05-19T00:45:29.702+0800: [GC concurrent-mark-end, 0.0010740 secs]
2021-05-19T00:45:29.702+0800: [GC remark, 0.0012480 secs]
2021-05-19T00:45:29.703+0800: [GC cleanup 82M->82M(100M), 0.0004452 secs]
2021-05-19T00:45:29.704+0800: [GC pause (G1 Evacuation Pause) (young)-- 83M->82M(100M), 0.0013198 secs]
2021-05-19T00:45:29.706+0800: [GC pause (G1 Evacuation Pause) (mixed)-- 85M->85M(100M), 0.0007048 secs]
2021-05-19T00:45:29.706+0800: [Full GC (Allocation Failure)  85M->72M(100M), 0.0134278 secs]
2021-05-19T00:45:29.720+0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 74M->73M(100M), 0.0019245 secs]
2021-05-19T00:45:29.722+0800: [GC concurrent-root-region-scan-start]
2021-05-19T00:45:29.722+0800: [GC concurrent-root-region-scan-end, 0.0000880 secs]
2021-05-19T00:45:29.722+0800: [GC concurrent-mark-start]
2021-05-19T00:45:29.723+0800: [GC pause (G1 Humongous Allocation) (young)-- 77M->75M(100M), 0.0013619 secs]
2021-05-19T00:45:29.725+0800: [GC pause (G1 Evacuation Pause) (young) 77M->75M(100M), 0.0008103 secs]
2021-05-19T00:45:29.726+0800: [GC concurrent-mark-end, 0.0033717 secs]
2021-05-19T00:45:29.726+0800: [GC remark, 0.0012500 secs]
2021-05-19T00:45:29.727+0800: [GC cleanup 77M->77M(100M), 0.0004065 secs]
2021-05-19T00:45:29.728+0800: [GC pause (G1 Evacuation Pause) (young)-- 77M->76M(100M), 0.0008329 secs]
2021-05-19T00:45:29.729+0800: [GC pause (G1 Humongous Allocation) (young)-- 77M->77M(100M), 0.0010191 secs]
2021-05-19T00:45:29.730+0800: [Full GC (Allocation Failure)  77M->74M(100M), 0.0031904 secs]
2021-05-19T00:45:29.733+0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 76M->75M(100M), 0.0012407 secs]
2021-05-19T00:45:29.735+0800: [GC concurrent-root-region-scan-start]
2021-05-19T00:45:29.735+0800: [GC concurrent-root-region-scan-end, 0.0000535 secs]
2021-05-19T00:45:29.735+0800: [GC concurrent-mark-start]
2021-05-19T00:45:29.735+0800: [GC pause (G1 Evacuation Pause) (young)-- 76M->76M(100M), 0.0010960 secs]
2021-05-19T00:45:29.736+0800: [Full GC (Allocation Failure)  76M->76M(100M), 0.0023247 secs]
2021-05-19T00:45:29.739+0800: [GC concurrent-mark-abort]
2021-05-19T00:45:29.739+0800: [GC pause (G1 Evacuation Pause) (young)-- 77M->77M(100M), 0.0027059 secs]
2021-05-19T00:45:29.742+0800: [Full GC (Allocation Failure)  77M->75M(100M), 0.0026869 secs]
2021-05-19T00:45:29.745+0800: [GC pause (G1 Evacuation Pause) (young)-- 76M->76M(100M), 0.0010872 secs]
2021-05-19T00:45:29.746+0800: [Full GC (Allocation Failure)  76M->75M(100M), 0.0035007 secs]
2021-05-19T00:45:29.750+0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark)-- 76M->76M(100M), 0.0015863 secs]
2021-05-19T00:45:29.751+0800: [GC concurrent-root-region-scan-start]
2021-05-19T00:45:29.751+0800: [GC concurrent-root-region-scan-end, 0.0000255 secs]
2021-05-19T00:45:29.751+0800: [GC concurrent-mark-start]
2021-05-19T00:45:29.751+0800: [GC pause (G1 Humongous Allocation) (young) 76M->76M(100M), 0.0008159 secs]
2021-05-19T00:45:29.752+0800: [Full GC (Allocation Failure)  76M->75M(100M), 0.0023190 secs]
2021-05-19T00:45:29.755+0800: [GC pause (G1 Evacuation Pause) (young) 76M->75M(100M), 0.0010713 secs]
2021-05-19T00:45:29.756+0800: [GC concurrent-mark-abort]
2021-05-19T00:45:29.756+0800: [GC pause (G1 Evacuation Pause) (young)-- 76M->76M(100M), 0.0008249 secs]
2021-05-19T00:45:29.757+0800: [Full GC (Allocation Failure)  76M->76M(100M), 0.0021754 secs]
2021-05-19T00:45:29.760+0800: [GC pause (G1 Evacuation Pause) (young)-- 77M->77M(100M), 0.0011265 secs]
2021-05-19T00:45:29.761+0800: [Full GC (Allocation Failure)  77M->76M(100M), 0.0022905 secs]
2021-05-19T00:45:29.763+0800: [Full GC (Allocation Failure)  76M->76M(100M), 0.0026052 secs]
2021-05-19T00:45:29.766+0800: [GC pause (G1 Evacuation Pause) (young) 76M->76M(100M), 0.0011091 secs]
2021-05-19T00:45:29.767+0800: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 76M->76M(100M), 0.0008196 secs]
2021-05-19T00:45:29.768+0800: [GC concurrent-root-region-scan-start]
2021-05-19T00:45:29.768+0800: [GC concurrent-root-region-scan-end, 0.0000298 secs]
2021-05-19T00:45:29.768+0800: [GC concurrent-mark-start]
2021-05-19T00:45:29.768+0800: [Full GC (Allocation Failure)  76M->250K(100M), 0.0022981 secs]
2021-05-19T00:45:29.771+0800: [GC concurrent-mark-abort]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
	at java.util.Arrays.copyOfRange(Arrays.java:3664)
	at java.lang.String.<init>(String.java:207)
	at java.lang.StringBuilder.toString(StringBuilder.java:407)
	at GCLogAnalysis.generateGarbage(GCLogAnalysis.java:58)
	at GCLogAnalysis.main(GCLogAnalysis.java:25)

同样可以看出G1GC也是有类似于CMSGC一样的标记清除步骤。

日志 含义
[GC pause (G1 Evacuation Pause) (young) 29M->10093K(100M), 0.0032925 secs] 转移暂停，young模式，从29M压缩到10M，花费了多少时间
[GC pause (G1 Evacuation Pause) (mixed) 70M->65M(100M), 0.0014884 secs] 混合模式

下图同样是G1的日志图，打印出了更详细的细节，下方更说明了图中标记的含义：

image-20220113233444999

1 表示 GC 发生的时间，一般使用可读的方式打印；

2 表示日志表明是 G1 的“转移暂停: 混合模式”，停顿了约 223ms；

3 表明由 8 个 Worker 线程并行执行，消耗了 214ms；

4 表示 Diff 越小越好，说明每个工作线程的速度都很均匀；

5 表示外部根区扫描，外部根是堆外区。JNI 引用，JVM 系统目录，Classloaders 等；

6 表示更新 RSet 的时间信息；

7 表示该任务主要是对 CSet 中存活对象进行转移（复制）；

8 表示花在 GC 之外的工作线程的时间；

9 表示并行阶段的 GC 总时间；

10 表示其他清理活动；

11表示收集结果统计；

12 表示时间花费统计。

# 可视化工具

  • gceasy

  • GCViewer

  • 使用脚本简单过滤

# Linux耗时的三维度

在GC日志中也能看到这三个时间维度，下表做了解释，一般只关注real即可。

维度 含义
real 实际花费的时间，指的是从开始到结束所花费的时间。比如进程在等待 I/O 完成，这个阻塞时间也会被计算在内；
user 进程在用户态（User Mode）所花费的时间，只统计本进程所使用的时间，注意是指多核；
sys 进程在核心态（Kernel Mode）花费的 CPU 时间量，指的是内核中的系统调用所花费的时间，只统计本进程所使用的时间。
修改于: 8/11/2022, 3:17:56 PM

JVM入门与进阶 →