GC 日志是我们了解 JVM 和垃圾收集器最可靠和全面的信息，因为里面包含了很多细节。学会分析 GC 日志是一项很有价值的技能，能帮助我们更好地排查性能问题。

GC 日志配置

建议为生产系统的程序配置 JVM 参数启用详细的 GC 日志，方便观察垃圾收集器的行为，对于 JDK8，我们可以这么设置：

  1. # OOM异常时Dump出堆的快照，以及指定快照的位置
  2. XX:+HeapDumpOnOutOfMemoryError 
  3. -XX:HeapDumpPath=. 
  5. # 查看GC时间
  6. -XX:+PrintGCDateStamps 
  8. # 查看GC详细信息，它会使虚拟机在退出前打印堆的详细信息
  9. -XX:+PrintGCDetails 
  11. # 打印 STW 时间
  12. -XX:+PrintGCApplicationStoppedTime
  13. # 打印对象年龄分布
  14. -XX:+PrintTenuringDistribution
  16. # 默认GC日志会在控制台中输出，通过该参数可将GC日志以文件的形式输出
  17. -Xloggc:gc.log 
  18. -XX:+UseGCLogFileRotation 
  19. -XX:NumberOfGCLogFiles=10 
  20. -XX:GCLogFileSize=100M

如果是长时间的 GC 日志，我们很难通过文本形式去查看整体的 GC 性能。此时，我们可以通过 GCViewer 工具来打开日志文件，图形化界面查看整体的 GC 性能。这里再推荐一个在线 GC 日志分析工具 GCeasy，我们可以将日志文件压缩之后，上传到 GCeasy 官网即可看到非常清楚的 GC 日志分析结果。

GC Cause

那有哪些情况会触发 GC 呢？实际上，触发 GC 的原因有很多，具体分类可以查看 Hotspot 源码：

  1. const char* GCCause::to_string(GCCause::Cause cause) {
  2.   switch (cause) {
  4.     // 手动触发 GC 操作      
  5.     case _java_lang_system_gc:
  6.       return "System.gc()";
  9.     case _full_gc_alot:
  10.       return "FullGCAlot";
  12.     case _scavenge_alot:
  13.       return "ScavengeAlot";
  15.     case _allocation_profiler:
  16.       return "Allocation Profiler";
  18.     case _jvmti_force_gc:
  19.       return "JvmtiEnv ForceGarbageCollection";
  21.     // 如果线程执行在JNI临界区时刚好要进行GC，此时GC Locker将阻止GC的发生，同时阻止其他线程进入JNI临界区，直到最后一个线程退出临界区时触发一次GC      
  22.     case _gc_locker:
  23.       return "GCLocker Initiated GC";
  25.     case _heap_inspection:
  26.       return "Heap Inspection Initiated GC";
  28.     case _heap_dump:
  29.       return "Heap Dump Initiated GC";
  31.     case _wb_young_gc:
  32.       return "WhiteBox Initiated Young GC";
  34.     case _wb_conc_mark:
  35.       return "WhiteBox Initiated Concurrent Mark";
  37.     case _wb_full_gc:
  38.       return "WhiteBox Initiated Full GC";
  40.     case _no_gc:
  41.       return "No GC";
  43.     case _allocation_failure:
  44.       return "Allocation Failure";
  46.     case _tenured_generation_full:
  47.       return "Tenured Generation Full";
  49.     case _metadata_GC_threshold:
  50.       return "Metadata GC Threshold";
  52.     case _metadata_GC_clear_soft_refs:
  53.       return "Metadata GC Clear Soft References";
  55.     case _cms_generation_full:
  56.       return "CMS Generation Full";
  58.     case _cms_initial_mark:
  59.       return "CMS Initial Mark";
  61.     case _cms_final_remark:
  62.       return "CMS Final Remark";
  64.     case _cms_concurrent_mark:
  65.       return "CMS Concurrent Mark";
  67.     case _old_generation_expanded_on_last_scavenge:
  68.       return "Old Generation Expanded On Last Scavenge";
  70.     case _old_generation_too_full_to_scavenge:
  71.       return "Old Generation Too Full To Scavenge";
  73.     // 自适应策略（堆内存分布的自适应）导致的GC      
  74.     case _adaptive_size_policy:
  75.       return "Ergonomics";
  77.     case _g1_inc_collection_pause:
  78.       return "G1 Evacuation Pause";
  80.     case _g1_humongous_allocation:
  81.       return "G1 Humongous Allocation";
  83.     case _dcmd_gc_run:
  84.       return "Diagnostic Command";
  86.     case _last_gc_cause:
  87.       return "ILLEGAL VALUE - last gc cause - ILLEGAL VALUE";
  89.     default:
  90.       return "unknown GCCause";
  91.   }
  92.   ShouldNotReachHere();
  93. }

下面我们通过实际操作来分析和解读 GC 日志。

Serial GC 日志解读

  1. Java HotSpot(TM) 64-Bit Server VM (25.181-b13) for bsd-amd64 JRE (1.8.0_181-b13), built on Jul  7 2018 01:02:31 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
  2. Memory: 4k page, physical 16777216k(394724k free)
  4. /proc/meminfo:
  6. CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseSerialGC 
  7. 2021-11-17T19:30:09.734-0800: 0.115: [GC (Allocation Failure) 2021-11-17T19:30:09.734-0800: 0.115: [DefNew: 2751K->320K(3072K), 0.0033703 secs] 2751K->1489K(9920K), 0.0034776 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] 
  8. 2021-11-17T19:30:09.739-0800: 0.120: [GC (Allocation Failure) 2021-11-17T19:30:09.739-0800: 0.120: [DefNew: 3071K->319K(3072K), 0.0063065 secs] 4240K->4163K(9920K), 0.0064187 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
  9. 2021-11-17T19:30:09.746-0800: 0.128: [GC (Allocation Failure) 2021-11-17T19:30:09.746-0800: 0.128: [DefNew: 3071K->3071K(3072K), 0.0000393 secs]2021-11-17T19:30:09.746-0800: 0.128: [Tenured: 3844K->6808K(6848K), 0.0082851 secs] 6915K->6808K(9920K), [Metaspace: 3262K->3262K(1056768K)], 0.0085076 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
  10. 2021-11-17T19:30:09.756-0800: 0.137: [GC (Allocation Failure) 2021-11-17T19:30:09.756-0800: 0.137: [DefNew: 2751K->2751K(3072K), 0.0000152 secs]2021-11-17T19:30:09.756-0800: 0.137: [Tenured: 6808K->6847K(6848K), 0.0056193 secs] 9560K->9549K(9920K), [Metaspace: 3273K->3273K(1056768K)], 0.0057171 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
  11. 2021-11-17T19:30:09.762-0800: 0.143: [Full GC (Allocation Failure) 2021-11-17T19:30:09.762-0800: 0.143: [Tenured: 6847K->6847K(6848K), 0.0042827 secs] 9919K->9911K(9920K), [Metaspace: 3285K->3285K(1056768K)], 0.0043606 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
  12. 2021-11-17T19:30:09.766-0800: 0.148: [Full GC (Allocation Failure) 2021-11-17T19:30:09.766-0800: 0.148: [Tenured: 6847K->6847K(6848K), 0.0049440 secs] 9919K->9802K(9920K), [Metaspace: 3285K->3285K(1056768K)], 0.0050105 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
  13. 2021-11-17T19:30:09.772-0800: 0.153: [Full GC (Allocation Failure) 2021-11-17T19:30:09.772-0800: 0.153: [Tenured: 6847K->6847K(6848K), 0.0082462 secs] 9919K->9919K(9920K), [Metaspace: 3285K->3285K(1056768K)], 0.0083187 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
  14. 2021-11-17T19:30:09.780-0800: 0.161: [Full GC (Allocation Failure) 2021-11-17T19:30:09.780-0800: 0.161: [Tenured: 6847K->6847K(6848K), 0.0045343 secs] 9919K->9919K(9920K), [Metaspace: 3285K->3285K(1056768K)], 0.0045866 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
  15. 2021-11-17T19:30:09.785-0800: 0.166: [Full GC (Allocation Failure) 2021-11-17T19:30:09.785-0800: 0.166: [Tenured: 6847K->376K(6848K), 0.0035121 secs] 9919K->376K(9920K), [Metaspace: 3285K->3285K(1056768K)], 0.0036375 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
  16. Heap
  17.  def new generation   total 3072K, used 121K [0x00000007bf600000, 0x00000007bf950000, 0x00000007bf950000)
  18.   eden space 2752K,   4% used [0x00000007bf600000, 0x00000007bf61e6d0, 0x00000007bf8b0000)
  19.   from space 320K,   0% used [0x00000007bf8b0000, 0x00000007bf8b0000, 0x00000007bf900000)
  20.   to   space 320K,   0% used [0x00000007bf900000, 0x00000007bf900000, 0x00000007bf950000)
  21.  tenured generation   total 6848K, used 376K [0x00000007bf950000, 0x00000007c0000000, 0x00000007c0000000)
  22.    the space 6848K,   5% used [0x00000007bf950000, 0x00000007bf9ae3f0, 0x00000007bf9ae400, 0x00000007c0000000)
  23.  Metaspace       used 3335K, capacity 4500K, committed 4864K, reserved 1056768K
  24.   class space    used 367K, capacity 388K, committed 512K, reserved 1048576K

日志的第一行是 JVM 版本信息，第二行往后到第一个时间戳之间的部分，展示了内存分页、物理内存大小以及命令行参数等信息。下面我们来详细分析下 GC 事件，以第一行 GC 事件为例分析：

2021-11-17T19:30:09.734-0800：GC 事件开始的时间点，其中 -0800 表示当前时区为东八区，后面的 0.115 是 GC 事件相对于 JVM 启动时间的间隔，单位是秒。GC 用来区分 Minor GC 还是 Full GC 的标志。GC 表明这是一次小型 GC（Minor GC），即年轻代 GC。Full GC 表示整堆 GC。Allocation Failure 表示触发 GC 的原因，即由于对象分配失败导致的 GC。

DefNew 表示新生代收集器，Tenured 表示老年代收集器，Metaspace 表示元空间。2751K->320K 表示在垃圾收集前后的年轻代/老年代/元空间的使用量。(3072K) 表示年轻代/老年代/元空间的总空间大小。后面的 0.0033703 secs 表示整个年轻代/老年代/元空间的收集耗时。在年轻代/老年代的收集信息后面还会有整个堆内存的使用情况，如 2751K->1489K，(9920K) 则表示堆内存可用的总空间大小。0.0034776 secs 表示整个堆 GC 事件的持续时间，单位为秒。

[Times: user=0.00 sys=0.01，real=0.00 secs]：此次 GC 事件的持续时间：user 部分表示进程在用户态（User Mode）所花费的时间；sys 部分表示进程在核心态（Kernel Mode）花费的 CPU 时间，具体指的是内核中系统调用和系统等待事件消耗的时间。real 则表示从开始到结束实际花费的时间。

Parallel GC 日志解读

并行垃圾收集器对年轻代使用 “标记-复制” 算法，对老年代使用 “标记-清除-整理” 算法，并且在执行 “标记” 和 “复制/整理” 阶段时都使用多个线程并发执行，因此得名 Parallel GC。通过开启 -XX:+UseParallelOldGC 指定年轻代和老年代都使用 Parallel GC。

Parallel GC 打印的日志文件如下：

  1. Java HotSpot(TM) 64-Bit Server VM (25.181-b13) for bsd-amd64 JRE (1.8.0_181-b13), built on Jul  7 2018 01:02:31 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
  2. Memory: 4k page, physical 16777216k(1427800k free)
  4. /proc/meminfo:
  6. CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelOldGC 
  7. 2021-11-17T20:18:27.623-0800: 0.127: [GC (Allocation Failure) [PSYoungGen: 2047K->496K(2560K)] 2047K->944K(9728K), 0.0025474 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
  8. 2021-11-17T20:18:27.627-0800: 0.131: [GC (Allocation Failure) [PSYoungGen: 2543K->488K(2560K)] 2991K->3000K(9728K), 0.0019150 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
  9. 2021-11-17T20:18:27.630-0800: 0.133: [GC (Allocation Failure) [PSYoungGen: 2536K->502K(2560K)] 5048K->5046K(9728K), 0.0016888 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
  10. 2021-11-17T20:18:27.631-0800: 0.135: [Full GC (Ergonomics) [PSYoungGen: 502K->0K(2560K)] [ParOldGen: 4544K->4786K(7168K)] 5046K->4786K(9728K), [Metaspace: 3229K->3229K(1056768K)], 0.0098201 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
  11. 2021-11-17T20:18:27.642-0800: 0.146: [GC (Allocation Failure) [PSYoungGen: 2047K->498K(2560K)] 6834K->6917K(9728K), 0.0036094 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
  12. 2021-11-17T20:18:27.646-0800: 0.150: [Full GC (Ergonomics) [PSYoungGen: 498K->0K(2560K)] [ParOldGen: 6418K->6761K(7168K)] 6917K->6761K(9728K), [Metaspace: 3243K->3243K(1056768K)], 0.0069351 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
  13. 2021-11-17T20:18:27.654-0800: 0.157: [Full GC (Ergonomics) [PSYoungGen: 2047K->2036K(2560K)] [ParOldGen: 6761K->6749K(7168K)] 8809K->8785K(9728K), [Metaspace: 3251K->3251K(1056768K)], 0.0084704 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
  14. 2021-11-17T20:18:27.662-0800: 0.166: [Full GC (Ergonomics) [PSYoungGen: 2047K->2047K(2560K)] [ParOldGen: 6749K->6749K(7168K)] 8796K->8796K(9728K), [Metaspace: 3251K->3251K(1056768K)], 0.0065516 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
  15. 2021-11-17T20:18:27.669-0800: 0.173: [Full GC (Ergonomics) [PSYoungGen: 2048K->2047K(2560K)] [ParOldGen: 6775K->6775K(7168K)] 8823K->8822K(9728K), [Metaspace: 3252K->3252K(1056768K)], 0.0065361 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
  16. 2021-11-17T20:18:27.676-0800: 0.180: [Full GC (Ergonomics) [PSYoungGen: 2048K->2047K(2560K)] [ParOldGen: 6802K->6798K(7168K)] 8850K->8846K(9728K), [Metaspace: 3255K->3255K(1056768K)], 0.0117229 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] 
  17. 2021-11-17T20:18:27.688-0800: 0.192: [Full GC (Ergonomics) [PSYoungGen: 2048K->2047K(2560K)] [ParOldGen: 6824K->6824K(7168K)] 8872K->8872K(9728K), [Metaspace: 3255K->3255K(1056768K)], 0.0064774 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
  18. 2021-11-17T20:18:27.695-0800: 0.199: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 6848K->6848K(7168K)] 8896K->8896K(9728K), [Metaspace: 3255K->3255K(1056768K)], 0.0085627 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
  19. 2021-11-17T20:18:27.704-0800: 0.207: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 6872K->6872K(7168K)] 8920K->8920K(9728K), [Metaspace: 3255K->3255K(1056768K)], 0.0073938 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
  20. 2021-11-17T20:18:27.711-0800: 0.215: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 6898K->6898K(7168K)] 8946K->8946K(9728K), [Metaspace: 3255K->3255K(1056768K)], 0.0060298 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
  21. 2021-11-17T20:18:27.718-0800: 0.221: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 6910K->6910K(7168K)] 8958K->8958K(9728K), [Metaspace: 3255K->3255K(1056768K)], 0.0057207 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
  22. 2021-11-17T20:18:27.724-0800: 0.227: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 6935K->6935K(7168K)] 8983K->8983K(9728K), [Metaspace: 3255K->3255K(1056768K)], 0.0062647 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
  23. 2021-11-17T20:18:27.730-0800: 0.234: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 6957K->6957K(7168K)] 9005K->9005K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0056482 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
  24. 2021-11-17T20:18:27.736-0800: 0.240: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 6980K->6980K(7168K)] 9028K->9028K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0055990 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
  25. 2021-11-17T20:18:27.742-0800: 0.246: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7116K->7032K(7168K)] 9164K->9080K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0055340 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
  26. 2021-11-17T20:18:27.748-0800: 0.251: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7056K->7055K(7168K)] 9104K->9103K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0050629 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
  27. 2021-11-17T20:18:27.753-0800: 0.257: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7080K->7080K(7168K)] 9128K->9128K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0053945 secs] [Times: user=0.03 sys=0.01, real=0.00 secs] 
  28. 2021-11-17T20:18:27.758-0800: 0.262: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7104K->7104K(7168K)] 9152K->9152K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0052261 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
  29. 2021-11-17T20:18:27.764-0800: 0.268: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7127K->7126K(7168K)] 9175K->9174K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0053256 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
  30. 2021-11-17T20:18:27.769-0800: 0.273: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7148K->7148K(7168K)] 9196K->9196K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0052571 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
  31. 2021-11-17T20:18:27.775-0800: 0.279: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7167K->7167K(7168K)] 9215K->9215K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0053317 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
  32. 2021-11-17T20:18:27.780-0800: 0.284: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7167K->7167K(7168K)] 9215K->9215K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0053503 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
  33. 2021-11-17T20:18:27.786-0800: 0.289: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7167K->7167K(7168K)] 9215K->9215K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0052200 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
  34. 2021-11-17T20:18:27.791-0800: 0.295: [Full GC (Allocation Failure) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7167K->7150K(7168K)] 9215K->9198K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0085718 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
  35. 2021-11-17T20:18:27.800-0800: 0.304: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7167K->7167K(7168K)] 9215K->9215K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0049015 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
  36. 2021-11-17T20:18:27.805-0800: 0.309: [Full GC (Ergonomics) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7168K->7168K(7168K)] 9216K->9216K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0054456 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
  37. 2021-11-17T20:18:27.811-0800: 0.314: [Full GC (Allocation Failure) [PSYoungGen: 2048K->2048K(2560K)] [ParOldGen: 7168K->7168K(7168K)] 9216K->9216K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0055809 secs] [Times: user=0.04 sys=0.00, real=0.00 secs] 
  38. 2021-11-17T20:18:27.816-0800: 0.320: [Full GC (Ergonomics) [PSYoungGen: 2048K->0K(2560K)] [ParOldGen: 7168K->374K(7168K)] 9216K->374K(9728K), [Metaspace: 3256K->3256K(1056768K)], 0.0035813 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
  39. Heap
  40.  PSYoungGen      total 2560K, used 111K [0x00000007bfd00000, 0x00000007c0000000, 0x00000007c0000000)
  41.   eden space 2048K, 5% used [0x00000007bfd00000,0x00000007bfd1bc98,0x00000007bff00000)
  42.   from space 512K, 0% used [0x00000007bff80000,0x00000007bff80000,0x00000007c0000000)
  43.   to   space 512K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007bff80000)
  44.  ParOldGen       total 7168K, used 374K [0x00000007bf600000, 0x00000007bfd00000, 0x00000007bfd00000)
  45.   object space 7168K, 5% used [0x00000007bf600000,0x00000007bf65daf0,0x00000007bfd00000)
  46.  Metaspace       used 3316K, capacity 4500K, committed 4864K, reserved 1056768K
  47.   class space    used 365K, capacity 388K, committed 512K, reserved 1048576K

整个日志文件的结构同 Serial GC 没有太大区别，只是年轻代、老年代使用的垃圾收集器的名称变了：

  • PSYoungGen：年轻代收集
  • ParOldGen：老年代收集

CMS 日志解读

CMS 也被称为并发标记清除垃圾收集器，其设计目标是避免在老年代 GC 时出现长时间的卡顿。CMS 默认使用的并发线程数等于 CPU 核数的 1/4。可通过开启 -XX:+UseConcMarkSweepGC 选项指定使用 CMS 。

CMS 的日志是一种完全不同的格式，并且很长，因为 CMS 对老年代进行垃圾收集时的每个阶段都会有自己的日志。在实际运行中，CMS 在进行老年代的并发垃圾回收时，可能会伴随着多次年轻代的 Minor GC。在这种情况下，Full GC 的日志中可能会掺杂着多次 Minor GC 事件。

下面我们就着重分析下 Full GC 的日志格式，为了简洁，我们对这部分日志按照阶段依次介绍：

1. Initial Mark（初始标记）

初始标记的目标是标记所有的根对象，包括 GC Roots 直接引用的对象，以及被年轻代中所有存活对象所引用的对象，初始标记阶段伴随着 STW 暂停。我们先看下这个阶段的日志：

  1. 2021-11-17T20:46:28.918-0800: 0.157: 
  2. [GC (CMS Initial Mark) 
  3. [1 CMS-initial-mark: 3867K(6848K)] 
  4. 5092K(9920K), 0.0012744 secs] 
  5. [Times: user=0.00 sys=0.00, real=0.00 secs]

第二行的 CMS Initial Mark 表示该阶段为初始标记阶段。
第三行的 [1 CMS-initial-mark: 3867K(6848K)] 表示老年代的使用量以及老年代的总容量。
第四行的 5092K(9920K), 0.0012744 secs 表示整个堆的使用量、总容量以及初始标记的暂停时间。

2. 并发标记

2.1 Concurrent Mark（并发标记）

在并发标记阶段，CMS 从前一阶段 Initial Mark 找到的 GC Roots 开始算起，遍历老年代并标记所有的存活对象。看看这个阶段的 GC 日志：

  1. 2021-11-17T00:00:31.889-0800: 1.091:
  2.   [CMS-concurrent-mark-start]
  3. 2021-11-17T00:00:31.890-0800: 1.092:
  4.   [CMS-concurrent-mark: 0.001/0.001 secs]
  5.   [Times: user=0.00 sys=0.00,real=0.01 secs]

第四行的 CMS-concurrent-mark 指明了 CMS 垃圾收集器当前所处的阶段为并发标记阶段，0.001/0.001 secs 表示此阶段的持续时间，分别是 GC 线程运行时间和该阶段实际消耗的时间。

第五行的 [Times: user=0.00 sys=0.00,real=0.01 secs] 对并发标记阶段来说没多少意义，因为在这段时间里应用线程也在执行，所以这个时间只是一个大概的值。

2.2 Concurrent Preclean（并发预清理）

此阶段同样是与应用线程并发执行的，不需要停止应用线程。看看并发预清理阶段的 GC 日志：

  1. 2021-11-17T00:00:31.891-0800: 1.092:
  2.   [CMS-concurrent-preclean-start]
  3. 2021-11-17T00:00:31.891-0800: 1.093:
  4.   [CMS-concurrent-preclean: 0.001/0.001 secs]
  5.   [Times: user=0.00 sys=0.00,real=0.00 secs]

第四行的 CMS-concurrent-preclean 表明这是并发预清理阶段的日志，这个阶段会统计前面的并发标记阶段执行过程中发生了改变的对象。0.001/0.001 secs 表示此阶段的持续时间，分别是 GC 线程运行时间和该阶段实际占用的时间。第五行内容同上。

2.3 Concurrent Abortable Preclean（可取消的并发预清理）

此阶段也不停止应用线程，尝试在会触发 STW 的 Final Remark 阶段开始之前，尽可能地多干一些活。本阶段的具体时间取决于多种因素，因为它循环做同样的事情，直到满足某一个退出条件（如迭代次数、有用工作量、消耗的系统时间等等）。

  1. 2021-11-17T00:00:31.891-0800: 1.093:
  2.   [CMS-concurrent-abortable-preclean-start]
  3. 2021-11-17T00:00:31.891-0800: 1.093:
  4.   [CMS-concurrent-abortable-preclean: 0.000/0.000 secs]
  5.   [Times: user=0.00 sys=0.00,real=0.00 secs]

第四行的 CMS-concurrent-abortable-preclean 表示此阶段的名称，0.000/0.000 secs 表示此阶段 GC 线程的运行时间和实际占用的时间。从本质上讲，GC 线程试图在执行 STW 暂停前会等待尽可能长的时间。默认条件下，此阶段可以持续最长 5 秒钟的时间。第五行内容同上。

3. Final Remark（最终标记）

最终标记阶段是此次 GC 事件中的第二次（也是最后一次）STW 停顿。本阶段的目标是完成老年代中所有存活对象的标记。因为之前的预清理阶段是并发执行的，有可能 GC 线程跟不上应用程序的修改速度。所以需要一次 STW 暂停来处理各种复杂的情况。通常 CMS 会尝试在年轻代尽可能空的情况下执行 final remark 阶段，以免连续触发多次 STW 事件。

  1. 2021-11-17T00:00:31.891-0800: 1.093:
  2.   [GC (CMS Final Remark)
  3.     [YG occupancy: 26095 K (157248 K)]
  4.     2021-11-17T00:00:31.891-0800: 1.093:
  5.       [Rescan (parallel) ，0.0002680 secs]
  6.     2021-11-17T00:00:31.891-0800: 1.093:
  7.       [weak refs processing，0.0000230 secs]
  8.     2021-11-17T00:00:31.891-0800: 1.093:
  9.       [class unloading，0.0004008 secs]
  10.     2021-11-17T00:00:31.892-0800: 1.094:
  11.       [scrub symbol table，0.0006072 secs]
  12.     2021-11-17T00:00:31.893-0800: 1.095:
  13.       [scrub string table，0.0001769 secs]
  14.       [1 CMS-remark: 342870K(349568K)]
  15.     368965K(506816K)，0.0015928 secs]
  16.   [Times: user=0.01 sys=0.00,real=0.00 secs]

这部分的 GC 日志看起来稍微复杂一些，一起来进行解读：

  • 第 2 行的 CMS Final Remark 表示该阶段的名称，即最终标记阶段。
  • 第 3 行的 [YG occupancy: 26095 K (157248 K)] 表示当前年轻代的使用量和总容量。
  • 第 5 行的 [Rescan (parallel) ，0.0002680 secs] 表示在程序暂停后进行重新扫描以完成对变动的存活对象的标记。这部分是并行执行的，消耗的时间为 0.0002680 秒。
  • 第 7 行的 [weak refs processing，0.0000230 secs] 为第一个子阶段，表示处理弱引用的持续时间。
  • 第 8 行的 [class unloading，0.0004008 secs] 为第二个子阶段，表示卸载不使用的类的持续时间。
  • 第 11 行的 [scrub symbol table，0.0006072 secs] 为第三个子阶段，用于清理符号表，即持有 class 级别 metadata 的符号表。
  • 第 13 行的 [scrub string table，0.0001769 secs] 为第四个子阶段，用于清理内联字符串对应的 string tables。
  • 第 14 行的 [1 CMS-remark: 342870K(349568K)] 表示此阶段完成后老年代的使用量和总容量。
  • 第 15 行的 368965K(506816K)，0.0015928 secs 表示此阶段完成后，整个堆内存的使用量和总容量，以及最终标记阶段的整体耗时。

在上面这 5 个标记阶段完成后，老年代中的所有存活对象就都被标记上了，接下来 JVM 会将所有不使用的对象清除掉，以回收老年代空间。

4. 并发清除

4.1 Concurrent Sweep（并发清除）

此阶段与应用程序并发执行，不需要 STW 停顿。目的是删除不再使用的对象，并回收他们占用的内存空间。这部分的 GC 日志如下：

  1. 2021-11-17T00:00:31.893-0800: 1.095:
  2.   [CMS-concurrent-sweep-start]
  3. 2021-11-17T00:00:31.893-0800: 1.095:
  4.   [CMS-concurrent-sweep: 0.000/0.000 secs]
  5.   [Times: user=0.00 sys=0.00,real=0.00 secs]

CMS-concurrent-sweep 表示此阶段的名称，即并发清除老年代中所有未被标记的对象、也就是不再使用的对象，以释放内存空间。

4.2 Concurrent Reset（并发重置）

此阶段与应用程序线程并发执行，重置 CMS 算法相关的内部数据结构，下一次触发 GC 时就可以直接使用。对应的 GC 日志为：

  1. 2021-11-17T00:00:31.893-0800: 1.095:
  2.   [CMS-concurrent-reset-start]
  3. 2021-11-17T00:00:31.894-0800: 1.096:
  4.   [CMS-concurrent-reset: 0.000/0.000 secs]
  5.   [Times: user=0.00 sys=0.00,real=0.00 secs]

CMS-concurrent-reset 表示此阶段的名称，即并发重置 CMS 算法的内部数据结构，为下一次 GC 循环做准备工作。

5. 失败日志

如果一切顺利，以上步骤就是 CMS 垃圾回收会经历的所有周期。不过，事实并不是这么简单，我们还需要查看下面这几种情况的日志，出现这些日志表明 CMS 垃圾收集遇到了麻烦：

5.1 concurrent mode failure

image.png
新生代发生垃圾回收，同时老年代又没有足够的空间容纳晋升的对象时，CMS 垃圾回收就会退化成 Full GC。所有的应用线程都会被暂停，老年代中所有的无效对象都被回收，释放空间之后老年代的占用为 1366 MB，这次操作导致应用程序线程停顿长达 5.6 秒。这个操作是单线程的，这就是为什么它耗时如此之长的原因之一。

5.2 promotion failed

第二个问题是老年代有足够的空间可以容纳晋升的对象，但是由于空闲空间的碎片化导致晋升失败：
image.png
在这个例子中，CMS 启动了新生代垃圾收集，判断老年代似乎有足够的空闲空间可以容纳所有的晋升对象（否则，CMS 收集器会报告发生并发模式失效）。这个假设最终被证明是错误的：由于老年代空间的碎片化，CMS 收集器无法晋升这些对象。

因此，CMS 收集器在新生代垃圾收集过程中（所有的应用线程都被暂停时），对整个老年代空间进行了整理和压缩。好消息是，随着堆的压缩，碎片化问题解决了。不过随之而来的是长达 28 秒的停顿时间。由于需要对整个堆进行整理，这个时间甚至比 CMS 收集器遭遇并发模式失效的时间还长的多，因为发生并发失效时，CMS 收集器只需要回收堆内无用的对象。