19 KiB
因收到Google相关通知，网站将会择期关闭。相关通知内容
19 GC 日志解读与分析（实例分析中篇）
CMS 的 GC 日志解读
CMS 也可称为“并发标记清除垃圾收集器”。其设计目标是避免在老年代 GC 时出现长时间的卡顿。默认情况下，CMS 使用的并发线程数等于 CPU 内核数的 1/4。
通过以下选项来指定 CMS 垃圾收集器：
-XX:+UseConcMarkSweepGC
如果 CPU 资源受限，CMS 的吞吐量会比并行 GC 差一些。示例：
请注意命令行启动时没有换行，此处是方便大家阅读。
java -XX:+UseConcMarkSweepGC -Xms512m -Xmx512m -Xloggc：gc.demo.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps demo.jvm0204.GCLogAnalysis
和前面分析的串行 GC/并行 GC 一样，我们将程序启动起来，看看 CMS 算法生成的 GC 日志是什么样子：
Java HotSpot(TM) 64-Bit Server VM (25.162-b12) 。。。 Memory： 4k page，physical 16777216k(1168104k free)
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
2019-12-22T00:00:31.865-0800: 1.067： [GC (Allocation Failure) 2019-12-22T00:00:31.865-0800: 1.067： [ParNew： 136418K->17311K(157248K)，0.0233955 secs] 442378K->360181K(506816K)，0.0234719 secs] [Times: user=0.10 sys=0.02，real=0.02 secs]
2019-12-22T00:00:31.889-0800: 1.091： [GC (CMS Initial Mark) [1 CMS-initial-mark: 342870K(349568K)] 363883K(506816K)，0.0002262 secs] [Times: user=0.00 sys=0.00,real=0.00 secs] 2019-12-22T00:00:31.889-0800: 1.091： [CMS-concurrent-mark-start] 2019-12-22T00:00:31.890-0800: 1.092： [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00,real=0.01 secs] 2019-12-22T00:00:31.891-0800: 1.092： [CMS-concurrent-preclean-start] 2019-12-22T00:00:31.891-0800: 1.093： [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00,real=0.00 secs] 2019-12-22T00:00:31.891-0800: 1.093： [CMS-concurrent-abortable-preclean-start] 2019-12-22T00:00:31.891-0800: 1.093： [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs] 2019-12-22T00:00:31.891-0800: 1.093： [GC (CMS Final Remark) [YG occupancy: 26095 K (157248 K)] 2019-12-22T00:00:31.891-0800: 1.093： [Rescan (parallel) ，0.0002680 secs] 2019-12-22T00:00:31.891-0800: 1.093： [weak refs processing，0.0000230 secs] 2019-12-22T00:00:31.891-0800: 1.093： [class unloading，0.0004008 secs] 2019-12-22T00:00:31.892-0800: 1.094： [scrub symbol table，0.0006072 secs] 2019-12-22T00:00:31.893-0800: 1.095： [scrub string table，0.0001769 secs] [1 CMS-remark: 342870K(349568K)] 368965K(506816K)，0.0015928 secs] [Times: user=0.01 sys=0.00,real=0.00 secs] 2019-12-22T00:00:31.893-0800: 1.095： [CMS-concurrent-sweep-start] 2019-12-22T00:00:31.893-0800: 1.095： [CMS-concurrent-sweep： 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs] 2019-12-22T00:00:31.893-0800: 1.095： [CMS-concurrent-reset-start] 2019-12-22T00:00:31.894-0800: 1.096： [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]
这只是摘录的一部分 GC 日志。比起串行 GC/并行 GC 来说，CMS 的日志信息复杂了很多，这一方面是因为 CMS 拥有更加精细的 GC 步骤，另一方面 GC 日志很详细就意味着暴露出来的信息也就更全面细致。
Minor GC 日志分析
最前面的几行日志是清理年轻代的 Minor GC 事件：
2019-12-22T00:00:31.865-0800: 1.067： [GC (Allocation Failure) 2019-12-22T00:00:31.865-0800: 1.067： [ParNew： 136418K->17311K(157248K)，0.0233955 secs] 442378K->360181K(506816K)，0.0234719 secs] [Times: user=0.10 sys=0.02，real=0.02 secs]
我们一起来解读：
2019-12-22T00:00:31.865-0800: 1.067：GC 事件开始的时间。 GC (Allocation Failure)：用来区分 Minor GC 还是 Full GC 的标志。GC 表明这是一次“小型 GC”；Allocation Failure 表示触发 GC 的原因。本次 GC 事件，是由于年轻代可用空间不足，新对象的内存分配失败引起的。 [ParNew： 136418K->17311K(157248K)，0.0233955 secs]：其中 ParNew 是垃圾收集器的名称，对应的就是前面日志中打印的 -XX:+UseParNewGC 这个命令行标志。表示在年轻代中使用的“并行的标记—复制（mark-copy）”垃圾收集器，专门设计了用来配合 CMS 垃圾收集器，因为 CMS 只负责回收老年代。后面的数字表示 GC 前后的年轻代使用量变化，以及年轻代的总大小。0.0233955 secs 是消耗的时间。 442378K->360181K(506816K)，0.0234719 secs：表示 GC 前后堆内存的使用量变化，以及堆内存空间的大小。消耗的时间是 0.0234719 secs，和前面的 ParNew 部分的时间基本上一样。 [Times: user=0.10 sys=0.02，real=0.02 secs]：GC 事件的持续时间。user 是 GC 线程所消耗的总 CPU 时间；sys 是操作系统调用和系统等待事件消耗的时间；应用程序实际暂停的时间 real ~= (user + sys)/GC线程数。我的机器是 4 核 8 线程，而这里是 6 倍的比例，因为总有一定比例的处理过程是不能并行执行的。
进一步计算和分析可以得知，在 GC 之前，年轻代使用量为 136418K/157248K=86%。堆内存的使用率为 442378K/506816K=87%。稍微估算一下，老年代的使用率为：(442378K-136418K)/(506816K-157248K)=(305960K /349568K)=87%。这里是凑巧了，GC 之前 3 个比例都在 87% 左右。
GC 之后呢？年轻代使用量为 17311K ~= 17%，下降了 119107K。堆内存使用量为 360181K ~= 71%，只下降了 82197K。两个下降值相减，就是年轻代提升到老年代的内存量：119107-82197=36910K。
那么老年代空间有多大？老年代使用量是多少？正在阅读的同学，请开动脑筋，用这些数字算一下。
此次 GC 的内存变化示意图为：
哇塞，这个数字不得了，老年代使用量 98% 了，非常高了。后面紧跟着就是一条 Full GC 的日志，请接着往下看。
Full GC 日志分析
实际上这次截取的年轻代 GC 日志和 FullGC 日志是紧连着的，我们从间隔时间也能大致看出来，1.067 + 0.02secs ~ 1.091。
CMS 的日志是一种完全不同的格式，并且很长，因为 CMS 对老年代进行垃圾收集时每个阶段都会有自己的日志。为了简洁，我们将对这部分日志按照阶段依次介绍。
首先来看 CMS 这次 FullGC 的日志：
2019-12-22T00:00:31.889-0800: 1.091: [GC (CMS Initial Mark) [1 CMS-initial-mark: 342870K(349568K)] 363883K(506816K)，0.0002262 secs] [Times: user=0.00 sys=0.00,real=0.00 secs] 2019-12-22T00:00:31.889-0800: 1.091: [CMS-concurrent-mark-start] 2019-12-22T00:00:31.890-0800: 1.092: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00,real=0.01 secs] 2019-12-22T00:00:31.891-0800: 1.092: [CMS-concurrent-preclean-start] 2019-12-22T00:00:31.891-0800: 1.093: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00,real=0.00 secs] 2019-12-22T00:00:31.891-0800: 1.093: [CMS-concurrent-abortable-preclean-start] 2019-12-22T00:00:31.891-0800: 1.093: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs] 2019-12-22T00:00:31.891-0800: 1.093: [GC (CMS Final Remark) [YG occupancy: 26095 K (157248 K)] 2019-12-22T00:00:31.891-0800: 1.093: [Rescan (parallel) ，0.0002680 secs] 2019-12-22T00:00:31.891-0800: 1.093: [weak refs processing，0.0000230 secs] 2019-12-22T00:00:31.891-0800: 1.093: [class unloading，0.0004008 secs] 2019-12-22T00:00:31.892-0800: 1.094: [scrub symbol table，0.0006072 secs] 2019-12-22T00:00:31.893-0800: 1.095: [scrub string table，0.0001769 secs] [1 CMS-remark: 342870K(349568K)] 368965K(506816K)，0.0015928 secs] [Times: user=0.01 sys=0.00,real=0.00 secs] 2019-12-22T00:00:31.893-0800: 1.095: [CMS-concurrent-sweep-start] 2019-12-22T00:00:31.893-0800: 1.095: [CMS-concurrent-sweep： 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs] 2019-12-22T00:00:31.893-0800: 1.095: [CMS-concurrent-reset-start] 2019-12-22T00:00:31.894-0800: 1.096: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]
在实际运行中，CMS 在进行老年代的并发垃圾回收时，可能会伴随着多次年轻代的 Minor GC（想想是为什么）。在这种情况下，Full GC 的日志中可能会掺杂着多次 Minor GC 事件。
阶段 1：Initial Mark（初始标记）
前面章节提到过，这个阶段伴随着 STW 暂停。初始标记的目标是标记所有的根对象，包括 GC ROOT 直接引用的对象，以及被年轻代中所有存活对象所引用的对象。后面这部分也非常重要，因为老年代是独立进行回收的。
先看这个阶段的日志：
2019-12-22T00:00:31.889-0800: 1.091: [GC (CMS Initial Mark) [1 CMS-initial-mark: 342870K(349568K)] 363883K(506816K), 0.0002262 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]
让我们简单解读一下：
2019-12-22T00:00:31.889-0800: 1.091:：时间部分就不讲了，参考前面的解读。后面的其他阶段也一样，不再进行重复介绍。 CMS Initial Mark：这个阶段的名称为“Initial Mark”，会标记所有的 GC Root。 [1 CMS-initial-mark: 342870K(349568K)]：这部分数字表示老年代的使用量，以及老年代的空间大小。 363883K(506816K)，0.0002262 secs：当前堆内存的使用量，以及可用堆的大小、消耗的时间。可以看出这个时间非常短，只有 0.2 毫秒左右，因为要标记的这些 Roo 数量很少。 [Times: user=0.00 sys=0.00,real=0.00 secs]：初始标记事件暂停的时间，可以看到可以忽略不计。
阶段 2：Concurrent Mark（并发标记）
在并发标记阶段，CMS 从前一阶段“Initial Mark”找到的 ROOT 开始算起，遍历老年代并标记所有的存活对象。
看看这个阶段的 GC 日志：
2019-12-22T00:00:31.889-0800: 1.091: [CMS-concurrent-mark-start] 2019-12-22T00:00:31.890-0800: 1.092: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00,real=0.01 secs]
简单解读一下：
CMS-concurrent-mark：指明了是 CMS 垃圾收集器所处的阶段为并发标记（“Concurrent Mark”）。 0.001/0.001 secs：此阶段的持续时间，分别是 GC 线程消耗的时间和实际消耗的时间。 [Times: user=0.00 sys=0.00,real=0.01 secs]：Times 对并发阶段来说这些时间并没多少意义，因为是从并发标记开始时刻计算的，而这段时间应用线程也在执行，所以这个时间只是一个大概的值。
阶段 3：Concurrent Preclean（并发预清理）
此阶段同样是与应用线程并发执行的，不需要停止应用线程。
看看并发预清理阶段的 GC 日志：
2019-12-22T00:00:31.891-0800: 1.092: [CMS-concurrent-preclean-start] 2019-12-22T00:00:31.891-0800: 1.093: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]
简单解读：
CMS-concurrent-preclean：表明这是并发预清理阶段的日志，这个阶段会统计前面的并发标记阶段执行过程中发生了改变的对象。 0.001/0.001 secs：此阶段的持续时间，分别是 GC 线程运行时间和实际占用的时间。 [Times: user=0.00 sys=0.00,real=0.00 secs]：Times 这部分对并发阶段来说没多少意义，因为是从开始时间计算的，而这段时间内不仅 GC 线程在执行并发预清理，应用线程也在运行。
阶段 4：Concurrent Abortable Preclean（可取消的并发预清理）
此阶段也不停止应用线程，尝试在会触发 STW 的 Final Remark 阶段开始之前，尽可能地多干一些活。
本阶段的具体时间取决于多种因素，因为它循环做同样的事情，直到满足某一个退出条件（如迭代次数、有用工作量、消耗的系统时间等等）。
看看 GC 日志：
2019-12-22T00:00:31.891-0800: 1.093: [CMS-concurrent-abortable-preclean-start] 2019-12-22T00:00:31.891-0800: 1.093: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]
简单解读：
CMS-concurrent-abortable-preclean：指示此阶段的名称：“Concurrent Abortable Preclean”。 0.000/0.000 secs：此阶段 GC 线程的运行时间和实际占用的时间。从本质上讲，GC 线程试图在执行 STW 暂停之前等待尽可能长的时间。默认条件下，此阶段可以持续最长 5 秒钟的时间。 [Times: user=0.00 sys=0.00,real=0.00 secs]：“Times”这部分对并发阶段来说没多少意义，因为程序在并发阶段中持续运行。
此阶段完成的工作可能对 STW 停顿的时间有较大影响，并且有许多重要的配置选项和失败模式。
阶段 5：Final Remark（最终标记）
最终标记阶段是此次 GC 事件中的第二次（也是最后一次）STW 停顿。
本阶段的目标是完成老年代中所有存活对象的标记。因为之前的预清理阶段是并发执行的，有可能 GC 线程跟不上应用程序的修改速度。所以需要一次 STW 暂停来处理各种复杂的情况。
通常 CMS 会尝试在年轻代尽可能空的情况下执行 final remark 阶段，以免连续触发多次 STW 事件。
这部分的 GC 日志看起来稍微复杂一些：
2019-12-22T00:00:31.891-0800: 1.093: [GC (CMS Final Remark) [YG occupancy: 26095 K (157248 K)] 2019-12-22T00:00:31.891-0800: 1.093: [Rescan (parallel) ，0.0002680 secs] 2019-12-22T00:00:31.891-0800: 1.093: [weak refs processing，0.0000230 secs] 2019-12-22T00:00:31.891-0800: 1.093: [class unloading，0.0004008 secs] 2019-12-22T00:00:31.892-0800: 1.094: [scrub symbol table，0.0006072 secs] 2019-12-22T00:00:31.893-0800: 1.095: [scrub string table，0.0001769 secs] [1 CMS-remark: 342870K(349568K)] 368965K(506816K)，0.0015928 secs] [Times: user=0.01 sys=0.00,real=0.00 secs]
一起来进行解读：
CMS Final Remark：这是此阶段的名称，最终标记阶段，会标记老年代中所有的存活对象，包括此前的并发标记过程中创建/修改的引用。 YG occupancy: 26095 K (157248 K)：当前年轻代的使用量和总容量。 [Rescan (parallel) ，0.0002680 secs]：在程序暂停后进行重新扫描（Rescan），以完成存活对象的标记。这部分是并行执行的，消耗的时间为 0.0002680 秒。 weak refs processing，0.0000230 secs：第一个子阶段，处理弱引用的持续时间。 class unloading，0.0004008 secs：第二个子阶段，卸载不使用的类，以及持续时间。 scrub symbol table，0.0006072 secs：第三个子阶段，清理符号表，即持有 class 级别 metadata 的符号表（symbol tables）。 scrub string table，0.0001769 secs：第四个子阶段， 清理内联字符串对应的 string tables。 [1 CMS-remark: 342870K(349568K)]：此阶段完成后老年代的使用量和总容量。 368965K(506816K)，0.0015928 secs：此阶段完成后，整个堆内存的使用量和总容量。 [Times: user=0.01 sys=0.00,real=0.00 secs]：GC 事件的持续时间。
在这 5 个标记阶段完成后，老年代中的所有存活对象都被标记上了，接下来 JVM 会将所有不使用的对象清除，以回收老年代空间。
阶段 6：Concurrent Sweep（并发清除）
此阶段与应用程序并发执行，不需要 STW 停顿。目的是删除不再使用的对象，并回收他们占用的内存空间。
看看这部分的 GC 日志：
2019-12-22T00:00:31.893-0800: 1.095: [CMS-concurrent-sweep-start] 2019-12-22T00:00:31.893-0800: 1.095: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]
简单解读：
CMS-concurrent-sweep：此阶段的名称，“Concurrent Sweep”，并发清除老年代中所有未被标记的对象、也就是不再使用的对象，以释放内存空间。 0.000/0.000 secs：此阶段的持续时间和实际占用的时间，这是一个四舍五入值，只精确到小数点后 3 位。 [Times: user=0.00 sys=0.00,real=0.00 secs]：“Times”部分对并发阶段来说没有多少意义，因为是从并发标记开始时计算的，而这段时间内不仅是并发标记线程在执行，程序线程也在运行。
阶段 7：Concurrent Reset（并发重置）
此阶段与应用程序线程并发执行，重置 CMS 算法相关的内部数据结构，下一次触发 GC 时就可以直接使用。
对应的日志为：
2019-12-22T00:00:31.893-0800: 1.095: [CMS-concurrent-reset-start] 2019-12-22T00:00:31.894-0800: 1.096: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,real=0.00 secs]
简单解读：
CMS-concurrent-reset：此阶段的名称，“Concurrent Reset”，重置 CMS 算法的内部数据结构，为下一次 GC 循环做准备。 0.000/0.000 secs：此阶段的持续时间和实际占用的时间 [Times: user=0.00 sys=0.00,real=0.00 secs]：“Times”部分对并发阶段来说没多少意义，因为是从并发标记开始时计算的，而这段时间内不仅 GC 线程在运行，程序也在运行。
那么问题来了，CMS 之后老年代内存使用量是多少呢？很抱歉这里分析不了，只能通过后面的 Minor GC 日志来分析了。
例如本次运行，后面的 GC 日志是这样的：
2019-12-22T00:00:31.921-0800: 1.123: [GC (Allocation Failure) 2019-12-22T00:00:31.921-0800: 1.123: [ParNew: 153242K->16777K(157248K), 0.0070050 secs] 445134K->335501K(506816K)， 0.0070758 secs] [Times: user=0.05 sys=0.00,real=0.00 secs]
参照前面年轻代 GC 日志的分析方法，我们推算出来，上面的 CMS Full GC 之后，老年代的使用量应该是：445134K-153242K=291892K，老年代的总容量 506816K-157248K=349568K，所以 Full GC 之后老年代的使用量占比是 291892K/349568K=83%。
这个占比不低。说明什么问题呢？ 一般来说就是分配的内存小了，毕竟我们才指定了 512MB 的最大堆内存。
按照惯例，来一张 GC 前后的内存使用情况示意图：
总之，CMS 垃圾收集器在减少停顿时间上做了很多给力的工作，很大一部分 GC 线程是与应用线程并发运行的，不需要暂停应用线程，这样就可以在一般情况下每次暂停的时候较少。当然，CMS 也有一些缺点，其中最大的问题就是老年代的内存碎片问题，在某些情况下 GC 会有不可预测的暂停时间，特别是堆内存较大的情况下。
透露一个学习 CMS 的诀窍：参考上面各个阶段的示意图，请同学们自己画一遍。
本节的学习到此就结束了，下一节我们继续介绍 G1 日志分析。