0
点赞
收藏
分享

微信扫一扫

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

非常帅气的昵称吧 2023-06-06 阅读 44
GC日志分析串行GC并行GCCMS GCG1 GCHtml/CSS前端开发


在学习前篇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] [Times: user=0.05 sys=0.00, real=0.03 secs] 
2021-12-16T19:30:04.693+0800: 0.865: [Full GC (Allocation Failure) 2021-12-16T19:30:04.693+0800: 0.865: [Tenured: 349296K->343154K(349568K), 0.0397555 secs] 506535K->343154K(506816K), [Metaspace: 2608K->2608K(1056768K)], 0.0398233 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 
2021-12-16T19:30:04.747+0800: 0.919: [GC (Allocation Failure) 2021-12-16T19:30:04.747+0800: 0.919: [DefNew: 139776K->139776K(157248K), 0.0000146 secs]2021-12-16T19:30:04.747+0800: 0.919: [Tenured: 343154K->349368K(349568K), 0.0243795 secs] 482930K->368942K(506816K), [Metaspace: 2608K->2608K(1056768K)], 0.0244925 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2021-12-16T19:30:04.789+0800: 0.961: [Full GC (Allocation Failure) 2021-12-16T19:30:04.789+0800: 0.961: [Tenured: 349368K->349326K(349568K), 0.0363575 secs] 506527K->366420K(506816K), [Metaspace: 2608K->2608K(1056768K)], 0.0364563 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 
2021-12-16T19:30:04.842+0800: 1.014: [Full GC (Allocation Failure) 2021-12-16T19:30:04.842+0800: 1.014: [Tenured: 349423K->349253K(349568K), 0.0359097 secs] 506586K->368491K(506816K), [Metaspace: 2608K->2608K(1056768K)], 0.0359858 secs] [Times: user=0.05 sys=0.00, real=0.04 secs] 
2021-12-16T19:30:04.892+0800: 1.064: [Full GC (Allocation Failure) 2021-12-16T19:30:04.892+0800: 1.065: [Tenured: 349565K->349260K(349568K), 0.0407681 secs] 506795K->354364K(506816K), [Metaspace: 2608K->2608K(1056768K)], 0.0408418 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 
Heap
 def new generation   total 157248K, used 11403K [0x00000000e0000000, 0x00000000eaaa0000, 0x00000000eaaa0000)
  eden space 139776K,   8% used [0x00000000e0000000, 0x00000000e0b22e98, 0x00000000e8880000)
  from space 17472K,   0% used [0x00000000e8880000, 0x00000000e8880000, 0x00000000e9990000)
  to   space 17472K,   0% used [0x00000000e9990000, 0x00000000e9990000, 0x00000000eaaa0000)
 tenured generation   total 349568K, used 349260K [0x00000000eaaa0000, 0x0000000100000000, 0x0000000100000000)
   the space 349568K,  99% used [0x00000000eaaa0000, 0x00000000fffb3190, 0x00000000fffb3200, 0x0000000100000000)
 Metaspace       used 2615K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

  日志的第一行是JVM版本信息，第二行往后到第一个时间戳之间的部分，展示了内存分页、物理内存大小， 命令行参数等信息。

1.2.1 Minor GC日志分析

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]

从中可以解读出这些信息:

  1. 2021-12-16T19:30:03.983+0800: 0.155: ，这是GC事件开始的时间点。其中 +0800 表示当前时区为东八区（北京时间），这只是一个标识，方便我们直观判断GC发生的时间点。后面的 0.155 是GC事件相对于JVM 启动时间的间隔，单位是秒。
  2. GC – 用来区分 Minor GC 还是 Full GC 的标志。 GC 表明这是一次小型GC(Minor GC)，即年轻代 GC。 Allocation Failure 表示触发 GC 的原因。本次GC事件，是由于对象分配失败，年轻代中没有空间来存放新生成的对象引起的。
  3. DefNew – 表示垃圾收集器的名称。这个名字表示：这是一个年轻代使用的单线程、标记-复制、需要STW的垃圾收集器。 139776K->17472K 表示在垃圾收集之前和之后的年轻代使用量。 (157248K) 表示年轻代的总空间大小。进一步分析可知：GC 之后年轻代使用率为11%
  4. 139776K->42655K – 表示在垃圾收集之前和之后整个堆内存的使用情况。(506816K) 则表示堆内存可用的总空间大小。进一步分析可知: GC 之后堆内存使用量为8%
  5. 0.0157119 secs – GC事件持续的时间，以秒为单位
  6. [Times: user=0.02 sys=0.00, real=0.02 secs] – 此次GC事件的持续时间，通过三个部分来衡量： user 部分表示所有 GC线程消耗的CPU时间； sys 部分表示系统调用和系统等待事件消耗的时间。 real 则表示应用程序暂停的时间。

  这个暂停时间对大部分系统来说可以接受，但对某些延迟敏感的系统就不太理想了，比如实时的游戏服务、高频交易业务，30ms暂停是致命的。

  GC前后对比，年轻代的使用量为 139776K->17472K ，减少了 122304K 。 但堆内存的总使用量 139776K->42655K 只下降了 97121K 。 可以算出，从年轻代提升到老年代的对象占用了 122304K - 97121K = 25183K 的内存空间。当然， 另一组数字也能推算出GC之后老年代的使用量 42655K - 17472K = 25183K

我们关注的主要是两个数据： GC暂停时间以及GC之后的内存使用量/使用率

此次GC事件的示意图如下所示:


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

1.2.2 Full GC日志分析

2021-12-16T22:53:35.154+0800: 0.439: [GC (Allocation Failure) 2021-12-16T22:53:35.154+0800: 0.439: 
[DefNew: 157245K->157245K(157248K), 0.0000141 secs]2021-12-16T22:53:35.154+0800: 0.439: 
[Tenured: 294996K->263651K(349568K), 0.0346014 secs] 452242K->263651K(506816K), 
[Metaspace: 2608K->2608K(1056768K)], 0.0347088 secs] 
[Times: user=0.05 sys=0.00, real=0.03 secs]

从中可以解读出这些信息：

  1. 2021-12-16T22:53:35.154+0800: 0.439: – GC事件开始的时间。
  2. [DefNew: 157245K->157245K(157248K), 0.0000141 secs] – 前面已经解读过了，因为内存分配失败，发生了一次年轻代 GC。此次GC同样用的 DefNew 收集器。注意：此次垃圾收集消耗了 0.0000141秒，基本上确认本次GC事件没怎么处理年轻代。
  3. Tenured – 用于清理老年代空间的垃圾收集器名称。 Tenured 表明使用的是单线程的STW垃圾收集器，使用的算法为标记-清除-整理(mark-sweep-compact) 。 294996K->263651K(349568K) 表示GC前后老年代的使用量，以及老年代的空间大小。 0.0346014 secs是清理老年代所花的时间。
  4. 452242K->263651K(506816K) – 在GC前后整个堆内存部分的使用情况，以及可用的堆空间大小。
  5. [Metaspace: 2608K->2608K(1056768K)] – Metaspace 空间的变化情况。可以看出，此次GC过程中 Metaspace 也没有什么变化。
  6. [Times: user=0.05 sys=0.00, real=0.03 secs] – GC事件的持续时间，分为user ， sys ， real 三个部分。

注意：GC的时间与GC后存活对象的总数量关系最大

进一步分析这些数据，GC之后老年代的使用率为： 263651K / 349568K = 75% ，这个比例不小了，但也不能就此说出了什么问题，毕竟GC后内存使用量下降了，还需要后续的观察。

和年轻代GC相比，比较明显的差别是此次GC事件清理了老年代。

总结：关于FullGC，主要关注GC之后内存使用量是否下降，其次关注暂停时间。简单估算，GC后老年代使用量为260MB左右，耗时30ms。如果内存扩大10倍，GC后老年代内存使用量也扩大10倍，那耗时可能就是300ms甚至更高，就会系统有很明显的影响了。这也是我们说串行GC性能弱的一个原因， 服务端一般是不会采用串行GC的。

此次GC事件的内存变化情况，可以表示为下面的示意图


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

年轻代看起来数据几乎没变化，重点看看上下文，其实还有其他的GC日志记录。

2.并行GC（Parallel GC）

2.1 并行垃圾收集器介绍

  并行垃圾收集器这一类组合，在年轻代使用 标记-复制（mark-copy）算法 ，在老年代使用 标记-清除- 整理（mark-sweep-compact）算法 。年轻代和老年代的垃圾回收都会触发STW事件，暂停所有的应用线程来执行垃圾收集。两者在执行标记和复制/整理阶段时都使用多个线程，因此得名Parallel。通过多个GC线程并行执行，能使JVM在多CPU平台上的GC时间大幅减少。

  通过命令行参数 -XX:ParallelGCThreads=NNN 来指定 GC 线程数， 其默认值为CPU核心数。 可以通过下面的任意一组命令行参数来指定并行GC：

-XX:+UseParallelGC 
 -XX:+UseParallelOldGC 
 -XX:+UseParallelGC -XX:+UseParallelOldGC

  并行垃圾收集器适用于多核服务器，主要目标是增加吞吐量(也就是降低GC总体消耗的时间)。为了达成这个目标，会尽量使用尽可能多的CPU资源：

  • 在GC事件执行期间，所有 CPU 内核都在并行清理垃圾，所以暂停时间相对来说更短；
  • 在两次GC事件中间的间隔期，不会启动GC线程，所以这段时间内不会消耗任何系统资源；

  另一方面，因为此GC的所有阶段都不能中断，所以并行GC很容易出现长时间的卡顿（注：长时间卡顿的意思是，并行GC启动后，一次性完成所有的GC操作，于是单次暂停的时间会较长。这里说的长时间也很短，一般来说例如minor GC是毫秒级别，full GC是几十几百毫秒级别）。如果系统延迟是非常重要的性能指标（主要目标是最低的停顿时间/延迟），而不是整体的吞吐量最大，那么就应该选择其他垃圾收集器组合。

2.2 并行GC日志解读

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

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

Java HotSpot(TM) 64-Bit Server VM (25.202-b08) for bsd-amd64 JRE (1.8.0_202-b08), built on Dec 15 2018 20:16:16 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 8388608k(17228k free)

/proc/meminfo:

CommandLine flags: -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2021-12-26T12:29:48.527-0800: 0.287: [GC (Allocation Failure) [PSYoungGen: 131041K->21492K(153088K)] 131041K->49246K(502784K), 0.0152442 secs] [Times: user=0.03 sys=0.05, real=0.02 secs] 
2021-12-26T12:29:48.564-0800: 0.324: [GC (Allocation Failure) [PSYoungGen: 152957K->21498K(153088K)] 180712K->93172K(502784K), 0.0203832 secs] [Times: user=0.03 sys=0.07, real=0.02 secs] 
2021-12-26T12:29:48.600-0800: 0.361: [GC (Allocation Failure) [PSYoungGen: 153082K->21492K(153088K)] 224756K->131158K(502784K), 0.0145353 secs] [Times: user=0.03 sys=0.04, real=0.01 secs] 
2021-12-26T12:29:48.632-0800: 0.392: [GC (Allocation Failure) [PSYoungGen: 153076K->21499K(153088K)] 262742K->171192K(502784K), 0.0131396 secs] [Times: user=0.03 sys=0.04, real=0.01 secs] 
2021-12-26T12:29:48.662-0800: 0.422: [GC (Allocation Failure) [PSYoungGen: 153083K->21500K(153088K)] 302776K->213889K(502784K), 0.0130427 secs] [Times: user=0.04 sys=0.05, real=0.01 secs] 
2021-12-26T12:29:48.691-0800: 0.452: [GC (Allocation Failure) [PSYoungGen: 153084K->21491K(80384K)] 345473K->257674K(430080K), 0.0217015 secs] [Times: user=0.04 sys=0.03, real=0.02 secs] 
2021-12-26T12:29:48.720-0800: 0.480: [GC (Allocation Failure) [PSYoungGen: 80371K->34010K(116736K)] 316554K->276425K(466432K), 0.0044657 secs] [Times: user=0.02 sys=0.01, real=0.00 secs] 
2021-12-26T12:29:48.732-0800: 0.492: [GC (Allocation Failure) [PSYoungGen: 92792K->44819K(116736K)] 335207K->292058K(466432K), 0.0047677 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:48.744-0800: 0.505: [GC (Allocation Failure) [PSYoungGen: 103238K->53411K(116736K)] 350478K->308994K(466432K), 0.0064440 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] 
2021-12-26T12:29:48.759-0800: 0.519: [GC (Allocation Failure) [PSYoungGen: 112291K->35958K(116736K)] 367874K->322789K(466432K), 0.0160100 secs] [Times: user=0.03 sys=0.03, real=0.02 secs] 
2021-12-26T12:29:48.783-0800: 0.544: [GC (Allocation Failure) [PSYoungGen: 94838K->23416K(116736K)] 381669K->340530K(466432K), 0.0092515 secs] [Times: user=0.02 sys=0.03, real=0.01 secs] 
2021-12-26T12:29:48.793-0800: 0.553: [Full GC (Ergonomics) [PSYoungGen: 23416K->0K(116736K)] [ParOldGen: 317113K->232542K(349696K)] 340530K->232542K(466432K), [Metaspace: 2560K->2560K(1056768K)], 0.0268958 secs] [Times: user=0.17 sys=0.00, real=0.02 secs] 
2021-12-26T12:29:48.828-0800: 0.588: [GC (Allocation Failure) [PSYoungGen: 58663K->18278K(116736K)] 291205K->250820K(466432K), 0.0017320 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2021-12-26T12:29:48.838-0800: 0.599: [GC (Allocation Failure) [PSYoungGen: 76934K->20931K(116736K)] 309477K->270511K(466432K), 0.0057888 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
2021-12-26T12:29:48.853-0800: 0.613: [GC (Allocation Failure) [PSYoungGen: 79750K->19587K(116736K)] 329330K->288919K(466432K), 0.0034292 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:48.865-0800: 0.626: [GC (Allocation Failure) [PSYoungGen: 78254K->19476K(116736K)] 347585K->305633K(466432K), 0.0024579 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:48.876-0800: 0.637: [GC (Allocation Failure) [PSYoungGen: 78146K->20006K(116736K)] 364303K->322818K(466432K), 0.0027379 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:48.879-0800: 0.639: [Full GC (Ergonomics) [PSYoungGen: 20006K->0K(116736K)] [ParOldGen: 302812K->260022K(349696K)] 322818K->260022K(466432K), [Metaspace: 2560K->2560K(1056768K)], 0.0277829 secs] [Times: user=0.19 sys=0.00, real=0.03 secs] 
2021-12-26T12:29:48.917-0800: 0.678: [GC (Allocation Failure) [PSYoungGen: 58880K->19931K(116736K)] 318902K->279953K(466432K), 0.0018048 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:48.929-0800: 0.690: [GC (Allocation Failure) [PSYoungGen: 78811K->20637K(116736K)] 338833K->300307K(466432K), 0.0028534 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2021-12-26T12:29:48.942-0800: 0.703: [GC (Allocation Failure) [PSYoungGen: 79517K->20780K(116736K)] 359187K->320023K(466432K), 0.0038547 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:48.955-0800: 0.715: [GC (Allocation Failure) [PSYoungGen: 79545K->18244K(116736K)] 378788K->337568K(466432K), 0.0036552 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:48.959-0800: 0.719: [Full GC (Ergonomics) [PSYoungGen: 18244K->0K(116736K)] [ParOldGen: 319323K->283238K(349696K)] 337568K->283238K(466432K), [Metaspace: 2560K->2560K(1056768K)], 0.0354562 secs] [Times: user=0.21 sys=0.01, real=0.04 secs] 
2021-12-26T12:29:49.006-0800: 0.766: [GC (Allocation Failure) [PSYoungGen: 58248K->21293K(116736K)] 341487K->304531K(466432K), 0.0028698 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:49.019-0800: 0.779: [GC (Allocation Failure) [PSYoungGen: 79918K->22280K(116736K)] 363157K->324612K(466432K), 0.0035632 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2021-12-26T12:29:49.033-0800: 0.793: [GC (Allocation Failure) [PSYoungGen: 81160K->18825K(116736K)] 383492K->343018K(466432K), 0.0050360 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:49.038-0800: 0.798: [Full GC (Ergonomics) [PSYoungGen: 18825K->0K(116736K)] [ParOldGen: 324193K->299619K(349696K)] 343018K->299619K(466432K), [Metaspace: 2560K->2560K(1056768K)], 0.0324275 secs] [Times: user=0.19 sys=0.01, real=0.04 secs] 
2021-12-26T12:29:49.082-0800: 0.842: [GC (Allocation Failure) [PSYoungGen: 58839K->21598K(116736K)] 358459K->321218K(466432K), 0.0027108 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:49.095-0800: 0.855: [GC (Allocation Failure) [PSYoungGen: 80390K->19606K(116736K)] 380010K->339237K(466432K), 0.0037413 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:49.099-0800: 0.859: [Full GC (Ergonomics) [PSYoungGen: 19606K->0K(116736K)] [ParOldGen: 319630K->308062K(349696K)] 339237K->308062K(466432K), [Metaspace: 2560K->2560K(1056768K)], 0.0329087 secs] [Times: user=0.20 sys=0.00, real=0.04 secs] 
2021-12-26T12:29:49.143-0800: 0.903: [GC (Allocation Failure) [PSYoungGen: 58816K->16859K(116736K)] 366879K->324922K(466432K), 0.0027406 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:49.155-0800: 0.915: [GC (Allocation Failure) [PSYoungGen: 75739K->17677K(116736K)] 383802K->342453K(466432K), 0.0029850 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:49.158-0800: 0.918: [Full GC (Ergonomics) [PSYoungGen: 17677K->0K(116736K)] [ParOldGen: 324776K->312157K(349696K)] 342453K->312157K(466432K), [Metaspace: 2560K->2560K(1056768K)], 0.0325338 secs] [Times: user=0.21 sys=0.00, real=0.04 secs] 
2021-12-26T12:29:49.203-0800: 0.964: [GC (Allocation Failure) [PSYoungGen: 58880K->18231K(117760K)] 371037K->330389K(467456K), 0.0022387 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-12-26T12:29:49.215-0800: 0.976: [GC (Allocation Failure) [PSYoungGen: 78135K->37327K(116736K)] 390293K->349485K(466432K), 0.0034790 secs] [Times: user=0.02 sys=0.01, real=0.00 secs] 
2021-12-26T12:29:49.227-0800: 0.988: [GC (Allocation Failure) [PSYoungGen: 96949K->23482K(119296K)] 409107K->370976K(468992K), 0.0099279 secs] [Times: user=0.03 sys=0.02, real=0.01 secs] 
2021-12-26T12:29:49.238-0800: 0.998: [Full GC (Ergonomics) [PSYoungGen: 23482K->0K(119296K)] [ParOldGen: 347493K->321756K(349696K)] 370976K->321756K(468992K), [Metaspace: 2560K->2560K(1056768K)], 0.0328866 secs] [Times: user=0.21 sys=0.00, real=0.04 secs] 
2021-12-26T12:29:49.282-0800: 1.043: [Full GC (Ergonomics) [PSYoungGen: 60818K->0K(119296K)] [ParOldGen: 321756K->327802K(349696K)] 382574K->327802K(468992K), [Metaspace: 2560K->2560K(1056768K)], 0.0330792 secs] [Times: user=0.22 sys=0.01, real=0.03 secs] 
2021-12-26T12:29:49.327-0800: 1.088: [Full GC (Ergonomics) [PSYoungGen: 61332K->0K(119296K)] [ParOldGen: 327802K->330183K(349696K)] 389135K->330183K(468992K), [Metaspace: 2560K->2560K(1056768K)], 0.0325230 secs] [Times: user=0.23 sys=0.00, real=0.04 secs] 
2021-12-26T12:29:49.373-0800: 1.133: [Full GC (Ergonomics) [PSYoungGen: 61440K->0K(119296K)] [ParOldGen: 330183K->334786K(349696K)] 391623K->334786K(468992K), [Metaspace: 2560K->2560K(1056768K)], 0.0319694 secs] [Times: user=0.22 sys=0.00, real=0.03 secs] 
2021-12-26T12:29:49.417-0800: 1.178: [Full GC (Ergonomics) [PSYoungGen: 61400K->0K(119296K)] [ParOldGen: 334786K->342656K(349696K)] 396186K->342656K(468992K), [Metaspace: 2560K->2560K(1056768K)], 0.0349932 secs] [Times: user=0.23 sys=0.00, real=0.04 secs] 
Heap
 PSYoungGen      total 119296K, used 2594K [0x00000007b5580000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 61440K, 4% used [0x00000007b5580000,0x00000007b58089d8,0x00000007b9180000)
  from space 57856K, 0% used [0x00000007bc780000,0x00000007bc780000,0x00000007c0000000)
  to   space 55296K, 0% used [0x00000007b9180000,0x00000007b9180000,0x00000007bc780000)
 ParOldGen       total 349696K, used 342656K [0x00000007a0000000, 0x00000007b5580000, 0x00000007b5580000)
  object space 349696K, 97% used [0x00000007a0000000,0x00000007b4ea00e0,0x00000007b5580000)
 Metaspace       used 2567K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 276K, capacity 386K, committed 512K, reserved 1048576K

2.2.1 Minor GC日志分析

为了更好的分析老年代，我这里用第5次GC日志分析

2021-12-26T12:29:48.662-0800: 0.422: [GC (Allocation Failure) 
[PSYoungGen: 153083K->21500K(153088K)] 302776K->213889K(502784K), 0.0130427 secs] 
[Times: user=0.04 sys=0.05, real=0.01 secs]

解读如下：

  1. 2021-12-26T12:29:48.662-0800: 0.422 – GC事件开始的时间。
  2. GC – 用来区分 Minor GC 还是 Full GC 的标志。这里是一次小型GC(Minor GC) 。
  3. PSYoungGen – 垃圾收集器的名称。这个名字表示的是在年轻代中使用的，表示这是并行的标记-复制(mark-copy) ，全线暂停(STW) 垃圾收集器。 153083K->21500K(153088K)表示GC前的年轻代使用量、GC后年轻代的使用量以及年轻代的总大小，简单计算GC后的年轻代使用率 21500K / 153088K = 14% 。
  4. 302776K->213889K(502784K) 则是GC前后整个堆内存的使用量，以及此时可用堆的总大小，GC后堆内存使用率为 213889K / 502784K = 42.5% 。
  5. [Times: user=0.04 sys=0.05, real=0.01 secs] – GC事件的持续时间，通过三个部分来衡量： user 表示GC线程所消耗的总CPU时间， sys 表示操作系统调用和系统等待事件所消耗的时间； real 则表示应用程序实际暂停的时间。因为并不是所有的操作过程都能全部并行，所以在 Parallel GC 中， real 约等于 user + system /GC线程数 。

  通过这部分日志可以简单算出：在GC之前，堆内存总使用量为 302776K，其中年轻代为 153083K ，那么可以算出刚开始老年代使用量为 302776K - 153083K = 149693K 。

  在此次GC完成后，年轻代使用量减少了 153083K - 21500K = 131583K ，总的堆内存使用量减少了302776K - 213889K = 88887K 。 那么我们可以计算出本次GC有 131583K - 88887K = 27754K 的对象从年轻代提升到老年代。年轻代减少的内存 - 堆内存减少的内存 = 年轻代提升到老年代的内存

  GC后老年代的使用量为： 213889K - 21500K = 192389K （GC后堆内存使用量 - GC后年轻代使用量）。 老年代的总大小为： 502784K - 153088K = 349696K（堆内存总大小 - 年轻代总大小） ，使用率为： 192389K / 349696K = 55% ，已经占用一半了。

总结：关于年轻代GC，我们关注暂停时间以及GC后的内存使用率是否正常即可，不用特别关注GC前的使用量，而且只要业务在运行，年轻代的对象分配就少不了，回收量也就不会少。

2.2.2 Full GC日志分析

2021-12-26T12:29:48.793-0800: 0.553: [Full GC (Ergonomics)
 [PSYoungGen: 23416K->0K(116736K)]
 [ParOldGen: 317113K->232542K(349696K)] 340530K->232542K(466432K),
 [Metaspace: 2560K->2560K(1056768K)], 0.0268958 secs] 
 [Times: user=0.17 sys=0.00, real=0.02 secs]

解读如下：

  1. 2021-12-26T12:29:48.793-0800: – GC事件开始的时间。
  2. Full GC – 完全GC的标志。 Full GC 表明本次GC清理年轻代和老年代， Ergonomics 是触发GC的原因，表示JVM内部环境认为此时可以进行一次垃圾收集。
  3. [PSYoungGen: 23416K->0K(116736K)] – 和上面的示例一样，清理年轻代的垃圾收集器是为 “PSYoungGen” 的STW收集器，采用标记-复制(mark-copy) 算法。年轻代使用量从 23416K变为 0，一般 Full GC 中年轻代的结果都是这样。
  4. ParOldGen – 用于清理老年代空间的垃圾收集器类型。在这里使用的是名为 ParOldGen 的垃 圾收集器，这是一款并行 STW垃圾收集器，算法为标记-清除-整理(mark-sweep-compact) 。317113K->232542K(349696K) – 在GC前后老年代内存的使用情况以及老年代空间大小。简单计 算一下，GC之前，老年代使用率为 317113K/349696K = 90% ，GC后老年代使用率 232542K / 349696K = 66% ，确实回收了不少。

  那么有多少内存提升到老年代呢？其实在Full GC里面不好算， 而在Minor GC之中比较好算，因为Full GC清理的是整个堆内存。
  举个例子，若堆内存的减少100K，年轻代减少180K，可能有年轻代有80K提升到老年代的内存，也可能是年轻代有110K提升（70K被清理），而老年代有30K被清理。
  若堆内存减少200K，年轻代减少100K，可能是年轻代提升了20K(80K被清理)，老年代清理了120K，也可能年轻代全部提升，老年代清理了200K。
  总之，Full GC虽然可以计算提升数值，但是有多少内存从年轻代提升到老年代是没有具体套路，得看减出来的差值哪个大，然后具体分析，比较麻烦。但是在Minor GC中，年轻代减少的内存 - 堆内存减少的内存 = 年轻代提升到老年代的内存，这是一定的。

  1. 340530K->232542K(466432K) – 在垃圾收集之前和之后堆内存的使用情况，以及可用堆内存的总容量。简单分析可知，GC之前堆内存使用率为: 340530K/ 466432K = 73% ，GC之后堆内存的使用率为： 232542K / 466432K = 50% 。
  2. [Metaspace: 2560K->2560K(1056768K)] – 前面我们也看到了关于 Metaspace 空间的类似信息。可以看出，在GC事件中 Metaspace 里面没有回收任何对象，熟悉Java内存模型的朋友肯定知道，Metaspace元数据区属于非堆，GC根本不管理，当然内存没有变化。
  3. 0.0268958secs – GC事件持续的时间，以秒为单位。
  4. [Times: user=0.17 sys=0.00, real=0.02 secs] – GC事件的持续时间，含义参见前面。

总结: Full GC 和 Minor GC的区别是很明显的 —— Full GC除了处理年轻代，还清理了老年代，Full GC时我们更关注老年代的使用量有没有下降，以及下降了多少。如果Full GC之后内存不怎么下降，使用率还很高，那就说明系统有问题了。

3. CMS GC

3.1 CMS垃圾收集器介绍

  CMS GC的官方名称为 “Mostly Concurrent Mark and Sweep Garbage Collector”（最大并发-标记-清除-垃圾收集器）。其对年轻代采用并行STW方式的 mark-copy (标记-复制)算法 ，对老年代主要使用并发 mark-sweep (标记-清除)算法 。 CMS GC的设计目标是避免在老年代垃圾收集时出现长时间的卡顿，主要通过两种手段来达成此目标：

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

  也就是说，在这些阶段并没有明显的应用线程暂停。但值得注意的是，它仍然和应用线程争抢CPU时间。默认情况下，CMS 使用的并发线程数等于CPU核心数的 1/4。

通过以下选项来指定CMS垃圾收集器：

-XX:+UseConcMarkSweepGC

  如果服务器是多核CPU，并且主要调优目标是降低GC停顿导致的系统延迟，那么使用CMS是个很明智的选择。通过减少每一次GC停顿的时间，很多时候会直接改善系统的用户体验。因为多数时候都有部分CPU资源被GC消耗，所以在CPU资源受限的情况下，CMS GC会比并行GC的吞吐量差一些（对于绝大部分系统， 这个吞吐和延迟的差别应该都不明显）。

3.2 CMS GC日志解读

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

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

Java HotSpot(TM) 64-Bit Server VM (25.202-b08) for bsd-amd64 JRE (1.8.0_202-b08), built on Dec 15 2018 20:16:16 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 8388608k(20340k free)

/proc/meminfo:

CommandLine flags: -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912 -XX:MaxNewSize=178958336 -XX:MaxTenuringThreshold=6 -XX:NewSize=178958336 -XX:OldPLABSize=16 -XX:OldSize=357912576 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
2022-01-09T15:24:32.400-0800: 0.426: [GC (Allocation Failure) 2022-01-09T15:24:32.401-0800: 0.426: [ParNew: 139776K->17471K(157248K), 0.0176261 secs] 139776K->51073K(506816K), 0.0179060 secs] [Times: user=0.03 sys=0.04, real=0.01 secs] 
2022-01-09T15:24:32.443-0800: 0.468: [GC (Allocation Failure) 2022-01-09T15:24:32.443-0800: 0.468: [ParNew: 157247K->17472K(157248K), 0.0582665 secs] 190849K->100725K(506816K), 0.0583472 secs] [Times: user=0.07 sys=0.05, real=0.06 secs] 
2022-01-09T15:24:32.522-0800: 0.548: [GC (Allocation Failure) 2022-01-09T15:24:32.522-0800: 0.548: [ParNew: 157079K->17472K(157248K), 0.0432975 secs] 240333K->147550K(506816K), 0.0433752 secs] [Times: user=0.14 sys=0.01, real=0.04 secs] 
2022-01-09T15:24:32.586-0800: 0.612: [GC (Allocation Failure) 2022-01-09T15:24:32.586-0800: 0.612: [ParNew: 157248K->17471K(157248K), 0.0376257 secs] 287326K->196615K(506816K), 0.0377060 secs] [Times: user=0.19 sys=0.02, real=0.04 secs] 
2022-01-09T15:24:32.624-0800: 0.650: [GC (CMS Initial Mark) [1 CMS-initial-mark: 179144K(349568K)] 196759K(506816K), 0.0001415 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:32.624-0800: 0.650: [CMS-concurrent-mark-start]
2022-01-09T15:24:32.627-0800: 0.653: [CMS-concurrent-mark: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:32.627-0800: 0.653: [CMS-concurrent-preclean-start]
2022-01-09T15:24:32.628-0800: 0.653: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:32.628-0800: 0.653: [CMS-concurrent-abortable-preclean-start]
2022-01-09T15:24:32.649-0800: 0.674: [GC (Allocation Failure) 2022-01-09T15:24:32.649-0800: 0.675: [ParNew: 156771K->17470K(157248K), 0.0419748 secs] 335915K->241582K(506816K), 0.0420578 secs] [Times: user=0.15 sys=0.02, real=0.05 secs] 
2022-01-09T15:24:32.708-0800: 0.734: [GC (Allocation Failure) 2022-01-09T15:24:32.708-0800: 0.734: [ParNew: 157246K->17471K(157248K), 0.0410544 secs] 381358K->288636K(506816K), 0.0415380 secs] [Times: user=0.18 sys=0.02, real=0.05 secs] 
2022-01-09T15:24:32.769-0800: 0.795: [GC (Allocation Failure) 2022-01-09T15:24:32.769-0800: 0.795: [ParNew: 157247K->17471K(157248K), 0.0396990 secs] 428412K->327152K(506816K), 0.0397807 secs] [Times: user=0.19 sys=0.02, real=0.04 secs] 
2022-01-09T15:24:32.829-0800: 0.854: [GC (Allocation Failure) 2022-01-09T15:24:32.829-0800: 0.854: [ParNew: 157247K->157247K(157248K), 0.0000394 secs]2022-01-09T15:24:32.829-0800: 0.854: [CMS2022-01-09T15:24:32.829-0800: 0.854: [CMS-concurrent-abortable-preclean: 0.006/0.201 secs] [Times: user=0.61 sys=0.07, real=0.20 secs] 
 (concurrent mode failure): 309680K->257052K(349568K), 0.1563297 secs] 466928K->257052K(506816K), [Metaspace: 2560K->2560K(1056768K)], 0.1564548 secs] [Times: user=0.07 sys=0.05, real=0.16 secs] 
2022-01-09T15:24:33.192-0800: 1.218: [GC (Allocation Failure) 2022-01-09T15:24:33.192-0800: 1.218: [ParNew: 139591K->17468K(157248K), 0.0072463 secs] 396643K->306430K(506816K), 0.0073297 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2022-01-09T15:24:33.200-0800: 1.225: [GC (CMS Initial Mark) [1 CMS-initial-mark: 288961K(349568K)] 306731K(506816K), 0.0001332 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:33.200-0800: 1.226: [CMS-concurrent-mark-start]
2022-01-09T15:24:33.201-0800: 1.227: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:33.201-0800: 1.227: [CMS-concurrent-preclean-start]
2022-01-09T15:24:33.202-0800: 1.228: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:33.202-0800: 1.228: [CMS-concurrent-abortable-preclean-start]
2022-01-09T15:24:33.221-0800: 1.246: [GC (Allocation Failure) 2022-01-09T15:24:33.221-0800: 1.246: [ParNew: 157244K->17470K(157248K), 0.0328066 secs] 446206K->342268K(506816K), 0.0328842 secs] [Times: user=0.07 sys=0.01, real=0.03 secs] 
2022-01-09T15:24:33.254-0800: 1.280: [CMS-concurrent-abortable-preclean: 0.001/0.052 secs] [Times: user=0.09 sys=0.01, real=0.05 secs] 
2022-01-09T15:24:33.254-0800: 1.280: [GC (CMS Final Remark) [YG occupancy: 25303 K (157248 K)]2022-01-09T15:24:33.255-0800: 1.280: [Rescan (parallel) , 0.0003075 secs]2022-01-09T15:24:33.255-0800: 1.280: [weak refs processing, 0.0000297 secs]2022-01-09T15:24:33.255-0800: 1.281: [class unloading, 0.0002089 secs]2022-01-09T15:24:33.255-0800: 1.281: [scrub symbol table, 0.0002644 secs]2022-01-09T15:24:33.255-0800: 1.281: [scrub string table, 0.0001460 secs][1 CMS-remark: 324797K(349568K)] 350101K(506816K), 0.0010829 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:33.256-0800: 1.281: [CMS-concurrent-sweep-start]
2022-01-09T15:24:33.256-0800: 1.282: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:33.256-0800: 1.282: [CMS-concurrent-reset-start]
2022-01-09T15:24:33.256-0800: 1.282: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 157248K, used 156429K [0x00000007a0000000, 0x00000007aaaa0000, 0x00000007aaaa0000)
  eden space 139776K,  99% used [0x00000007a0000000, 0x00000007a87b3c58, 0x00000007a8880000)
  from space 17472K,  99% used [0x00000007a9990000, 0x00000007aaa9fa68, 0x00000007aaaa0000)
  to   space 17472K,   0% used [0x00000007a8880000, 0x00000007a8880000, 0x00000007a9990000)
 concurrent mark-sweep generation total 349568K, used 285724K [0x00000007aaaa0000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 2567K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 276K, capacity 386K, committed 512K, reserved 1048576K

  可以看到，比起串行GC/并行GC来说，CMS的日志信息复杂了很多，这一方面是因为 CMS拥有更加精细的GC步骤，另一方面GC日志很详细就意味着暴露出来的信息也就更全面细致。

3.2.1 Minor GC日志分析

2022-01-09T15:24:32.443-0800: 0.468: [GC (Allocation Failure) 
	2022-01-09T15:24:32.443-0800: 0.468: [ParNew: 157247K->17472K(157248K), 0.0582665 secs]
	190849K->100725K(506816K), 0.0583472 secs]
	[Times: user=0.07 sys=0.05, real=0.06 secs]

解读如下：

  1. 2022-01-09T15:24:32.443-0800: 0.468: – GC事件开始的时间。
  2. GC (Allocation Failure) – 用来区分 Minor GC 还是 Full GC 的标志。 GC 表明这是一次小型GC ，Allocation Failure 表示触发GC的原因。本次GC事件，是由于年轻代可用空间不足，新对象的内存分配失败引起的。
  3. [ParNew: 157247K->17472K(157248K), 0.0582665 secs] - 其中 ParNew 是垃圾收集器的名称，对应的就是前面日志中打印的 -XX:+UseParNewGC 这个命令行标志。表示在年轻代中使用的并行的标记-复制(mark-copy) 垃圾收集器，这是专门设计了用来配合 CMS 垃圾收集器，因为CMS只负责回收老年代。后面的数字表示GC前后的年轻代使用量，以及年轻代的总大小。0.0582665 secs 是消耗的时间。
  4. 190849K->100725K(506816K), 0.0583472 secs – 表示GC前后堆内存的使用量，以及堆内存空间的大小。消耗的时间是 0.0583472 secs，和前面的 ParNew 部分的时间基本上一样。
  5. [Times: user=0.07 sys=0.05, real=0.06 secs] – GC事件的持续时间。 user 是GC线程所消耗的总CPU时间； sys 是操作系统调用和系统等待事件消耗的时间； 应用程序实际暂停的时间 real ≈ (user + sys) / GC线程数 。因为并不是所有线程都用来GC，总有一定比例的处理过程是不能并行执行的。

  进一步计算和分析可以得知，在GC之前，年轻代使用量为 157247K / 157248K = 99.9% 。堆内存的使用率为 190849K / 506816K = 37.7% 。稍微估算一下，GC前老年代的使用率为： (190849K-157247K) / (506816K-157248K) = (33602K /349568K) = 9.6% 。GC后年轻代使用量为 17472K / 157248K = 11% ，下降了 139775K 。堆内存使用量为 100725K / 506816K = 19.8% ，只下降了 90124K 。年轻代减少的内存 - 堆内存减少的内存 = 年轻代提升到老年代的内存，则139775K - 90124K = 49651K 。

3.2.2 Full GC日志分析

  CMS的日志是一种完全不同的格式，并且很长，因为CMS对老年代进行垃圾收集时每个阶段都会有自己的日志。为了简洁，我们将对这部分日志按照阶段依次介绍

2022-01-09T15:24:33.200-0800: 1.225: [GC (CMS Initial Mark) 
[1 CMS-initial-mark: 288961K(349568K)] 306731K(506816K), 0.0001332 secs] 
[Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:33.200-0800: 1.226: [CMS-concurrent-mark-start]
2022-01-09T15:24:33.201-0800: 1.227: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:33.201-0800: 1.227: [CMS-concurrent-preclean-start]
2022-01-09T15:24:33.202-0800: 1.228: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:33.202-0800: 1.228: [CMS-concurrent-abortable-preclean-start]
2022-01-09T15:24:33.221-0800: 1.246: [GC (Allocation Failure) 2022-01-09T15:24:33.221-0800: 1.246: [ParNew: 157244K->17470K(157248K), 0.0328066 secs] 446206K->342268K(506816K), 0.0328842 secs] [Times: user=0.07 sys=0.01, real=0.03 secs] 
2022-01-09T15:24:33.254-0800: 1.280: [CMS-concurrent-abortable-preclean: 0.001/0.052 secs] [Times: user=0.09 sys=0.01, real=0.05 secs] 
2022-01-09T15:24:33.254-0800: 1.280: [GC (CMS Final Remark) 
[YG occupancy: 25303 K (157248 K)]
2022-01-09T15:24:33.255-0800: 1.280: 
[Rescan (parallel) , 0.0003075 secs]
2022-01-09T15:24:33.255-0800: 1.280: 
[weak refs processing, 0.0000297 secs]
2022-01-09T15:24:33.255-0800: 1.281: 
[class unloading, 0.0002089 secs]
2022-01-09T15:24:33.255-0800: 1.281: 
[scrub symbol table, 0.0002644 secs]
2022-01-09T15:24:33.255-0800: 1.281: 
[scrub string table, 0.0001460 secs]
[1 CMS-remark: 324797K(349568K)] 350101K(506816K), 0.0010829 secs] 
[Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:33.256-0800: 1.281: [CMS-concurrent-sweep-start]
2022-01-09T15:24:33.256-0800: 1.282: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-09T15:24:33.256-0800: 1.282: [CMS-concurrent-reset-start]
2022-01-09T15:24:33.256-0800: 1.282: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

  在实际情况下，进行老年代的并发回收时，可能会伴随着多次年轻代的minor GC。在这种情况下，full GC 的日志中就会掺杂着多次minor GC事件。

3.2.2.1 阶段 1: Initial Mark(初始标记) （有STW）

  这个阶段伴随着STW暂停。初始标记的目标是标记所有的根对象，包括根对象直接引用的对象，以及被年轻代中所有存活对象所引用的对象（老年代单独回收），见下图。

【为什么CMS不管年轻代了呢? 前面不是刚刚完成minor GC嘛，再去收集年轻代估计也没什么效果】。


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

先看这个阶段的日志：

2022-01-09T15:24:33.200-0800: 1.225: 
[GC (CMS Initial Mark)
 [1 CMS-initial-mark: 288961K(349568K)] 306731K(506816K), 0.0001332 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]

本阶段日志解读如下：

  1. 2022-01-09T15:24:33.200-0800: 1.225: – 时间部分就不讲了，参考前面的解读。后面的其他阶段也一样，不再进行重复介绍。
  2. CMS Initial Mark – 这个阶段的名称为 “Initial Mark”，会标记所有的 GC Root。
  3. [1 CMS-initial-mark: 288961K(349568K)] – 这部分数字表示老年代的使用量，以及老年代的空间大小。
  4. 306731K(506816K)，0.0001332 secs – 当前堆内存的使用量，以及可用堆的大小、消耗的时间。可以看出这个时间非常短，只有 0.1毫秒左右，因为要标记的这些Root数量很少。
  5. [Times: user=0.00 sys=0.00, real=0.00 secs] – 初始标记事件暂停的时间，都是0可以忽略不计。
3.2.2.2 阶段 2: Concurrent Mark(并发标记)

  在此阶段，CMS GC遍历老年代，标记所有的存活对象，从前一阶段 “Initial Mark” 找到的根对象开始算起。
  所谓“并发标记”阶段，就是与应用程序同时运行，不用暂停的阶段。 请注意，并非所有老年代中存活的对象都在此阶段被标记，因为在标记过程中对象的引用关系还在发生变化。


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

在上面的示意图中， “ 当前处理的对象 ” 的一个引用就被应用线程给断开了，即这个部分的对象关系发生了变化（后面会讲如何处理）。

先看这个阶段的日志：

2022-01-09T15:24:33.200-0800: 1.226: [CMS-concurrent-mark-start]
2022-01-09T15:24:33.201-0800: 1.227: 
[CMS-concurrent-mark: 0.001/0.001 secs] 
[Times: user=0.00 sys=0.00, real=0.00 secs]

本阶段日志解读如下：

  1. CMS-concurrent-mark – 指明了是CMS垃圾收集器所处的阶段为并发标记(“Concurrent Mark”) 。
  2. 0.001/0.001 secs – 此阶段的持续时间，分别是GC线程消耗的时间和实际消耗的时间。
  3. [Times: user=0.00 sys=0.00, real=0.00 secs] – Times 对并发阶段来说这些时间并没多少意义，因为是从并发标记开始时刻计算的，而这段时间应用线程也在执行，所以这个时间只是一个大概的值。
3.2.2.3 阶段 3: Concurrent Preclean(并发预清理)

  此阶段同样是与应用线程并发执行的，不需要停止应用线程。 因为前一阶段【并发标记】与程序并发运行，可能有一些引用关系已经发生了改变。如果在并发标记过程中引用关系发生了变化，JVM会通过“ Card（卡片）”的方式将引用关系发生了改变的区域标记为“脏”区，这就是所谓的卡片标记（Card Marking）


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

  在预清理阶段，这些脏对象会被统计出来，他们所引用的对象也会被标记。此阶段完成后，用以标记的 card 也就会被清空。


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

此外，本阶段也会进行一些必要的细节处理， 还会为 Final Remark 阶段做一些准备工作。

看看本阶段的日志：

2022-01-09T15:24:33.201-0800: 1.227: [CMS-concurrent-preclean-start]
2022-01-09T15:24:33.202-0800: 1.228: 
[CMS-concurrent-preclean: 0.001/0.001 secs] 
[Times: user=0.00 sys=0.00, real=0.00 secs]

简单解读本阶段日志：

  1. CMS-concurrent-preclean – 表明这是并发预清理阶段的日志，这个阶段会统计前面的并发标 记阶段执行过程中引用关系发生了改变的对象。
  2. 0.001/0.001 secs – 此阶段的持续时间，分别是GC线程运行时间和实际占用的时间。
  3. [Times: user=0.00 sys=0.00, real=0.00 secs] – Times 这部分对并发阶段来说没多少意义，因为是从开始时间计算的，而这段时间内不仅GC线程在执行并发预清理，应用线程也在运行。
3.2.2.4 阶段 4: Concurrent Abortable Preclean(可取消的并发预清理)

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

看看本阶段的日志：

2022-01-09T15:24:33.202-0800: 1.228: [CMS-concurrent-abortable-preclean-start]
2022-01-09T15:24:33.221-0800: 1.246: [GC (Allocation Failure) 
2022-01-09T15:24:33.221-0800: 1.246: [ParNew: 157244K->17470K(157248K), 0.0328066 secs] 
446206K->342268K(506816K), 0.0328842 secs] 
[Times: user=0.07 sys=0.01, real=0.03 secs] 
2022-01-09T15:24:33.254-0800: 1.280: 
[CMS-concurrent-abortable-preclean: 0.001/0.052 secs] 
[Times: user=0.09 sys=0.01, real=0.05 secs]

开头就说了，在CMS垃圾回收器中，Full GC 的日志中就会掺杂着多次Minor GC，这里有一个Minor GC，我们只分析Full GC就好了。

简单解读：

  1. CMS-concurrent-abortable-preclean – 指示此阶段的名称：“Concurrent Abortable Preclean”。
  2. 0.001/0.052 secs – 此阶段GC线程的运行时间和实际占用的时间。从本质上讲，GC线程试图 在执行 STW 暂停之前等待尽可能长的时间。默认条件下，此阶段可以持续最长5秒钟的时间。
  3. [Times: user=0.09 sys=0.01, real=0.05 secs] – “Times” 这部分对并发阶段来说没多少意义，因为程序在并发阶段中持续运行。

此阶段可能显著影响STW停顿的持续时间，并且有许多重要的配置选项和失败模式。

3.2.2.5 阶段 5: Final Remark(最终标记) （有STW）

  最终标记阶段是此次GC事件中的第二次(也是最后一次)STW停顿。 本阶段的目标是完成老年代中所有存活对象的标记。因为之前的预清理阶段是并发执行的，有可能GC线程跟不上应用程序的修改速度。所以需要一次 STW 暂停来处理各种复杂的情况。

  通常CMS会尝试在年轻代尽可能空的情况下执行 Final Remark 阶段，以免连续触发多次 STW 事件。

来看看本阶段日志，相对复杂一点

2022-01-09T15:24:33.254-0800: 1.280: [GC (CMS Final Remark) 
[YG occupancy: 25303 K (157248 K)]
2022-01-09T15:24:33.255-0800: 1.280: [Rescan (parallel) , 0.0003075 secs]
2022-01-09T15:24:33.255-0800: 1.280: [weak refs processing, 0.0000297 secs]
2022-01-09T15:24:33.255-0800: 1.281: [class unloading, 0.0002089 secs]
2022-01-09T15:24:33.255-0800: 1.281: [scrub symbol table, 0.0002644 secs]
2022-01-09T15:24:33.255-0800: 1.281: [scrub string table, 0.0001460 secs]
[1 CMS-remark: 324797K(349568K)] 350101K(506816K), 0.0010829 secs] 
[Times: user=0.00 sys=0.00, real=0.00 secs]

日志解读如下：

  1. CMS Final Remark – 这是此阶段的名称，最终标记阶段，会标记老年代中所有的存活对象，包 括此前的并发标记过程中创建/修改的引用。
  2. YG occupancy: 25303 K (157248 K) – 当前年轻代的使用量和总容量。
  3. [Rescan (parallel) , 0.0003075 secs] – 在程序暂停后进行重新扫描(Rescan)，以完成存活对象的标记。这部分是并行执行的，消耗的时间为 0.0003075秒 。
  4. weak refs processing，0.0000297 secs – 第一个子阶段： 处理弱引用的持续时间。
  5. class unloading，0.0002089 secs – 第二个子阶段： 卸载不使用的类，以及持续时间。
  6. scrub symbol table, 0.0002644 secs – 第三个子阶段： 清理符号表，即持有class级别 metadata 的符号表(symbol tables)。
  7. scrub string table, 0.0001460 secs – 第四个子阶段： 清理内联字符串对应的 string tables。
  8. [1 CMS-remark: 324797K(349568K)] – 此阶段完成后老年代的使用量和总容量。
  9. 350101K(506816K)，0.0010829 secs – 此阶段完成后，整个堆内存的使用量和总容量。
  10. [Times: user=0.00 sys=0.00, real=0.00 secs] – GC事件的持续时间。

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

3.2.2.6 阶段 6: Concurrent Sweep(并发清除)

此阶段与应用程序并发执行，不需要STW停顿。JVM在此阶段删除不再使用的对象，并回收他们占用的内存空间。


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

看看本阶段日志

2022-01-09T15:24:33.256-0800: 1.281: [CMS-concurrent-sweep-start]
2022-01-09T15:24:33.256-0800: 1.282: 
[CMS-concurrent-sweep: 0.001/0.001 secs] 
[Times: user=0.00 sys=0.00, real=0.00 secs]

简单解读下日志：

  1. CMS-concurrent-sweep – 此阶段的名称，“Concurrent Sweep”，并发清除老年代中所有未被 标记的对象、也就是不再使用的对象，以释放内存空间。
  2. 0.001/0.001 secs – 此阶段的持续时间和实际占用的时间，这是一个四舍五入值，只精确到小数点后3位。
  3. [Times: user=0.00 sys=0.00, real=0.00 secs] – “Times”部分对并发阶段来说没有多少意义，因为是从并发标记开始时计算的，而这段时间内不仅是并发标记线程在执行，程序线程也在运行。
3.2.2.7 阶段 7: Concurrent Reset(并发重置)

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

看看本阶段日志：

2022-01-09T15:24:33.256-0800: 1.282: [CMS-concurrent-reset-start]
2022-01-09T15:24:33.256-0800: 1.282: 
[CMS-concurrent-reset: 0.000/0.000 secs] 
[Times: user=0.00 sys=0.00, real=0.00 secs]

简单解读下日志：

  1. CMS-concurrent-reset – 此阶段的名称，“Concurrent Reset”，重置CMS算法的内部数据结构，为下一次GC循环做准备。
  2. 0.000/0.000 secs – 此阶段的持续时间和实际占用的时间
  3. [Times: user=0.00 sys=0.00,real=0.00 secs] – “Times”部分对并发阶段来说没多少意义，因为是从并发标记开始时计算的，而这段时间内不仅GC线程在运行，程序也在运行。

  那么问题来了，CMS 之后老年代内存使用量是多少呢? 很抱歉这里分析不了，只能通过后面的Minor GC日志来分析了，需要看下次的Minor GC的日志

  总之，CMS垃圾收集器在减少停顿时间上做了很多复杂而有用的工作，用于垃圾回收的并发线程执行的同时，并不需要暂停应用线程。 当然，CMS也有一些缺点，其中最大的问题就是老年代内存碎片问题（因为不压缩），在某些情况下GC会造成不可预测的暂停时间，特别是堆内存较大的情况下。

4. G1垃圾收集器

4.1 G1垃圾收集器介绍

  G1的全称是 Garbage-First ，意为垃圾优先，哪一块的垃圾最多就优先清理它。
  G1 GC最主要的设计目标是：将STW停顿的时间和分布，变成可预期且可配置的。

  事实上，G1 GC是一款软实时垃圾收集器，可以为其设置某项特定的性能指标。例如可以指定: 在任意 xx 毫秒时间范围内，STW停顿不得超过 yy 毫秒。 举例说明: 任意 1秒 内暂停时间不超过 5毫秒 。G1 GC 会尽力达成这个目标（有很大概率会满足，但并不完全确定）。

  为了达成可预期停顿时间的指标，G1 GC有一些独特的实现。 首先，堆不再分成年轻代和老年代，而是划分为多个（通常是2048个）可以存放对象的小块堆区域(smaller heap regions) 。每个小块，可能一会被定义成 Eden 区，一会被指定为 Survivor区或者Old 区。在逻辑上，所有的Eden区和Survivor区合起来就是年轻代，所有的Old区拼在一起那就是老年代，如下图所示：


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

  这样划分之后，使得 G1不必每次都去收集整个堆空间，而是以增量的方式来进行处理: 每次只处理一部分内存块，称为此次GC的回收集(collection set)。每次GC暂停都会收集所有年轻代的内存块，但一般只包含部分老年代的内存块，见下图带对号的部分：


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

  G1的另一项创新是，在并发阶段估算每个小堆块存活对象的总数。构建回收集的原则是： 垃圾最多的小块 会被优先收集。这也是G1名称的由来。

通过以下选项来指定G1垃圾收集器：

-XX:+UseG1GC

4.2 G1 GC常用参数设置

  • -XX:+UseG1GC ：启用G1 GC，JDK7和JDK8要求必须显示申请启动G1 GC；
  • -XX:G1NewSizePercent ：初始年轻代占整个Java Heap的大小，默认值为5%；
  • -XX:G1MaxNewSizePercent ：最大年轻代占整个Java Heap的大小，默认值为60%；
  • -XX:G1HeapRegionSize ：设置每个Region的大小，单位MB，需要为1，2，4，8，16，32中的某 个值，默认是堆内存的1/2000。如果这个值设置比较大，那么大对象就可以进入Region了。
  • -XX:ConcGCThreads ：与Java应用一起执行的GC线程数量，默认是Java线程的1/4，减少这个参 数的数值可能会提升并行回收的效率，提高系统内部吞吐量。如果这个数值过低，参与回收垃圾的线程不足，也会导致并行回收机制耗时加长。
  • -XX:+InitiatingHeapOccupancyPercent （简称IHOP）：G1内部并行回收循环启动的阈值， 默认为Java Heap的45%。这个可以理解为老年代使用大于等于45%的时候，JVM会启动垃圾回收。这个值非常重要，它决定了在什么时间启动老年代的并行回收。
  • -XX:G1HeapWastePercent ：G1停止回收的最小内存大小，默认是堆大小的5%。GC会收集所有的Region中的对象，但是如果下降到了5%，就会停下来不再收集了。就是说，不必每次回收就把所有的垃圾都处理完，可以遗留少量的下次处理，这样也降低了单次消耗的时间。
  • -XX:G1MixedGCCountTarget ：设置并行循环之后需要有多少个混合GC启动，默认值是8个。老 年代Regions的回收时间通常比年轻代的收集时间要长一些。所以如果混合收集器比较多，可以允许G1延长老年代的收集时间。
  • -XX:+G1PrintRegionLivenessInfo ：这个参数需要和 -XX:+UnlockDiagnosticVMOptions 配合启动，打印JVM的调试信息，每个Region里的对象存活信息。
  • -XX:G1ReservePercent ：G1为了保留一些空间用于年代之间的提升，默认值是堆空间的10%。 因为大量执行回收的地方在年轻代（存活时间较短），所以如果你的应用里面有比较大的堆内存空间、 比较多的大对象存活，这里需要保留一些内存。
  • -XX:+G1SummarizeRSetStats ：这也是一个VM的调试信息。如果启用，会在VM退出的时候打印出RSets的详细总结信息。如果启用 -XX:G1SummaryRSetStatsPeriod 参数，就会阶段性地打印 RSets信息。
  • -XX:+G1TraceConcRefinement ：这个也是一个VM的调试信息，如果启用，并行回收阶段的日志就会被详细打印出来。
  • -XX:+GCTimeRatio ：大家知道，GC的有些阶段是需要Stop-the-World，即停止应用线程的。这个参数就是计算花在Java应用线程上和花在GC线程上的时间比率，默认是9，跟新生代内存的分配比例一致。这个参数主要的目的是让用户可以控制花在应用上的时间，G1的计算公式是100/ （1+GCTimeRatio）。这样如果参数设置为9，则最多10%的时间会花在GC工作上面。Parallel GC的 默认值是99，表示1%的时间被用在GC上面，这是因为Parallel GC贯穿整个GC，而G1则根据Region来进行划分，不需要全局性扫描整个内存堆。
  • -XX:+UseStringDeduplication ：手动开启Java String对象的去重工作，这个是JDK8u20版本之后新增的参数，主要用于相同String避免重复申请内存，节约Region的使用。
  • -XX:MaxGCPauseMills ：预期G1每次执行GC操作的暂停时间，单位是毫秒，默认值是200毫秒， G1会尽量保证控制在这个范围内。

这里面最重要的参数，就是：

  1. -XX:+UseG1GC ：启用G1 GC；
  2. -XX:+InitiatingHeapOccupancyPercent ：决定什么情况下发生G1 GC；
  3. -XX:MaxGCPauseMills ：期望每次GC暂定的时间，比如我们设置为50，则G1 GC会通过调节每次GC的操作时间，尽量让每次系统的GC停顿都在50上下浮动。如果某次GC时间超过50ms， 比如说100ms，那么系统会自动在后面动态调整GC行为，围绕50毫秒浮动。

4.3 G1日志解读和分析

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

让我们看看G1 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(5481624k free), swap 28079616k(4538104k free)
CommandLine flags: -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation 
2022-01-10T10:42:58.694+0800: 0.203: [GC pause (G1 Evacuation Pause) (young), 0.0023921 secs]
   [Parallel Time: 2.0 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 202.8, Avg: 202.8, Max: 202.9, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.2, Avg: 0.4, Max: 0.9, Diff: 0.8, Sum: 1.5]
      [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.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.8, Avg: 1.3, Max: 1.5, Diff: 0.7, Sum: 5.1]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.7]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 1.8, Avg: 1.9, Max: 1.9, Diff: 0.2, Sum: 7.5]
      [GC Worker End (ms): Min: 204.6, Avg: 204.7, Max: 204.8, Diff: 0.2]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 25.0M(25.0M)->0.0B(21.0M) Survivors: 0.0B->4096.0K Heap: 29.2M(512.0M)->10.4M(512.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-10T10:42:58.706+0800: 0.215: [GC pause (G1 Evacuation Pause) (young), 0.0025225 secs]
   [Parallel Time: 2.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 215.1, Avg: 215.1, Max: 215.1, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.0, Sum: 0.5]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.3, Max: 1, Diff: 1, Sum: 1]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 1.4, Avg: 1.5, Max: 1.5, Diff: 0.1, Sum: 5.8]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 1.7, Avg: 1.7, Max: 1.7, Diff: 0.0, Sum: 6.7]
      [GC Worker End (ms): Min: 216.8, Avg: 216.8, Max: 216.8, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 21.0M(21.0M)->0.0B(24.0M) Survivors: 4096.0K->4096.0K Heap: 36.5M(512.0M)->21.0M(512.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
  // 这里省略很多重复类似的日志...................
2022-01-10T10:42:59.662+0800: 1.171: [GC concurrent-root-region-scan-start]
2022-01-10T10:42:59.662+0800: 1.171: [GC concurrent-root-region-scan-end, 0.0000776 secs]
2022-01-10T10:42:59.662+0800: 1.171: [GC concurrent-mark-start]
2022-01-10T10:42:59.664+0800: 1.173: [GC concurrent-mark-end, 0.0019498 secs]
2022-01-10T10:42:59.664+0800: 1.173: [GC remark 2022-01-10T10:42:59.664+0800: 1.173: [Finalize Marking, 0.0000447 secs] 2022-01-10T10:42:59.664+0800: 1.174: [GC ref-proc, 0.0000356 secs] 2022-01-10T10:42:59.664+0800: 1.174: [Unloading, 0.0004159 secs], 0.0018676 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-10T10:42:59.666+0800: 1.175: [GC cleanup 379M->379M(512M), 0.0002800 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 garbage-first heap   total 524288K, used 387501K [0x00000000e0000000, 0x00000000e0101000, 0x0000000100000000)
  region size 1024K, 16 young (16384K), 2 survivors (2048K)
 Metaspace       used 2615K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

为了节省空间，这里只截取部分日志，完整日志有2900多行

4.3.1 年轻代模式转移暂停（Evacuation Pause）

  当年轻代空间用满后，应用线程会被暂停，年轻代内存块中的存活对象被拷贝到存活区。 如果还没有存活区，则任意选择一部分空闲的内存块作为存活区。 拷贝的过程称为转移(Evacuation)，这和前面介绍的其他年轻代收集器是一样的工作原理。 转移暂停的日志信息很长，为简单起见，我们去除了一些不重要的信息.。在并发阶段之后我们会进行详细的讲解。 此外，由于日志记录很多，所以并行阶段和“其他”阶段的日志将拆分为多个部分来进行讲解。

我们从GC日志中抽取部分关键信息

2022-01-10T10:42:58.694+0800: 0.203: 
[GC pause (G1 Evacuation Pause) (young), 0.0023921 secs]
   [Parallel Time: 2.0 ms, GC Workers: 4]
      ...... worker线程的详情，下面单独讲解
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.4 ms]
      ...... 其他琐碎任务，下面单独讲解
   [Eden: 25.0M(25.0M)->0.0B(21.0M) Survivors: 0.0B->4096.0K Heap: 29.2M(512.0M)->10.4M(512.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

分析一下日志：

  1. [GC pause (G1 Evacuation Pause) (young), 0.0023921 secs] – G1转移暂停，纯年轻代模式，只清理年轻代空间。这次暂停在JVM启动之后 203 ms 开始，持续的系统时间为0.0023921 秒 ，也就是 2.4ms 。
  2. [Parallel Time: 2.0 ms, GC Workers: 4] – 表明后面的活动由4个 Worker 线程并行执行，消耗时间为2.0毫秒(real time)，worker 是一种模式，类似于一个老板指挥多个工人干活。
  3. [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] – 释放用于管理并行活动的内部数据，一般都接近于零。这个过程是串行执行的。
  4. [Clear CT: 0.0 ms] – 清理其他部分数据，也是非常快的，如非必要基本上等于零。也是串行执行的过程。
  5. [Other: 0.4 ms] – 其他活动消耗的时间，其中大部分是并行执行的。
  6. [Eden: 25.0M(25.0M)->0.0B(21.0M) – 暂停之前Eden 区的使用量/总容量和暂停之后Eden 区的使用量/总容量
  7. Survivors: 0.0B -> 4096.0K – GC暂停前后，存活区的使用量。
  8. Heap: 29.2M(512.0M)->10.4M(512.0M)] – 暂停前整个堆内存的使用量与总容量，暂停后整个堆内存的使用量与总容量
  9. [Times: user=0.00 sys=0.00, real=0.00 secs] – GC事件的持续时间。

  再来看看上面省略的worker线程的日志，最繁重的GC任务由多个专用的 worker 线程来执行。

[Parallel Time: 2.0 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 202.8, Avg: 202.8, Max: 202.9, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.2, Avg: 0.4, Max: 0.9, Diff: 0.8, Sum: 1.5]
      [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.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.8, Avg: 1.3, Max: 1.5, Diff: 0.7, Sum: 5.1]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.7]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 1.8, Avg: 1.9, Max: 1.9, Diff: 0.2, Sum: 7.5]
      [GC Worker End (ms): Min: 204.6, Avg: 204.7, Max: 204.8, Diff: 0.2]

Worker线程的日志信息解读：

  1. [Parallel Time: 2.0 ms, GC Workers: 4] – 前面介绍过，这表明下列活动由4个线程并行执行，消耗的时间为2.0毫秒(real time)。
  2. GC Worker Start (ms) – GC的worker线程开始启动时，相对于 pause 开始时间的毫秒间隔。如果 Min 和 Max 差别很大，则表明本机其他进程所使用的线程数量过多，挤占了GC的可用 CPU时间。
  3. Ext Root Scanning (ms) – 用了多长时间来扫描堆外内存(non-heap)的 GC ROOT，如 classloaders，JNI引用，JVM系统ROOT等。后面显示了运行时间，“Sum” 指的是CPU时间。
  4. Update RS ， Processed Buffers ， Scan RS 这三部分也是类似的， RS 是Remembered Set 的缩写，可以参考前面。
  5. Code Root Scanning (ms) – 扫描实际代码中的 root 用了多长时间：例如线程栈中的局部变量。
  6. Object Copy (ms) – 用了多长时间来拷贝回收集中的存活对象。
  7. Termination (ms) – GC的worker线程用了多长时间来确保自身可以安全地停止，在这段时间内什么也不做，完成后GC线程就终止运行了，所以叫终止等待时间。
  8. Termination Attempts – GC的worker 线程尝试多少次 try 和 teminate。如果worker发现还有一些任务没处理完，则这一次尝试就是失败的，暂时还不能终止。
  9. GC Worker Other (ms) – 其他的小任务， 因为时间很短，在GC日志将他们归结在一起。
  10. GC Worker Total (ms) – GC的worker 线程工作时间总计。
  11. [GC Worker End (ms) – GC的worker 线程完成作业时刻，相对于此次GC暂停开始时间的毫秒数。通常来说这部分数字应该大致相等，否则就说明有太多的线程被挂起，很可能是因为“坏邻居效应(noisy neighbor)" 所导致的。

此外，在转移暂停期间,还有一些琐碎的小任务。

[Other: 0.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]

其他琐碎任务，这里只介绍其中的一部分：

  1. [Other: 0.4 ms] – 其他活动消耗的时间，其中很多是并行执行的。
  2. Choose CSet - 选择CSet消耗的时间; CSet 是 Collection Set 的缩写。
  3. [Ref Proc: 0.2 ms] – 处理非强引用(non-strong)的时间：进行清理或者决定是否需要清理。
  4. [Ref Enq: 0.0 ms] – 用来将剩下的 non-strong 引用排列到合适的ReferenceQueue 中。
  5. Humongous Register ， Humongous Reclaim 大对象相关的部分。后面进行介绍。
  6. [Free CSet: 0.0 ms] – 将回收集中被释放的小堆归还所消耗的时间，以便他们能用来分配新的对象。

此次 young GC对应的示意图如下所示:


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

4.3.2 Concurrent Marking(并发标记)

  G1 GC的很多概念建立在CMS的基础上，所以下面的内容需要对CMS有一定的理解。G1并发标记的过程与CMS基本上是一样的。G1的并发标记通过 Snapshot-At-The-Beginning(起始快照) 的方式，在标记阶段开始时记下所有的存活对象。即使在标记的同时又有一些变成了垃圾。通过对象的存活信息，可以构建出每个小堆块的存活状态，以便回收集能高效地进行选择。 这些信息在接下来的阶段会用来执行老年代区域的垃圾收集。

有两种情况是可以完全并发执行的

  • 一、如果在标记阶段确定某个小堆块中没有存活对象，只包含垃圾；
  • 二、在STW转移暂停期间，同时包含垃圾和存活对象的老年代小堆块。

  当堆内存的总体使用比例达到一定数值，就会触发并发标记。这个默认比例是 45% ，但也可以通过JVM参数 InitiatingHeapOccupancyPercent 来设置。和CMS一样，G1的并发标记也是由多个阶段组成， 其中一些阶段是完全并发的，还有一些阶段则会暂停应用线程。

4.3.2.1 阶段 1: Initial Mark(初始标记)

  此阶段标记所有从GC根对象直接可达的对象。在CMS中需要一次STW暂停，但G1里面通常是在转移暂停的同时处理这些事情，所以它的开销是很小的。
  可以在 Evacuation Pause 日志中的第一行看到(initial-mark)暂停，类似这样：

2022-01-10T10:42:58.694+0800: 0.203: [GC pause (G1 Evacuation Pause) (young), 0.0023921 secs]

这里引发GC的原因是Evacuation Pause，表示标记可达对象产生的暂停，也可能是其他原因，例如： to-space exhausted，或者默认GC原因等等。

4.3.2.2 阶段 2: Root Region Scan(Root区扫描)

  此阶段标记所有从 “根区域” 可达的存活对象。根区域包括：非空的区域，以及在标记过程中不得不收集的区域。

  因为在并发标记的过程中迁移对象会造成很多麻烦，所以此阶段必须在下一次转移暂停之前完成。如果必须启动转移暂停，则会先要求根区域扫描中止，等它完成才能继续扫描。在当前版本的实现中，根区域是存活的小堆块：包括下一次转移暂停中肯定会被清理的那部分年轻代小堆块。

对应的日志：

2022-01-10T10:42:59.662+0800: 1.171: [GC concurrent-root-region-scan-start]
2022-01-10T10:42:59.662+0800: 1.171: [GC concurrent-root-region-scan-end, 0.0000776 secs]

4.3.2.3 阶段 3: Concurrent Mark(并发标记)

  此阶段和CMS的并发标记阶段非常类似：只遍历对象图，并在一个特殊的位图中标记能访问到的对象。
  为了确保标记开始时的快照准确性，所有应用线程并发对对象图执行引用更新，G1 要求放弃前面阶段为了标记目的而引用的过时引用。

对应的日志:

2022-01-10T10:42:59.662+0800: 1.171: [GC concurrent-mark-start]
2022-01-10T10:42:59.664+0800: 1.173: [GC concurrent-mark-end, 0.0019498 secs]

4.3.2.4 阶段 4: Remark(再次标记)

  和CMS类似，这是一次STW停顿(因为不是并发的阶段)，以完成标记过程。 G1收集器会短暂地停止应用线程，停止并发更新信息的写入，处理其中的少量信息，并标记所有在并发标 记开始时未被标记的存活对象。 这一阶段也执行某些额外的清理，如引用处理或者类卸载(class unloading)。

对应的日志:

2022-01-10T10:42:59.664+0800: 1.173: 
[GC remark 2022-01-10T10:42:59.664+0800: 1.173: [Finalize Marking, 0.0000447 secs]
 2022-01-10T10:42:59.664+0800: 1.174: [GC ref-proc, 0.0000356 secs]
 2022-01-10T10:42:59.664+0800: 1.174: [Unloading, 0.0004159 secs], 0.0018676 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

4.3.2.5 阶段 5: Cleanup(清理)

  最后这个清理阶段为即将到来的转移阶段做准备，统计小堆块中所有存活的对象，并将小堆块进行排序，以提升GC的效率。此阶段也为下一次标记执行必需的所有整理工作(house-keeping activities)：维护并发标记的内部状态。 所有不包含存活对象的小堆块在此阶段都被回收了。有一部分任务是并发的：例如空堆区的回收，还有大部分的存活率计算。此阶段也需要一个短暂的STW暂停，才能不受应用线程的影响并完成作业。

这种STW停顿的对应的日志如下：

2022-01-10T10:42:59.666+0800: 1.175: [GC cleanup 379M->379M(512M), 0.0002800 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

如果发现某些小堆块中只包含垃圾，则日志格式可能会有点不同

2022-01-10T10:42:58.906+0800: 0.416: [GC cleanup 369M->368M(512M), 0.0002913 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-10T10:42:58.907+0800: 0.416: [GC concurrent-cleanup-start]
2022-01-10T10:42:58.907+0800: 0.416: [GC concurrent-cleanup-end, 0.0000089 secs]

如果没有看到对应的GC日志，可以多跑几遍试试。毕竟GC和内存分配属于运行时动态的，每次运行都可能有些不同。

标记周期一般只在碰到region中一个存活对象都没有的时候，才会顺手处理一把，大多数情况下都不释放内存。示意图如下所示:


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

4.3.3 转移暂停: 混合模式（Evacuation Pause (mixed)）

  并发标记完成之后，G1将执行一次混合收集(mixed collection)，不只清理年轻代，还将一部分老年代区域也加入到 collection set 中。 混合模式的转移暂停(Evacuation pause)不一定紧跟并发标记阶段。在并发标记与混合转移暂停之间，很可能会存在多次 young 模式的转移暂停。

混合模式就是指这次GC事件混合着处理年轻代和老年代的region。这也是G1等增量垃圾收集器的特色。而ZGC等最新的垃圾收集器则不使用分代算法。 当然，以后可能还是会实现分代的，毕竟分代之后性能还会有提升。

混合模式下的日志，和纯年轻代模式相比还是有不同

2022-01-10T10:42:58.929+0800: 0.438: [GC pause (G1 Evacuation Pause) (mixed), 0.0023414 secs]
   [Parallel Time: 2.0 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 438.5, Avg: 438.5, Max: 438.5, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.5]
      // 这里=====
      [Update RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.7]
         [Processed Buffers: Min: 0, Avg: 2.8, Max: 4, Diff: 4, 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: 1.7, Avg: 1.7, Max: 1.7, Diff: 0.0, Sum: 6.7]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 2.0, Avg: 2.0, Max: 2.0, Diff: 0.0, Sum: 8.1]
      [GC Worker End (ms): Min: 440.6, Avg: 440.6, Max: 440.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 16.0M(16.0M)->0.0B(21.0M) Survivors: 9216.0K->4096.0K Heap: 393.9M(512.0M)->331.6M(512.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

简单解读（部分概念和名称，可以参考上面，这里介绍不同的）：

  1. [Update RS (ms) – 因为 Remembered Sets 是并发处理的，必须确保在实际的垃圾收集之前，缓冲区中的 card 得到处理。如果card数量很多，则GC并发线程的负载可能就会很高。可能的原因是修改的字段过多，或者CPU资源受限。
  2. Processed Buffers – 各个 worker 线程处理了多少个本地缓冲区(local buffer)。
  3. Scan RS (ms) – 用了多长时间扫描来自RSet的引用。
  4. [Clear CT: 0.0 ms] – 清理 card table 中 cards 的时间。清理工作只是简单地删除“脏”状态，此状态用来标识一个字段是否被更新的，供Remembered Sets使用。
  5. [Redirty Cards: 0.0 ms] – 将 card table 中适当的位置标记为 dirty 所花费的时间。"适当的位置"是由GC本身执行的堆内存改变所决定的，例如引用排队等。

4.3.4 Full GC (Allocation Failure)

  G1是一款自适应的增量垃圾收集器。一般来说，只有在内存严重不足的情况下才会发生Full GC。 比如堆空间不足或者to-space空间不足。 在前面的示例程序基础上，增加缓存对象的数量，即可模拟Full GC。

日志如下：

2022-01-10T10:42:59.552+0800: 1.061: [Full GC (Allocation Failure)  419M->349M(512M), 0.0313367 secs]
   [Eden: 0.0B(25.0M)->0.0B(25.0M) 
   Survivors: 0.0B->0.0B Heap: 419.6M(512.0M)->349.3M(512.0M)], 
   [Metaspace: 2608K->2608K(1056768K)]
 [Times: user=0.03 sys=0.00, real=0.03 secs]

因为我们的堆内存空间很小，存活对象的数量也不多，所以这里看到的Full GC暂停时间很短。

5. GC选择的经验总结


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

  为了简洁我们省略了很多实现细节， 例如如何处理巨无霸对象(humongous objects)。 综合来看，G1是JDK11之前HotSpot JVM中最先进的准产品级(production-ready)垃圾收集器。重要的是， HotSpot 工程师的主要精力都放在不断改进G1上面。在更新的JDK版本中，将会带来更多强大的功能和优化。

  可以看到，G1作为CMS的代替者出现，解决了 CMS 中的各种疑难问题，包括暂停时间的可预测性，并终结了堆内存的碎片化。对单业务延迟非常敏感的系统来说，如果CPU资源不受限制，那么G1可以说是 HotSpot 中最好的选择，特别是在最新版本的JVM中。当然这种降低延迟的优化也不是没有代价的：由于额外的写屏障和守护线程，G1的开销会更大。如果系统属于吞吐量优先型的，又或者CPU持续占用100%，而又不在乎单次GC的暂停时间，那么CMS是更好的选择。

总之: G1适合大内存，需要较低延迟的场景。

选择正确的GC算法，唯一可行的方式就是去尝试，并找出不合理的地方，一般性的指导原则：

  • 如果系统考虑吞吐优先，CPU资源都用来最大程度处理业务，用Parallel GC；
  • 如果系统考虑低延迟有限，每次GC时间尽量短，用CMS GC；
  • 如果系统内存堆较大，同时希望整体来看平均GC时间可控，使用G1 GC。

对于内存大小的考量：

  • 一般4G以上，算是比较大，用G1的性价比较高。
  • 一般超过8G，比如16G-64G内存，非常推荐使用G1 GC。

最后讨论一个很多开发者经常忽视的问题，也是面试大厂常问的问题：

JDK8的默认GC是什么？

很多人或觉得是CMS，甚至G1，其实都不是。
看过这篇文章就知道答案是并行GC

注意，G1成为JDK9以后版本的默认GC策略，同时， ParNew + SerialOld 这种组合不被支持。



欢迎一键三连~



有问题请留言，大家一起探讨学习



----------------------Talk is cheap, show me the code-----------------------



举报

相关推荐

jvm(9) -- cms收集器、G1收集器

jvmjava老年代垃圾收集虚拟化云计算

JVM 垃圾收集器之G1 收集的具体步骤

jvm

深入理解 Java G1 垃圾收集器

技术原理JVM和并发编程面试精选jvm

G1收集器

日记本面试精选JVM一些收藏

Serial,Parallel,CMS,G1四大GC收集器特点小结

JVMG1垃圾回收器HarmonyOS后端开发

垃圾收集器ParNew&CMS&G1详解

java开发语言后端

JVM性能优化（三）G1垃圾收集器

jvm垃圾收集器GCEasy老年代垃圾回收OpenStack云计算

JVM专题之G1垃圾收集器下

kubernetes

CMS垃圾收集器

JVM算法实现java服务端云平台云计算

CMS垃圾收集器及日志详解

javajvmcmsg1并发清除Html/CSS前端开发
0 条评论