Java GC垃圾收集器的具体实现与日志案例分析(串行并行CMSG1)

Posted 2022-05-28 砖业洋__

在学习前篇Java GC算法背景原理与内存池划分后，相信对于GC的一些基本算法原理有了基本了解，之后 Java GC算法——日志解读与分析（GC参数基础配置分析），相信对基本的GC日志有了了解，现在在分析下各种GC垃圾收集器下的GC日志

文章目录

• 1. 串行GC（Serial GC）
• • 1.1 串行垃圾收集器介绍
  • 1.2 串行GC日志解读
  • • 1.2.1 Minor GC日志分析
    • 1.2.2 Full GC日志分析
• 2.并行GC（Parallel GC）
• • 2.1 并行垃圾收集器介绍
  • 2.2 并行GC日志解读
  • • 2.2.1 Minor GC日志分析
    • 2.2.2 Full GC日志分析
• 3. CMS GC
• • 3.1 CMS垃圾收集器介绍
  • 3.2 CMS GC日志解读
  • • 3.2.1 Minor GC日志分析
    • 3.2.2 Full GC日志分析
    • • 3.2.2.1 阶段 1: Initial Mark(初始标记) （有STW）
      • 3.2.2.2 阶段 2: Concurrent Mark(并发标记)
      • 3.2.2.3 阶段 3: Concurrent Preclean(并发预清理)
      • 3.2.2.4 阶段 4: Concurrent Abortable Preclean(可取消的并发预清理)
      • 3.2.2.5 阶段 5: Final Remark(最终标记) （有STW）
      • 3.2.2.6 阶段 6: Concurrent Sweep(并发清除)
      • 3.2.2.7 阶段 7: Concurrent Reset(并发重置)
• 4. G1垃圾收集器
• • 4.1 G1垃圾收集器介绍
  • 4.2 G1 GC常用参数设置
• 4.3 G1日志解读和分析
• • • 4.3.1 年轻代模式转移暂停（Evacuation Pause）
    • 4.3.2 Concurrent Marking(并发标记)
    • • 4.3.2.1 阶段 1: Initial Mark(初始标记)
      • 4.3.2.2 阶段 2: Root Region Scan(Root区扫描)
      • 4.3.2.3 阶段 3: Concurrent Mark(并发标记)
      • 4.3.2.4 阶段 4: Remark(再次标记)
      • 4.3.2.5 阶段 5: Cleanup(清理)
    • 4.3.3 转移暂停: 混合模式（Evacuation Pause (mixed)）
    • 4.3.4 Full GC (Allocation Failure)
• 5. GC选择的经验总结

前文学习了GC算法的相关概念后，这里我们会讲解JVM中这些算法的具体实现。大多数JVM 都需要使用两种不同的GC算法 —— 一种用来清理年轻代，另一种用来清理老年代。我们可以选择JVM内置的各种算法。如果不通过参数明确指定垃圾收集算法，则会使用相应JDK版本的默认实现。本文会详细介绍各种算法的实现原理。

1. 串行GC（Serial GC）

1.1 串行垃圾收集器介绍

  串行GC对年轻代使用 mark-copy（标记-复制）算法，对老年代使用 mark-sweep-compact（标记- 清除-整理） 算法。 由于是单线程的垃圾收集器，不能进行并行处理，所以对年轻代和老年代的垃圾收集都会触发全线暂停（STW），停止所有的应用线程。因此这种GC算法不能充分利用多核CPU。不管有多少CPU内核，JVM 在垃圾收集时都只能使用单个核心。

  要启用此款收集器，只需要指定一个JVM启动参数即可，同时对年轻代和老年代生效

-XX:+UseSerialGC

  该选项只适合几百MB堆内存的JVM，而且是单核CPU时比较有用。 对于服务器端来说，因为一般是多个CPU内核，并不推荐使用，除非确实需要限制JVM所使用的资源。 大多数服务器端应用部署在多核平台上，选择串行GC就意味着人为地限制了系统资源的使用，会导致资源闲 置，多余的CPU资源也不能用增加业务处理的吞吐量。

1.2 串行GC日志解读

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

让我们看看Serial GC的垃圾收集日志（由于写作的原因，这里是windows系统，日志开头显示了windows-amd64）

Java HotSpot(TM) 64-Bit Server VM (25.212-b10) for windows-amd64 JRE (1.8.0_212-b10), built on Apr  1 2019 22:50:23 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16633820k(5238816k free), swap 25449536k(5187744k free)
CommandLine flags: -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseSerialGC 
2021-12-16T19:30:03.983+0800: 0.155: [GC (Allocation Failure) 2021-12-16T19:30:03.983+0800: 0.155: [DefNew: 139776K->17472K(157248K), 0.0155099 secs] 139776K->42655K(506816K), 0.0157119 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2021-12-16T19:30:04.016+0800: 0.189: [GC (Allocation Failure) 2021-12-16T19:30:04.016+0800: 0.189: [DefNew: 157211K->17471K(157248K), 0.0195822 secs] 182394K->81289K(506816K), 0.0196621 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2021-12-16T19:30:04.052+0800: 0.225: [GC (Allocation Failure) 2021-12-16T19:30:04.052+0800: 0.225: [DefNew: 157247K->17470K(157248K), 0.0176595 secs] 221065K->127182K(506816K), 0.0177252 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2021-12-16T19:30:04.089+0800: 0.262: [GC (Allocation Failure) 2021-12-16T19:30:04.089+0800: 0.262: [DefNew: 157246K->17471K(157248K), 0.0180485 secs] 266958K->165146K(506816K), 0.0181250 secs] [Times: user=0.00 sys=0.02, real=0.02 secs] 
2021-12-16T19:30:04.128+0800: 0.300: [GC (Allocation Failure) 2021-12-16T19:30:04.128+0800: 0.300: [DefNew: 156973K->17471K(157248K), 0.0181455 secs] 304647K->207272K(506816K), 0.0182251 secs] [Times: user=0.00 sys=0.02, real=0.02 secs] 
2021-12-16T19:30:04.164+0800: 0.336: [GC (Allocation Failure) 2021-12-16T19:30:04.164+0800: 0.336: [DefNew: 157247K->17471K(157248K), 0.0205090 secs] 347048K->249163K(506816K), 0.0206178 secs] [Times: user=0.00 sys=0.01, real=0.02 secs] 
2021-12-16T19:30:04.203+0800: 0.375: [GC (Allocation Failure) 2021-12-16T19:30:04.203+0800: 0.375: [DefNew: 157143K->17471K(157248K), 0.0188082 secs] 388834K->295301K(506816K), 0.0188897 secs] [Times: user=0.02 sys=0.02, real=0.02 secs] 
2021-12-16T19:30:04.239+0800: 0.411: [GC (Allocation Failure) 2021-12-16T19:30:04.239+0800: 0.412: [DefNew: 157247K->17471K(157248K), 0.0165640 secs] 435077K->336036K(506816K), 0.0166406 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2021-12-16T19:30:04.273+0800: 0.445: [GC (Allocation Failure) 2021-12-16T19:30:04.273+0800: 0.445: [DefNew: 157247K->157247K(157248K), 0.0000144 secs]2021-12-16T19:30:04.273+0800: 0.445: [Tenured: 318564K->268197K(349568K), 0.0343878 secs] 475812K->268197K(506816K), [Metaspace: 2608K->2608K(1056768K)], 0.0345041 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 
2021-12-16T19:30:04.323+0800: 0.495: [GC (Allocation Failure) 2021-12-16T19:30:04.323+0800: 0.495: [DefNew: 139776K->17470K(157248K), 0.0060237 secs] 407973K->313385K(506816K), 0.0061055 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2021-12-16T19:30:04.348+0800: 0.520: [GC (Allocation Failure) 2021-12-16T19:30:04.348+0800: 0.520: [DefNew: 156845K->17470K(157248K), 0.0138671 secs] 452760K->360125K(506816K), 0.0139485 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
2021-12-16T19:30:04.380+0800: 0.552: [GC (Allocation Failure) 2021-12-16T19:30:04.380+0800: 0.552: [DefNew: 157246K->157246K(157248K), 0.0000148 secs]2021-12-16T19:30:04.380+0800: 0.552: [Tenured: 342654K->316653K(349568K), 0.0405361 secs] 499901K->316653K(506816K), [Metaspace: 2608K->2608K(1056768K)], 0.0406369 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 
2021-12-16T19:30:04.437+0800: 0.610: [GC (Allocation Failure) 2021-12-16T19:30:04.437+0800: 0.610: [DefNew: 139776K->139776K(157248K), 0.0000156 secs]2021-12-16T19:30:04.437+0800: 0.610: [Tenured: 316653K->328505K(349568K), 0.0362663 secs] 456429K->328505K(506816K), [Metaspace: 2608K->2608K(1056768K)], 0.0363715 secs] [Times: user=0.05 sys=0.00, real=0.04 secs] 
2021-12-16T19:30:04.489+0800: 0.661: [GC (Allocation Failure) 2021-12-16T19:30:04.489+0800: 0.661: [DefNew: 139776K->139776K(157248K), 0.0000696 secs]2021-12-16T19:30:04.489+0800: 0.661: [Tenured: 328505K->316403K(349568K), 0.0373156 secs] 468281K->316403K(506816K), [Metaspace: 2608K->2608K(1056768K)], 0.0374730 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 
2021-12-16T19:30:04.547+0800: 0.719: [GC (Allocation Failure) 2021-12-16T19:30:04.547+0800: 0.719: [DefNew: 139776K->139776K(157248K), 0.0000145 secs]2021-12-16T19:30:04.547+0800: 0.719: [Tenured: 316403K->334486K(349568K), 0.0244239 secs] 456179K->334486K(506816K), [Metaspace: 2608K->2608K(1056768K)], 0.0245235 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
2021-12-16T19:30:04.589+0800: 0.762: [GC (Allocation Failure) 2021-12-16T19:30:04.590+0800: 0.762: [DefNew: 139776K->139776K(157248K), 0.0000183 secs]2021-12-16T19:30:04.590+0800: 0.762: [Tenured: 334486K->345826K(349568K), 0.0350912 secs] 474262K->345826K(506816K), [Metaspace: 2608K->2608K(1056768K)], 0.0352064 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 
2021-12-16T19:30:04.640+0800: 0.812: [GC (Allocation Failure) 2021-12-16T19:30:04.640+0800: 0.812: [DefNew: 139776K->139776K(157248K), 0.0000143 secs]2021-12-16T19:30:04.640+0800: 0.812: [Tenured: 345826K->349080K(349568K), 0.0349528 secs] 485602K->351316K(506816K), [Metaspace: 2608K->2608K(1056768K)], 0.0350525 secs] [以上是关于Java GC垃圾收集器的具体实现与日志案例分析(串行并行CMSG1)的主要内容，如果未能解决你的问题，请参考以下文章
 
 Java GC垃圾收集器的具体实现与日志案例分析(串行并行CMSG1)
 JVM之GC日志分析与对象内存分配回收策略
 JVM-GC日志查看分析
 深入理解java虚拟机GC垃圾回收-虚拟机及垃圾收集器日志参数总结
 JVM探秘：GC日志收集与分析
 Java GC算法——日志解读与分析（GC参数基础配置分析）