分析CMS GC日志

28 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

CMS的官方名称为 Mostly Concurrent Mark and Sweep Garbage Collector(主要并发-标记-清除-垃圾收集器)。其对年轻代采用标记-复制算法, 对老年代使用标记-清除算法。

CMS的设计目标是避免在老年代垃圾收集时出现长时间的卡顿。主要通过两种手段来达成此目标。

第一，不对老年代进行整理, 而是使用空闲列表(free-lists)来管理内存空间的回收。
第二，在标记-清除阶段的大部分工作和应用线程一起并发执行。

也就是说, 在这些阶段并没有明显的应用线程暂停，低延迟，高响应比。但值得注意的是，它仍然和应用线程争抢CPU时间，吞吐量会有所下降。默认情况下， CMS 使用的并发线程数等于CPU内核数的 1/4。

CMS过程多，较复杂，这里只给出一个演示案例。

案例（-Xms512m -Xmx51m）：

D:\>java -XX:+UseConcMarkSweepGC -Xms512m -Xmx512m -XX:+PrintGCDetails GCLogAnalysis
正在执行...
[GC (Allocation Failure) [ParNew: 139524K->17472K(157248K), 0.0081116 secs] 139524K->53858K(506816K), 0.0084194 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [ParNew: 157248K->17461K(157248K), 0.0111317 secs] 193634K->100350K(506816K), 0.0114263 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [ParNew: 157237K->17470K(157248K), 0.0190110 secs] 240126K->147606K(506816K), 0.0191201 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
[GC (Allocation Failure) [ParNew: 157246K->17471K(157248K), 0.0202185 secs] 287382K->191303K(506816K), 0.0204533 secs] [Times: user=0.11 sys=0.02, real=0.02 secs]
[GC (Allocation Failure) [ParNew: 157247K->17471K(157248K), 0.0202245 secs] 331079K->241173K(506816K), 0.0204438 secs] [Times: user=0.11 sys=0.01, real=0.02 secs]
[GC (CMS Initial Mark) [1 CMS-initial-mark: 223702K(349568K)] 241617K(506816K), 0.0006136 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-abortable-preclean-start]
[GC (Allocation Failure) [ParNew: 157247K->17471K(157248K), 0.0201002 secs] 380949K->289532K(506816K), 0.0202149 secs] [Times: user=0.09 sys=0.02, real=0.02 secs]
[GC (Allocation Failure) [ParNew: 157217K->17469K(157248K), 0.0192277 secs] 429279K->333751K(506816K), 0.0193328 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
[GC (Allocation Failure) [ParNew: 157245K->157245K(157248K), 0.0000573 secs][CMS[CMS-concurrent-abortable-preclean: 0.004/0.091 secs] [Times: user=0.30 sys=0.02, real=0.09 secs]
 (concurrent mode failure): 316281K->252015K(349568K), 0.0440026 secs] 473527K->252015K(506816K), [Metaspace: 2613K->2613K(1056768K)], 0.0445195 secs] [Times: user=0.05 sys=0.00, real=0.04 secs]
[GC (Allocation Failure) [ParNew: 139776K->17470K(157248K), 0.0088589 secs] 391791K->294554K(506816K), 0.0092332 secs] [Times: user=0.09 sys=0.00, real=0.01 secs]
[GC (CMS Initial Mark) [1 CMS-initial-mark: 277083K(349568K)] 297545K(506816K), 0.0005588 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-abortable-preclean-start]
[GC (Allocation Failure) [ParNew: 157246K->17471K(157248K), 0.0123281 secs] 434330K->339422K(506816K), 0.0126656 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [ParNew: 157247K->157247K(157248K), 0.0001621 secs][CMS[CMS-concurrent-abortable-preclean: 0.001/0.045 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
 (concurrent mode failure): 321950K->293344K(349568K), 0.0528400 secs] 479198K->293344K(506816K), [Metaspace: 2613K->2613K(1056768K)], 0.0537640 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
[GC (Allocation Failure) [ParNew: 139776K->17471K(157248K), 0.0099173 secs] 433120K->342675K(506816K), 0.0101634 secs] [Times: user=0.09 sys=0.00, real=0.01 secs]
[GC (CMS Initial Mark) [1 CMS-initial-mark: 325204K(349568K)] 342800K(506816K), 0.0029137 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [ParNew: 157247K->157247K(157248K), 0.0001170 secs][CMS (concurrent mode failure): 325204K->321810K(349568K), 0.0477790 secs] 482451K->321810K(506816K), [Metaspace: 2613K->2613K(1056768K)], 0.0533533 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
[GC (Allocation Failure) [ParNew: 139776K->139776K(157248K), 0.0002987 secs][CMS: 321810K->326699K(349568K), 0.0448380 secs] 461586K->326699K(506816K), [Metaspace: 2613K->2613K(1056768K)], 0.0460650 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
[GC (CMS Initial Mark) [1 CMS-initial-mark: 326699K(349568K)] 326973K(506816K), 0.0007281 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (CMS Final Remark) [YG occupancy: 28785 K (157248 K)][Rescan (parallel) , 0.0002592 secs][weak refs processing, 0.0000208 secs][class unloading, 0.0008936 secs][scrub symbol table, 0.0002973 secs][scrub string table, 0.0000928 secs][1 CMS-remark: 326699K(349568K)] 355485K(506816K), 0.0049802 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [ParNew: 139776K->139776K(157248K), 0.0003069 secs][CMS: 326197K->336731K(349568K), 0.0527671 secs] 465973K->336731K(506816K), [Metaspace: 2613K->2613K(1056768K)], 0.0560247 secs] [Times: user=0.05 sys=0.00, real=0.06 secs]
[GC (CMS Initial Mark) [1 CMS-initial-mark: 336731K(349568K)] 339780K(506816K), 0.0007651 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.05 sys=0.00, real=0.00 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (CMS Final Remark) [YG occupancy: 25128 K (157248 K)][Rescan (parallel) , 0.0003284 secs][weak refs processing, 0.0000299 secs][class unloading, 0.0002353 secs][scrub symbol table, 0.0004058 secs][scrub string table, 0.0001077 secs][1 CMS-remark: 336731K(349568K)] 361859K(506816K), 0.0092770 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [ParNew: 139776K->139776K(157248K), 0.0002000 secs][CMS: 336093K->341106K(349568K), 0.0473734 secs] 475869K->341106K(506816K), [Metaspace: 2613K->2613K(1056768K)], 0.0484223 secs] [Times: user=0.03 sys=0.01, real=0.05 secs]
[GC (CMS Initial Mark) [1 CMS-initial-mark: 341106K(349568K)] 344308K(506816K), 0.0003132 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (CMS Final Remark) [YG occupancy: 36942 K (157248 K)][Rescan (parallel) , 0.0004149 secs][weak refs processing, 0.0000188 secs][class unloading, 0.0002119 secs][scrub symbol table, 0.0002849 secs][scrub string table, 0.0000902 secs][1 CMS-remark: 341106K(349568K)] 378048K(506816K), 0.0040528 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [ParNew: 139776K->139776K(157248K), 0.0000658 secs][CMS: 338824K->343334K(349568K), 0.0446340 secs] 478600K->343334K(506816K), [Metaspace: 2613K->2613K(1056768K)], 0.0455519 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
[GC (CMS Initial Mark) [1 CMS-initial-mark: 343334K(349568K)] 343987K(506816K), 0.0006540 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.05 sys=0.00, real=0.00 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (CMS Final Remark) [YG occupancy: 26957 K (157248 K)][Rescan (parallel) , 0.0002413 secs][weak refs processing, 0.0000212 secs][class unloading, 0.0004218 secs][scrub symbol table, 0.0002805 secs][scrub string table, 0.0000875 secs][1 CMS-remark: 343334K(349568K)] 370291K(506816K), 0.0016550 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [ParNew: 139776K->139776K(157248K), 0.0001528 secs][CMS: 342197K->345032K(349568K), 0.0488002 secs] 481973K->345032K(506816K), [Metaspace: 2613K->2613K(1056768K)], 0.0500741 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
[GC (CMS Initial Mark) [1 CMS-initial-mark: 345032K(349568K)] 345176K(506816K), 0.0008459 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (CMS Final Remark) [YG occupancy: 21309 K (157248 K)][Rescan (parallel) , 0.0002177 secs][weak refs processing, 0.0000220 secs][class unloading, 0.0006460 secs][scrub symbol table, 0.0003373 secs][scrub string table, 0.0000925 secs][1 CMS-remark: 345032K(349568K)] 366342K(506816K), 0.0022575 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
执行结束!共生成对象次数:9876
Heap
 par new generation   total 157248K, used 86018K [0x00000000e0000000, 0x00000000eaaa0000, 0x00000000eaaa0000)
  eden space 139776K,  61% used [0x00000000e0000000, 0x00000000e5400bb0, 0x00000000e8880000)
  from space 17472K,   0% used [0x00000000e8880000, 0x00000000e8880000, 0x00000000e9990000)
  to   space 17472K,   0% used [0x00000000e9990000, 0x00000000e9990000, 0x00000000eaaa0000)
 concurrent mark-sweep generation total 349568K, used 343078K [0x00000000eaaa0000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 2619K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

现在对CMS GC日志中的关键字段进行解释：

首先发生的是年轻代的minor gc:

[GC (Allocation Failure) [ParNew: 139524K->17472K(157248K), 0.0081116 secs] 139524K->53858K(506816K), 0.0084194 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

GC (Allocation Failure ：GC表明这是一次小型GC(Minor GC)。触发垃圾收集的原因是由于年轻代中没有适当的空间存放新的数据结构引起的。
ParNew：ParNew是垃圾收集器的名称。这个名字表示的是在年轻代中使用的，基于标记-复制算法，专门设计用来配合老年代使用的 CMS。
139524K->17472K(157248K), 0.0081116 secs：在垃圾收集之前（139524K）和之后（17472K）的年轻代使用量，年轻代的总大小（157248K），该阶段耗时0.0081116秒。
139524K->53858K(506816K), 0.0084194 secs：在垃圾收集之前（139524K）和之后（53858K）堆内存的使用情况，堆内存总共大小（506816K），该阶段耗时0.0084194秒。包括标记-复制和CMS收集器的通信开销，提升存活时间达标的对象到老年代,以及垃圾收集后期的一些最终清理。
[Times: user=0.00 sys=0.00, real=0.01 secs]： GC事件的持续时间。

后面发生的是Full GC，主要是CMS收集器作用于老年代，这个过程很复杂，包括7个阶段，这些阶段直接夹杂着minor gc。

第一阶段： Initial Mark(初始标记)：这是第一次STW事件。此阶段的目标是标记老年代中所有存活的对象, 包括 GC Root的直接引用，以及由年轻代中存活对象指向老年代中的对象。后者也非常重要, 因为老年代是独立进行回收的。

[GC (CMS Initial Mark) [1 CMS-initial-mark: 223702K(349568K)] 241617K(506816K), 0.0006136 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

CMS Initial Mark：该阶段名称是Initial Mark，标记所有的GC Root。
223702K(349568K)：老年代当前使用量和老年代总共可使用的容量。
241617K(506816K)：堆当前使用量和堆总共可使用的容量。
0.0006136 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]：此次暂停的持续时间，以 user, system 和 real time 3 个部分进行衡量。

第二阶段： concurrent-mark(并发标记)：从GC Root开始并发标记老年代中存活的对象。由于是并发，所以是与应用程序同时运行的，不用暂停的阶段。注意, 并非所有老年代中存活的对象都在此阶段被标记，因为在标记过程中应用程序在运行，对象的引用关系就还会发生变化。

[CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

CMS-concurrent-mark：该阶段名称叫做concurrent mark，遍历老年代并标记所有的存活对象。
0.001/0.001 secs：此阶段的持续时间, 分别是运行时间和相应的实际时间。
[Times: user=0.00 sys=0.00, real=0.00 secs]：这部分对并发阶段来说没多少意义，因为是从并发标记开始时计算的,而这段时间内不仅并发标记在运行,程序也在运行。

第三阶段： concurrent-preclean(并发标记预清理)：此阶段同样是与应用线程并行执行的, 不需要停止应用线程。因为前一阶段是与程序并发进行的，可能有一些引用已经改变。如果在并发标记过程中发生了引用关系变化，JVM会将发生了改变的区域标记为“脏”区，统计脏对象。

[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

CMS-concurrent-preclean：该阶段名称叫做concurrent preclean，统计此前的标记阶段中发生了改变的对象。
0.001/0.001 secs：此阶段的持续时间, 分别是运行时间和相应的实际时间。
[Times: user=0.00 sys=0.00, real=0.00 secs]：这部分对并发阶段来说没多少意义，因为是从并发标记开始时计算的,而这段时间内不仅并发标记在运行,程序也在运行。

第四阶段： Concurrent Abortable Preclean(并发可取消的预清理)：此阶段也不停止应用线程，本阶段尝试在 STW 的 Final Remark 之前尽可能地多做一些工作。

[CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

CMS-concurrent-abortable-preclean：该阶段名称叫做concurrent abortable preclean。
0.000/0.000 secs：此阶段的持续时间, 分别是运行时间和相应的实际时间。
[Times: user=0.00 sys=0.00, real=0.01 secs]：这部分对并发阶段来说没多少意义，因为是从并发标记开始时计算的,而这段时间内不仅并发标记在运行，程序也在运行。

第五阶段： Final Remark(最终标记)：这是此次GC事件中第二次(也是最后一次)STW阶段。本阶段的目标是完成老年代中所有存活对象的标记。因为之前的 preclean 阶段是并发的，有可能无法跟上应用程序的变化速度。所以需要 STW暂停来处理复杂情况。

[GC (CMS Final Remark) [YG occupancy: 28785 K (157248 K)][Rescan (parallel) , 0.0002592 secs][weak refs processing, 0.0000208 secs][class unloading, 0.0008936 secs][scrub symbol table, 0.0002973 secs][scrub string table, 0.0000928 secs][1 CMS-remark: 326699K(349568K)] 355485K(506816K), 0.0049802 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

CMS Final Remark：此阶段的名称为 Final Remark, 标记老年代中所有存活的对象，包括在此前的并发标记过程中创建/修改的引用。
YG occupancy: 28785 K (157248 K)：当前年轻代的使用量和总容量。
Rescan (parallel) , 0.0002592 secs: 在程序暂停时重新进行扫描(Rescan),以完成存活对象的标记。此时 rescan 是并行执行的,消耗的时间为 0.0002592秒。
weak refs processing, 0.0000208 secs：处理弱引用，消耗的时间是0.0000208秒。
class unloading, 0.0008936 secs：卸载不使用的类，消耗的时间是0.0008936秒。
scrub symbol table, 0.0002973 secs：清理持有class级别 metadata 的符号表(symbol tables)，消耗的时间是 0.0002973 秒。
scrub string table, 0.0000928 secs：清理内部化字符串对应的 string tables，消耗的时间是0.0000928秒。
CMS-remark:326699K(349568K)：清除完成后老年代的使用量和总容量。
355485K(506816K)：此阶段完成后整个堆内存的使用量和总容量。
0.0049802 secs：此阶段的持续时间。
Times: user=0.00 sys=0.00, real=0.00 secs：GC事件的持续时间, 通过不同的类别来衡量: user, system and real time。

第六阶段： concurrent sweep(并发清除)：阶段与应用程序并发执行，不需要STW停顿。目的是删除未使用的对象，并收回他们占用的空间。

[CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

concurrent-sweep：该阶段的名称是concurrent sweep。
0.001/0.001 secs：此阶段的持续时间，分别是运行时间和实际时间。

第七阶段： concurrent reset(并发重置)：此阶段与应用程序并发执行，重置CMS算法相关的内部数据，为下一次GC循环做准备。

[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

concurrent-reset：该阶段的名称是concurrent reset。
0.000/0.000 secs：此阶段的持续时间，分别是运行时间和实际时间。

小结，CMS垃圾收集器的目标是减少停顿时间，阶段划分的更加详细，大量的并发线程执行的工作并不需要暂停应用线程。CMS的缺点是老年代内存碎片问题, 在某些情况下GC会造成不可预测的暂停时间，特别是堆内存较大的情况下。

Midnight

分析CMS GC日志

Related Posts...

从0到1手写配置中心config之实现配置中心客户端 06 May 2024

从0到1手写配置中心config之@configurationproperties热更新 06 May 2024

从0到1手写配置中心config之基于h2的config Server 04 May 2024