文档建议反馈控制台
首页
学习
活动
专区
圈层
工具
MCP广场
文章/答案/技术大牛
发布
首页
学习
活动
专区
圈层
工具
MCP广场
返回腾讯云官网
社区首页 >专栏 >Java GC垃圾收集器的具体实现与日志案例分析(串行、并行、CMS、G1)

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

作者头像
砖业洋__
发布于 2023-05-06 20:41:40
发布于 2023-05-06 20:41:40
76200
代码可运行
举报
文章被收录于专栏：博客迁移同步博客迁移同步
运行总次数：0
代码可运行

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

1. 串行GC（Serial GC）

1.1 串行垃圾收集器介绍

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

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

代码语言：javascript
代码运行次数：0
运行
复制
-XX:+UseSerialGC

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

1.2 串行GC日志解读

代码语言：javascript
代码运行次数：0
运行
复制
java -XX:+UseSerialGC -Xms512m -Xmx512m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc.demo.log  GCLogAnalysis

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

代码语言：javascript
代码运行次数：0
运行
复制
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日志分析

代码语言：javascript
代码运行次数：0
运行
复制
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事件的示意图如下所示:

1.2.2 Full GC日志分析

代码语言：javascript
代码运行次数：0
运行
复制
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事件的内存变化情况，可以表示为下面的示意图

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

2.并行GC（Parallel GC）

2.1 并行垃圾收集器介绍

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

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

代码语言：javascript
代码运行次数：0
运行
复制
 -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日志解读

代码语言：javascript
代码运行次数：0
运行
复制
java -XX:+UseParallelGC -Xms512m -Xmx512m -Xloggc:gc.demo.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis

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

代码语言：javascript
代码运行次数：0
运行
复制
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日志分析

代码语言：javascript
代码运行次数：0
运行
复制
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日志分析

代码语言：javascript
代码运行次数：0
运行
复制
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垃圾收集器：

代码语言：javascript
代码运行次数：0
运行
复制
-XX:+UseConcMarkSweepGC

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

3.2 CMS GC日志解读

代码语言：javascript
代码运行次数：0
运行
复制
java -XX:+UseConcMarkSweepGC -Xms512m -Xmx512m 
-Xloggc:gc.demo.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis

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

代码语言：javascript
代码运行次数：0
运行
复制
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日志分析

代码语言：javascript
代码运行次数：0
运行
复制
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对老年代进行垃圾收集时每个阶段都会有自己的日志。为了简洁，我们将对这部分日志按照阶段依次介绍

代码语言：javascript
代码运行次数：0
运行
复制
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嘛，再去收集年轻代估计也没什么效果】。

先看这个阶段的日志：

代码语言：javascript
代码运行次数：0
运行
复制
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” 找到的根对象开始算起。   所谓“并发标记”阶段，就是与应用程序同时运行，不用暂停的阶段。 请注意，并非所有老年代中存活的对象都在此阶段被标记，因为在标记过程中对象的引用关系还在发生变化。

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

先看这个阶段的日志：

代码语言：javascript
代码运行次数：0
运行
复制
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）

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

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

看看本阶段的日志：

代码语言：javascript
代码运行次数：0
运行
复制
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阶段之前尽可能地多做一些工作。本阶段的具体时间取决于多种因素，因为它循环做同样的事情，直到满足某个退出条件( 如迭代次数，有用工作量， 消耗的系统时间等等)。

看看本阶段的日志：

代码语言：javascript
代码运行次数：0
运行
复制
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 事件。

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

代码语言：javascript
代码运行次数：0
运行
复制
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在此阶段删除不再使用的对象，并回收他们占用的内存空间。

看看本阶段日志

代码语言：javascript
代码运行次数：0
运行
复制
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循环做准备。

看看本阶段日志：

代码语言：javascript
代码运行次数：0
运行
复制
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区拼在一起那就是老年代，如下图所示：

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

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

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

代码语言：javascript
代码运行次数：0
运行
复制
-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日志解读和分析

代码语言：javascript
代码运行次数：0
运行
复制
java -XX:+UseG1GC -Xms512m -Xmx512m 
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc.demo.log  GCLogAnalysis

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

代码语言：javascript
代码运行次数：0
运行
复制
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日志中抽取部分关键信息

代码语言：javascript
代码运行次数：0
运行
复制
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 线程来执行。

代码语言：javascript
代码运行次数：0
运行
复制
[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)" 所导致的。

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

代码语言：javascript
代码运行次数：0
运行
复制
   [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对应的示意图如下所示:

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)暂停，类似这样：

代码语言：javascript
代码运行次数：0
运行
复制
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区扫描)

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

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

对应的日志：

代码语言：javascript
代码运行次数：0
运行
复制
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 要求放弃前面阶段为了标记目的而引用的过时引用。

对应的日志:

代码语言：javascript
代码运行次数：0
运行
复制
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)。

对应的日志:

代码语言：javascript
代码运行次数：0
运行
复制
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停顿的对应的日志如下：

代码语言：javascript
代码运行次数：0
运行
复制
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]

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

代码语言：javascript
代码运行次数：0
运行
复制
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中一个存活对象都没有的时候，才会顺手处理一把，大多数情况下都不释放内存。示意图如下所示:

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

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

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

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

代码语言：javascript
代码运行次数：0
运行
复制
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。

日志如下：

代码语言：javascript
代码运行次数：0
运行
复制
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选择的经验总结

  为了简洁我们省略了很多实现细节， 例如如何处理巨无霸对象(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 这种组合不被支持。

本文参与 腾讯云自媒体同步曝光计划，分享自作者个人站点/博客。
原始发表：2022-05-26，如有侵权请联系 cloudcommunity@tencent.com 删除
java
cms
gc
内存
日志

本文分享自 作者个人站点/博客 前往查看

如有侵权，请联系 cloudcommunity@tencent.com 删除。

本文参与 腾讯云自媒体同步曝光计划  ，欢迎热爱写作的你一起参与！

java
cms
gc
内存
日志
评论
登录后参与评论
0 条评论
热度
最新
登录 后参与评论
推荐阅读
目录
  • 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日志分析
  • 4. G1垃圾收集器
    • 4.1 G1垃圾收集器介绍
    • 4.2 G1 GC常用参数设置
  • 4.3 G1日志解读和分析
    • 4.3.1 年轻代模式转移暂停（Evacuation Pause）
    • 4.3.2 Concurrent Marking(并发标记)
    • 4.3.3 转移暂停: 混合模式（Evacuation Pause (mixed)）
    • 4.3.4 Full GC (Allocation Failure)
  • 5. GC选择的经验总结
领券

腾讯云开发者

扫码关注腾讯云开发者

扫码关注腾讯云开发者

领取腾讯云代金券

热门产品

热门推荐

更多推荐

Copyright © 2013 - 2025 Tencent Cloud. All Rights Reserved. 腾讯云 版权所有 

深圳市腾讯计算机系统有限公司 ICP备案/许可证号：粤B2-20090059 深公网安备号 44030502008569

腾讯云计算（北京）有限责任公司 京ICP证150476号 |  京ICP备11018762号 | 京公网安备号11010802020287

问题归档专栏文章快讯文章归档关键词归档开发者手册归档开发者手册 Section 归档

Copyright © 2013 - 2025 Tencent Cloud.

All Rights Reserved. 腾讯云 版权所有

登录 后参与评论