GC日志解读与分析
作者：互联网
一、验证GC代码
程序并不复杂，我们指定一个运行时间作为退出条件，时间一到自动退出循环。在 generateGarbage 方法中，我们用了随机数来生成各种类型的数组对象并返回。
在 main 方法中，我们用一个数组来随机存放一部分生成的对象，这样可以模拟让部分对象晋升到老年代。具体的持续运行时间和缓存对象个数，可以自己进行调整。
额外说一句：这个示例除了可以用来进行GC日志分析之外，稍微修改一下，还可以用作其他用途：
比如让缓存的对象变多，在限制堆内存的情况下，就可以模拟 内存溢出 。
增加运行时长，比如加到30分钟或者更长，我们就可以用前面介绍过的 VisualVM 等工具来实时监控和观察。
当然，我们也可以使用全局静态变量来缓存，用来模拟 内存泄漏 ，以及进行堆内存Dump的试验和分析。
加大每次生成的数组的大小，可以用来模拟 大对象/巨无霸对象
import java.util.Random;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.LongAdder;
public class GCLogAnalysis {
private static Random random = new Random();
public static void main(String[] args) {
// 当前毫秒时间戳
long startMillis = System.currentTimeMillis();
// 持续运行毫秒数; 可根据需要进行修改
long timeoutMillis = TimeUnit.SECONDS.toMillis(1);
// 结束时间戳
long endMillis = startMillis + timeoutMillis;
LongAdder counter = new LongAdder();
System.out.println("正在执行...");
// 缓存一部分对象; 进入老年代
int cacheSize = 2000;
Object[] cachedGarbage = new Object[cacheSize];
// 在此时间范围内,持续循环
while (System.currentTimeMillis() < endMillis) {
// 生成垃圾对象
Object garbage = generateGarbage(100*1024);
counter.increment();
int randomIndex = random.nextInt(2 * cacheSize);
if (randomIndex < cacheSize) {
cachedGarbage[randomIndex] = garbage;
}
}
System.out.println("执行结束!共生成对象次数:" + counter.longValue());
}
// 生成对象
private static Object generateGarbage(int max) {
int randomSize = random.nextInt(max);
int type = randomSize % 4;
Object result = null;
switch (type) {
case 0:
result = new int[randomSize];
break;
case 1:
result = new byte[randomSize];
break;
case 2:
result = new double[randomSize];
break;
default:
StringBuilder builder = new StringBuilder();
String randomString = "randomString-Anything";
while (builder.length() < randomSize) {
builder.append(randomString);
builder.append(max);
builder.append(randomSize);
}
result = builder.toString();
break;
}
return result;
}
}
二、GC基础配置
编译和运行上述代码
conglongli@bogon exercise % javac -g GCLogAnalysis.java conglongli@bogon exercise % java GCLogAnalysis 正在执行... 执行结束!共生成对象次数:10648
因为没有指定任何启动参数，所以输出的日志内容也很简单。
1、输出GC日志详情
然后加上启动参数 -XX:+PrintGCDetails ，打印GC日志详情，再次执行示例：
java -XX:+PrintGCDetails GCLogAnalysis
PSYoungGen表示年轻代总空间及使用空间，中括号中的内容是内存地址信息，同时还展示了年轻代中Eden、from、to三个区域的空间大小和使用率；ParOldGen表示老年代，展示了老年代的总空间、已用空间、使用率等；Metaspace表示元空间的相关情况，元空间中used表示已使用空间、capacity表示可用容量、commited表示jvm保证可用大小、reserved表示保留空间；class space表示class所用空间。
2、输出到文件
加上启动参数 -Xloggc:gc.demo.log ， 再次执行。
java -Xloggc:demogc.log -XX:+PrintGCDetails GCLogAnalysis
从JDK8开始，支持使用 %p ， %t 等占位符来指定GC输出文件。分别表示进程pid和启动时间戳。例如: -Xloggc:gc.%p.log ; -Xloggc:gc-%t.log ;在某些情况下，将每次JVM执行的GC日志输出到不同的文件可以方便排查问题。如果业务访问量大，导致GC日志文件太大，可以开启GC日志轮换，分割成多个文件，可以参考：https://blog.gceasy.io/2016/11/15/rotating-gc-log-fifiles 。
输出文件：
指定 -Xloggc: 参数，自动加上了 -XX:+PrintGCTimeStamps 配置。观察GC日志文件可以看到，每一行前面多了一个时间戳（如 0.310: ），表示JVM启动后经过的时间（单位秒）。从GC日志中可以看到，JDK8默认使用的垃圾收集器参数: -XX:+UseParallelGC
3、打印GC事件发生的日期和时间
我们在前面的基础上，加上启动参数 -XX:+PrintGCDateStamps ，再次执行
java -Xloggc:demogc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis
输出内容：
可以看到，加上 -XX:+PrintGCDateStamps 参数之后，GC日志每一行前面，都打印了GC发生时的具体时间。如 2022-05-04T14:09:08.828-0800 ，表示的是： 东8区时间2022年05月04日14:09:08秒.828毫秒。
4、指定堆内存大小
java -Xms512m -Xmx512m -Xloggc:demogc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis
5、指定垃圾回收器
# 使用串行垃圾收集器： -XX:+UseSerialGC -XX:+UseSerialGC # 使用并行垃圾收集器： -XX:+UseParallelGC 和 -XX:+UseParallelGC -XX:+UseParallelOldGC 是等价的, 可以通过GC日志文件中的flags看出来。 -XX:+UseParallelGC -XX:+UseParallelGC -XX:+UseParallelOldGC # 使用CMS垃圾收集器： -XX:+UseConcMarkSweepGC 和 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC 是等价的。 但如果只指定 -XX:+UseParNewGC 参数则老年代GC会 使用SerialGC。使用CMS时，命令行参数中会自动计算出年轻代、老年代的初始值和最大值，以及最大晋升阈值等信息（例如 -XX:MaxNewSize=178958336 -XX:NewSize=178958336 -XX:OldSize=357912576 ）。 -XX:+UseConcMarkSweepGC -XX:+UseConcMarkSweepGC -XX:+UseParNewGC # 使用 G1垃圾收集器： -XX:+UseG1GC 。原则上不能指定G1垃圾收集器的年轻代大小，否则不仅是画蛇添足，更是自废武功了。因为G1的回收方式是小批量划定区块（region）进行，可能一次普通GC中 既有年轻代又有老年代，可能某个区块一会是老年代，一会又变成年轻代了。 -XX:+UseG1GC
如果使用不支持的GC组合，会启动失败，报fatal错误。
6、其他参数与总结
JVM里还有一些GC日志相关的参数， 例如：-XX:+PrintGCApplicationStoppedTime 可以输出每次GC的持续时间和程序暂停时间；-XX:+PrintReferenceGC 输出GC清理了多少引用类型等。
大部分情况下，配置GC参数并不是越多越好。原则上只配置最重要的几个参数即可，其他的都保持默认值，除非你对系统的业务特征有了深入的分析和了解，才需要进行某些细微参数的调整。 毕竟，古语有云：“过早优化是万恶之源”。
需要提醒的是，这些参数是基于JDK8配置的。在JDK9之后的版本中，启动参数有一些变化，继续使用原来的参数配置可能会在启动时报错。不过也不用担心，如果碰到，一般都可以从错误提示中找到对应的处置措施和解决方案。例如JDK11版本中打印info级别GC日志的启动脚本：
# JDK11环境，输出info级别的GC日志 java -Xms512m -Xmx512m -Xlog:gc*=info:file=gc.log:time:filecount=0 demo.jvm0204.GCLogAnalysis
从JDK9开始，可以使用命令 java -Xlog:help 来查看当前JVM支持的日志参数。
三、GC事件类型
一般来说，垃圾收集事件(Garbage Collection events)可以分为三种类型：Minor GC(小型GC)、Major GC(大型GC)、Full GC(完全GC)。
虽然 Minor GC ， Major GC 和 Full GC 这几个词汇到处都在用，但官方并没有给出标准的定义。这些术语出现在官方的各种分析工具和垃圾收集日志中，并不是很统一。官方的文档和工具之间也常常混淆，这些混淆甚至根植于标准的JVM工具中。
Minor GC（小型GC）：Minor GC 清理的是年轻代，又或者说 Minor GC 就是 年轻代GC
收集年轻代内存的GC事件称为 Minor GC 。关于 Minor GC 事件， 我们需要了解一些相关的内容：
1. 当JVM无法为新对象分配内存空间时就会触发 Minor GC （ 一般就是 Eden 区用满了）。 如果对象的分配速率很快， 那么 Minor GC 的次数也就会很多，频率也就会很快。
2. Minor GC 事件不处理老年代， 所以会把所有从老年代指向年轻代的引用都当做 GC Root 。从年轻代指向老年代的引用则在标记阶段被忽略。
3. 与我们一般的认知相反， Minor GC 每次都会引起STW停顿（stop-the-world）， 挂起所有的应用线程。 对大部分应用程序来说， Minor GC 的暂停时间可以忽略不计，因为 Eden 区里面的对象大部分都是垃圾，也不怎么复制到存活区/老年代。 但如果不符合这种情况，那么很多新创建的对象就不能被GC清理， Minor GC 的停顿时间就会增大，就会产生比较明显的GC性能影响。
Major GC vs. Full GC ：值得一提的是，这几个术语都没有正式的定义--无论是在JVM规范中还是在GC论文中。
我们知道，除了 Minor GC 外，另外两种GC事件则是：Major GC(大型GC) ：清理老年代空间（Old Space）的GC事件。
Full GC(完全GC) ：清理整个堆内存空间的GC事件，包括年轻代空间和老年代空间。其实 Major GC 和 Full GC 有时候并不能很好地区分。更复杂的情况是， 很多 Major GC 是由Minor GC 触发的，所以很多情况下这两者是不可分离的。另外，像G1这种垃圾收集算法，是每次找一小部分区域来进行清理，这部分区域中可能有一部分是年轻代，另一部分区域属于老年代。
所以我们不要太纠结具体是叫 Major GC 呢还是叫 Full GC ，它们一般都会造成单次较长时间的STW暂停。所以我们需要关注的是：某次GC事件，是暂停了所有线程、进而对系统造成了性能影响呢，还是与其他业务线程并发执行、暂停时间几乎可以忽略不计。
四、串行GC与并行GC日志分析
（一）串行GC
使用串行GC
java -XX:+UseSerialGC -Xms512m -Xmx512m -Xloggc:demogc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis
输出内容：
日志的第一行是JVM版本信息，第二行往后到第一个时间戳之间的部分，展示了内存分页、物理内存大小，命令行参数等信息。仔细观察，我们发现在这段日志中发生了两次GC事件，其中一次清理的是年轻代，另一次清理的是整个堆内存。让我们先来分析前一次年轻代GC事件。
2019-12-15T15:18:36.592-0800: 0.420: [GC (Allocation Failure) 2019-12-15T15:18:36.592-0800: 0.420:
[DefNew: 139776K->17472K(157248K)，0.0364555 secs]
139776K->47032K(506816K)， 0.0365665 secs]
[Times: user=0.02 sys=0.01，real=0.03 secs]
从日志输出可以看到：
1、 2019-12-15T15:18:36.592-0800 – GC事件开始的时间点。其中 -0800 表示当前时区为东八区，这只是一个标识，方便我们直观判断GC发生的时间点。后面的 0.420 – 是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->47032K(506816K) – 表示在垃圾收集之前和之后整个堆内存的使用情况。(506816K) 则表示堆内存可用的总空间大小。进一步分析可知: GC 之后堆内存使用量为9%。
5、 0.0365665 secs – GC事件持续的时间，以秒为单位。
6、 [Times: user=0.02 sys=0.01，real=0.03 secs] – 此次GC事件的持续时间，通过三个部分来衡量： user 部分表示所有 GC线程消耗的CPU时间； sys 部分表示系统调用和系统等待事件消耗的时间。 real 则表示应用程序暂停的时间。因为串行垃圾收集器(Serial Garbage Collector)只使用单个线程，所以这里 real = user + system ，0.03秒也就是30毫秒。
凭经验，这个暂停时间对大部分系统来说可以接受，但对某些延迟敏感的系统就不太理想了，比如实时的游戏服务、高频交易业务，30ms暂停导致的延迟可能会要了亲命 。
这样解读之后，我们可以分析JVM 在GC事件中的内存使用以及变化情况。
在此次垃圾收集之前，堆内存总的使用量为 139776K ，其中年轻代使用了 139776K 。可以算出，GC之前老年代空间的使用量为 0 。【实际上这是GC日志中的第一条记录】
这些数字中蕴含了更重要的信息：
GC前后对比，年轻代的使用量为 139776K->17472K ，减少了 122304K 。但堆内存的总使用量 139776K->47032K 只下降了 92744K 。可以算出，从年轻代提升到老年代的对象占用了 122304K - 92744K = 29560K 的内存空间。当然，另一组数字也能推算出GC之后老年代的使用量 47032K - 17472K = 29560K 。
通过这么分析下来应该发现，我们关注的主要是两个数据： GC暂停时间，以及GC之后的内存使用量/使用率。
2019-12-15T15:18:37.081-0800: 0.908: [GC (Allocation Failure) 2019-12-15T15:18:37.081-0800: 0.908:
[DefNew: 156152K->156152K(157248K)，0.0000331 secs] 2019-12-15T15:18:37.081-0800: 0.908:
[Tenured: 299394K->225431K(349568K)，0.0539242 secs] 455546K->225431K(506816K)，
[Metaspace: 3431K->3431K(1056768K)]， 0.0540948 secs] [Times: user=0.05 sys=0.00，real=0.05 secs]
从日志输出可以看到：
1、 2019-12-15T15:18:37.081-0800 – GC事件开始的时间。
2、 [DefNew: 156152K->156152K(157248K)，0.0000331 secs] – 前面已经解读过了，因为内存分配失败，发生了一次年轻代 GC。此次GC同样用的 DefNew 收集器。注意：此次垃圾收集消耗了 0.0000331秒，基本上确认本次GC事件没怎么处理年轻代。
3、 Tenured – 用于清理老年代空间的垃圾收集器名称。 Tenured 表明使用的是单线程的STW垃圾收集器，使用的算法为 标记-清除-整理(mark-sweep-compact ) 。 299394K->225431K(349568K) 表示GC前后老年代的使用量，以及老年代的空间大小。 0.0539242 secs是清理老年代所花的时间。
4、 455546K->225431K(506816K) – 在GC前后整个堆内存部分的使用情况，以及可用的堆空间大小。
5、 [Metaspace: 3431K->3431K(1056768K)] – Metaspace 空间的变化情况。可以看出，此次GC过程中 Metaspace 也没有什么变化。
6、 [Times: user=0.05 sys=0.00，real=0.05 secs] – GC事件的持续时间，分为user ， sys ， real 三个部分。因为串行垃圾收集器只使用单个线程，因此 real = user + system 。
进一步分析这些数据，GC之后老年代的使用率为： 225431K / 349568K = 64% ，这个比例不算小，但也不能就此说出了什么问题，毕竟GC后内存使用量下降了，还需要后续的观察。。。
和年轻代GC 相比，比较明显的差别是此次GC事件清理了老年代和Metaspace。
总结：FullGC，我们主要关注GC之后内存使用量是否下降，其次关注暂停时间。简单估算，GC后老年代使用量为220MB左右，耗时 50ms。如果内存扩大10倍，GC后老年代内存使用量也扩大10倍，那耗时可能就是500ms甚至更高，就会系统有很明显的影响了。这也是我们说串行GC性能弱的一个原因，服务端一般是不会采用串行GC的。
（二）并行GC
并行垃圾收集器对年轻代使用 标记-复制(mark-copy) 算法，对老年代使用 标记-清除-整理(mark-sweep-compact) 算法。年轻代和老年代的垃圾回收时都会触发STW事件，暂停所有的应用线程，再来执行垃圾收集。在执行 标记 和 复制/整理 阶段时都使用多个线程，因此得名“ Parallel ”。通过多个GC线程并行执行的方式，能使JVM在多CPU平台上的GC时间大幅减少。通过命令行参数 -XX:ParallelGCThreads=N 可以指定 GC 线程的数量，其默认值为CPU内核数量。
下面的三组命令行参数都是等价的，都可用来指定并行垃圾收集器：
-XX:+UseParallelGC -XX:+UseParallelOldGC -XX:+UseParallelGC -XX:+UseParallelOldGC
使用并行GC：
java -XX:+UseParallelGC -Xms512m -Xmx512m -Xloggc:demogc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis
并行垃圾收集器适用于多核服务器，其主要目标是增加系统吞吐量(也就是降低GC总体消耗的时间)。为了达成这个目标，会尽量使用尽可能多的CPU资源：
在GC事件执行期间，所有 CPU 内核都在并行地清理垃圾，所以暂停时间相对来说更短
在两次GC事件中间的间隔期，不会启动GC线程，所以这段时间内不会消耗任何系统资源
另一方面，因为并行GC的所有阶段都不能中断，所以并行GC很可能会出现长时间的卡顿。长时间卡顿的意思，就是并行GC启动后，一次性完成所有的GC操作，所以单次暂停的时间较长。假如系统延迟是非常重要的性能指标，那么就应该选择其他垃圾收集器。
执行上面的命令行，让我们看看并行垃圾收集器的GC日志长什么样子：
Minor GC：
2019-12-18T00:37:47.463-0800: 0.690: [GC (Allocation Failure)
[PSYoungGen: 104179K->14341K(116736K)] 383933K->341556K(466432K)，0.0229343 secs]
[Times: user=0.04 sys=0.08，real=0.02 secs]
解读如下：
日志信息和上面的串行GC基本上一样，这里单独说一下Times：
在并行GC中，并不是所有的操作过程都能全部并行，所以 real 约等于 user + system /GC线程数 。 笔者的机器是8个物理线程，所以默认是8个GC线程。分析这个时间，可以发现，如果使用串行GC，可能得暂停120毫秒，但并行GC只暂停了 20毫秒，实际上性能是大幅度提升了。
full GC：
2019-12-18T00:37:47.486-0800: 0.713: [Full GC (Ergonomics)
[PSYoungGen: 14341K->0K(116736K)]
[ParOldGen: 327214K->242340K(349696K)] 341556K->242340K(466432K)，
[Metaspace: 3322K->3322K(1056768K)]， 0.0656553 secs]
[Times: user=0.30 sys=0.02，real=0.07 secs]
日志信息和上面的Minor GC基本上一样，这里说一下不同点：
1、Full GC – 完全GC的标志。 Full GC 表明本次GC清理年轻代和老年代， Ergonomics 是触发GC的原因，表示JVM内部环境认为此时可以进行一次垃圾收集。
2、此次GC事件除了处理年轻代，还清理了老年代和Metaspace。
总结: 对于年轻代GC，主要关注暂停时间和GC后内存使用率是否正常，而不需要关注GC前的内存使用量；Full GC时我们更关注老年代的使用量有没有下降，以及下降了多少。如果FullGC之后内存不怎么下降，使用率还很高，那就说明系统有问题了。
四、CMS GC日志分析
CMS也可称为 并发标记清除垃圾收集器 。其设计目标是避免在老年代GC时出现长时间的卡顿。默认情况下，CMS 使用的并发线程数等于CPU内核数的 1/4 。通过以下选项来指定CMS垃圾收集器： -XX:+UseConcMarkSweepGC。如果CPU资源受限，CMS的吞吐量会比并行GC差一些。
示例：
java -XX:+UseConcMarkSweepGC -Xms512m -Xmx512m -Xloggc:demogc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis
日志示例：
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]
GC日志和并行GC类似，就不再做过多分析。
Full GC：
实际上这次截取的年轻代GC日志和FullGC日志是紧连着的，我们从间隔时间也能大致看出来， 1.067 +0.02secs ~ 1.091 。CMS的日志是一种完全不同的格式，并且很长，因为CMS对老年代进行垃圾收集时每个阶段都会有自己的日志。
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]
解读：
1、 CMS Initial Mark – 这个阶段的名称为 “Initial Mark”，会标记所有的 GC Root。
2、[1 CMS-initial-mark: 342870K(349568K)] – 这部分数字表示老年代的使用量，以及老年代的空间大小。
3、 363883K(506816K)，0.0002262 secs – 当前堆内存的使用量，以及可用堆的大小、消耗的时间。可以看出这个时间非常短，只有 0.2毫秒左右，因为要标记的这些Roo数量很少。
阶段 2：Concurrent Mark(并发标记)
在并发标记阶段，CMS 从前一阶段 “Initial Mark” 找到的 ROOT 开始算起，遍历老年代并标记所有的存活对象。
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]
解读：
1、CMS-concurrent-mark – 指明了是CMS垃圾收集器所处的阶段为并发标记("Concurrent Mark")。
2、 0.001/0.001 secs – 此阶段的持续时间，分别是GC线程消耗的时间和实际消耗的时间。
阶段 3：Concurrent Preclean(并发预清理)
此阶段同样是与应用线程并发执行的，不需要停止应用线程。
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]
解读：
1、CMS-concurrent-preclean – 表明这是并发预清理阶段的日志，这个阶段会统计前面的并发标记阶段执行过程中发生了改变的对象。
2、0.001/0.001 secs – 此阶段的持续时间，分别是GC线程运行时间和实际占用的时间。
阶段 4：Concurrent Abortable Preclean(可取消的并发预清理)
此阶段也不停止应用线程，尝试在会触发STW 的 Final Remark 阶段开始之前，尽可能地多干一些活。本阶段的具体时间取决于多种因素，因为它循环做同样的事情，直到满足某一个退出条件(如迭代次数，有用工作量，消耗的系统时间等等)。
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]
解读：
1、CMS-concurrent-abortable-preclean – 指示此阶段的名称：“Concurrent AbortablePreclean”。
2、0.000/0.000 secs – 此阶段GC线程的运行时间和实际占用的时间。从本质上讲，GC线程试图在执行 STW 暂停之前等待尽可能长的时间。默认条件下，此阶段可以持续最长5秒钟的时间。
此阶段完成的工作可能对STW停顿的时间有较大影响，并且有许多重要的配置选项和失败模式。
阶段 5：Final Remark(最终标记)
最终标记阶段是此次GC事件中的第二次(也是最后一次)STW停顿。本阶段的目标是完成老年代中所有存活对象的标记。因为之前的预清理阶段是并发执行的，有可能GC线程跟不上应用程序的修改速度。所以需要一次 STW 暂停来处理各种复杂的情况。通常CMS会尝试在年轻代尽可能空的情况下执行 final remark 阶段，以免连续触发多次 STW 事件。
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]
解读：
1、CMS Final Remark – 这是此阶段的名称，最终标记阶段，会标记老年代中所有的存活对象，包括此前的并发标记过程中创建/修改的引用。
2、YG occupancy: 26095 K (157248 K) – 当前年轻代的使用量和总容量。
3、 [Rescan (parallel) ，0.0002680 secs] – 在程序暂停后进行重新扫描(Rescan)，以完成存活对象的标记。这部分是并行执行的，消耗的时间为 0.0002680秒 。
4、 weak refs processing，0.0000230 secs – 第一个子阶段： 处理弱引用的持续时间。
5、 class unloading，0.0004008 secs – 第二个子阶段： 卸载不使用的类，以及持续时间。
6、scrub symbol table，0.0006072 secs – 第三个子阶段： 清理符号表，即持有class级别metadata 的符号表(symbol tables)。
7、 scrub string table，0.0001769 secs – 第四个子阶段： 清理内联字符串对应的 stringtables。
8、 [1 CMS-remark: 342870K(349568K)] – 此阶段完成后老年代的使用量和总容量。
9、 368965K(506816K)，0.0015928 secs – 此阶段完成后，整个堆内存的使用量和总容量。
10、[Times: user=0.01 sys=0.00,real=0.00 secs] – GC事件的持续时间。
在这5个标记阶段完成后，老年代中的所有存活对象都被标记上了，接下来JVM会将所有不使用的对象清除，以回收老年代空间。
阶段 6：Concurrent Sweep(并发清除)
此阶段与应用程序并发执行，不需要STW停顿。目的是删除不再使用的对象，并回收他们占用的内存空间。
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]
解读：
1、CMS-concurrent-sweep – 此阶段的名称，“Concurrent Sweep”，并发清除老年代中所有未被标记的对象、也就是不再使用的对象，以释放内存空间。
2、 0.000/0.000 secs – 此阶段的持续时间和实际占用的时间，这是一个四舍五入值，只精确到小数点后3位。
阶段 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]
解读：
1、CMS-concurrent-reset – 此阶段的名称，“Concurrent Reset”，重置CMS算法的内部数据结构，为下一次GC循环做准备。
2、0.000/0.000 secs – 此阶段的持续时间和实际占用的时间
那么问题来了，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 ，所以FullGC之后老年代的使用量占比是 291892K / 349568K = 83% 。这个占比不低。说明什么问题呢？ 一般来说就是分配的内存小了，毕竟我们才指定了512MB的最大堆内存。
总之，CMS垃圾收集器在减少停顿时间上做了很多给力的工作，很大一部分GC线程是与应用线程并发运行的，不需要暂停应用线程，这样就可以在一般情况下每次暂停的时候较少。当然，CMS也有一些缺点，其中最大的问题就是老年代的内存碎片问题，在某些情况下GC会有不可预测的暂停时间，特别是堆内存较大的情况下。
五、G1 GC日志分析
使用G1 GC
java -XX:+UseG1GC -Xms512m -Xmx512m -Xloggc:demogc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis
打印的东西非常多，能会生成上千行的GC日志：
如果只想看GC总的GC步骤，不想看详细信息，可以将参数中PrintGCDetails改为PrintGC
（一）Evacuation Pause: young(纯年轻代模式转移暂停)
（二）Concurrent Marking(并发标记)
（三）Evacuation Pause (mixed)(转移暂停: 混合模式)
（四）Full GC (Allocation Failure)
1、总体日志
当年轻代空间用满后，应用线程会被暂停，年轻代内存块中的存活对象被拷贝到存活区。 如果还没有存活区，则任意选择一部分空闲的内存块作为存活区。拷贝的过程称为转移(Evacuation)，这和前面介绍的其他年轻代收集器是一样的工作原理。转移暂停的日志信息很长，为简单起见，我们去除了一些不重要的信息。在并发阶段之后我们会进行详细的讲解。
此外，由于日志记录很多，所以并行阶段和“其他”阶段的日志将拆分为多个部分来进行讲解。
2019-12-23T01:45:40.605-0800: 0.181: [GC pause (G1 Evacuation Pause) (young)，0.0038577 secs]
[Parallel Time: 3.1 ms，GC Workers: 8]
...... worker线程的详情，下面单独讲解
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 0.6 ms]
...... 其他琐碎任务，下面单独讲解
[Eden: 25.0M(25.0M)->0.0B(25.0M) Survivors: 0.0B->4096.0K Heap: 28.2M(512.0M)->9162.7K(512.0M)]
[Times: user=0.01 sys=0.01，real=0.00 secs]
（1）[GC pause (G1 Evacuation Pause) (young)，0.0038577 secs] – G1转移暂停，纯年轻代模式; 只清理年轻代空间。这次暂停在JVM启动之后 181 ms 开始，持续的系统时间为0.0038577秒 ，也就是 3.8ms 。
（2） [Parallel Time: 3.1 ms，GC Workers: 8] – 表明后面的活动由8个 Worker 线程并行执，消耗时间为3.1毫秒(real time); worker 是一种模式，类似于一个老板指挥多个工人干活。
（3） …... – 为阅读方便，省略了部分内容，下面紧接着也会讲解。
（4） [Code Root Fixup: 0.0 ms] – 释放用于管理并行活动的内部数据，一般都接近于零。这个过程是串行执行的。
（5） [Code Root Purge: 0.0 ms] – 清理其他部分数据，也是非常快的，如非必要基本上等于零。也是串行执行的过程。
（6） [Other: 0.6 ms] – 其他活动消耗的时间，其中大部分是并行执行的。
（7） … – 请参考后文。
（8） [Eden: 25.0M(25.0M)->0.0B(25.0M) – 暂停之前和暂停之后，Eden 区的使用量/总容量。
（9） Survivors: 0.0B->4096.0K – GC暂停前后，存活区的使用量。 Heap:28.2M(512.0M)->9162.7K(512.0M)] – 暂停前后，整个堆内存的使用量与总容量。
（10） [Times: user=0.01 sys=0.01，real=0.00 secs] – GC事件的持续时间。
说明：系统时间(wall clock time/elapsed time)，是指一段程序从运行到终止，系统时钟走过的时间。一般系统时间都要比CPU时间略微长一点。
2、worker线程详情：
最繁重的GC任务由多个专用的 worker 线程来执行，下面的日志描述了他们的行为:
[Parallel Time: 3.1 ms，GC Workers: 8]
[GC Worker Start (ms): Min: 180.6，Avg: 180.6，Max: 180.7，Diff: 0.1]
[Ext Root Scanning (ms): Min: 0.1，Avg: 0.3，Max: 0.6，Diff: 0.4，Sum: 2.1]
[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.1，Diff: 0.1，Sum: 0.1]
[Object Copy (ms): Min: 2.2，Avg: 2.5，Max: 2.7，Diff: 0.4，Sum: 19.8]
[Termination (ms): Min: 0.0，Avg: 0.2，Max: 0.4，Diff: 0.4，Sum: 1.5]
[Termination Attempts: Min: 1，Avg: 1.0，Max: 1，Diff: 0，Sum: 8]
[GC Worker Other (ms): Min: 0.0，Avg: 0.0，Max: 0.0，Diff: 0.0，Sum: 0.1]
[GC Worker Total (ms): Min: 2.9，Avg: 3.0，Max: 3.0，Diff: 0.1，Sum: 23.7]
[GC Worker End (ms): Min: 183.6，Avg: 183.6，Max: 183.6，Diff: 0.0]
Worker线程的日志信息解读：
（1） [Parallel Time: 3.1 ms，GC Workers: 8] – 前面介绍过，这表明下列活动由8个线程并行执行，消耗的时间为3.1毫秒(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)" 所导致的。
3、其他琐碎任务
此外，在转移暂停期间,还有一些琐碎的小任务。
[Other: 0.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
这里只介绍其中的一部分：
（1） [Other: 0.6 ms] – 其他活动消耗的时间，其中很多是并行执行的。
（2） Choose CSet - 选择CSet消耗的时间; CSet 是 Collection Set 的缩写。
（3） [Ref Proc: 0.3 ms] – 处理非强引用(non-strong)的时间：进行清理或者决定是否需要清理。
（4） [Ref Enq: 0.0 ms] – 用来将剩下的 non-strong 引用排列到合适的 ReferenceQueue 中。
（5） Humongous Register ， Humongous Reclaim 大对象相关的部分。后面进行介绍。
（6） [Free CSet: 0.0 ms] – 将回收集中被释放的小堆归还所消耗的时间，以便他们能用来分配新的对象。
配新的对象。
（二）Concurrent Marking(并发标记)
当堆内存的总
当堆内存的总体使用比例达到一定数值时，就会触发并发标记。 这个默认比例是 45% ，但也可以通过JVM参数 InitiatingHeapOccupancyPercent 来设置。和CMS一样，G1的并发标记也是由多个阶段组成，其中一些阶段是完全并发的，还有一些阶段则会暂停应用线程。
阶段 1: Initial Mark(初始标记)
可以在 Evacuation Pause 日志中的第一行看到(initial-mark)暂停，类似这样:
2019-12-23T01:45:41.568-0800: 1.144: [GC pause (G1 Humongous Allocation) (young) (initial-mark)， 0.0012116 secs]
当然，这里引发GC的原因是大对象分配，也可能是其他原因，例如： to-space exhausted ，或者默认GC原因等等.
阶段 2: Root Region Scan(Root区扫描)
此阶段标记所有从 "根区域" 可达的存活对象。根区域包括：非空的区域，以及在标记过程中不得不收集的区域。对应的日志：
2019-12-23T01:45:41.569-0800: 1.145: [GC concurrent-root-region-scan-start]
2019-12-23T01:45:41.569-0800: 1.145: [GC concurrent-root-region-scan-end，0.0000360 secs]
阶段 3: Concurrent Mark(并发标记)
2019-12-23T01:45:41.569-0800: 1.145: [GC concurrent-mark-start]
2019-12-23T01:45:41.571-0800: 1.146: [GC concurrent-mark-end，0.0015209 secs]
阶段 4: Remark(再次标记)
2019-12-23T01:45:41.571-0800: 1.146: [GC remark 2019-12-23T01:45:41.571-0800: 1.147: [Finalize Marking，0.0002456 secs]
2019-12-23T01:45:41.571-0800: 1.147: [GC ref-proc，0.0000504 secs]2019-12-23T01:45:41.571-0800: 1.147: [Unloading，0.0007297 secs]，0.0021658 secs] [Times: user=0.01 sys=0.00，real=0.00 secs]
阶段 5: Cleanup(清理)
最后这个清理阶段为即将到来的转移阶段做准备，统计小堆块中所有存活的对象，并将小堆块进行排序，以提升GC的效率。此阶段也为下一次标记执行必需的所有整理工作(house-keeping activities)：维护并发标记的内部状态。要提醒的是，所有不包含存活对象的小堆块在此阶段都被回收了。有一部分任务是并发的: 例如空堆区的回收，还有大部分的存活率计算，此阶段也需要一个短暂的STW暂停，才能不受应用线程的影响并完成作业。
这种STW停顿的对应的日志如下：
2019-12-23T01:45:41.573-0800: 1.149: [GC cleanup 366M->366M(512M)，0.0006795 secs] [Times: user=0.00 sys=0.00，real=0.00 secs]
如果发现某些小堆块中只包含垃圾，则日志格式可能会有点不同，如:
2019-12-23T21:26:42.411-0800: 0.689: [GC cleanup 247M->242M(512M)，0.0005349 secs] [Times: user=0.00 sys=0.00，real=0.00 secs] 2019-12-23T21:26:42.412-0800: 0.689: [GC concurrent-cleanup-start] 2019-12-23T21:26:42.412-0800: 0.689: [GC concurrent-cleanup-end，0.0000134 secs]如果你在执行示例程序之后没有看到对应的GC日志，可以多跑几遍试试。毕竟GC和内存分配属于运行时动态的，每次运行都可能有些不同。
我们在示例程序中生成的数组大小和缓存哪个对象都是用的随机数，每次运行结果都不一样。如果想让每次的随机数都一致，请搜索: " 随机数种子 "。标记周期一般只在碰到region中一个存活对象都没有的时候，才会顺手处理一把，大多数情况下都不释放内存。
（三）Evacuation Pause (mixed)(转移暂停: 混合模式)
并发标记完成之后
并发标记完成之后，G1将执行一次混合收集(mixed collection)，不只清理年轻代，还将一部分老年代区域也加入到 collection set 中。混合模式的转移暂停(Evacuation pause)不一定紧跟并发标记阶段。在并发标记与混合转移暂停之间，很可能会存在多次 young 模式的转移暂停。 混合模式 就是指这次GC事件混合着处理年轻代和老年代的region。这也是G1等增量垃圾收集器的特色。而ZGC等最新的垃圾收集器则不使用分代算法。 当然，以后可能还是会实现分代的，毕竟分代之后性能还会有提升。
混合模式下的日志，和纯年轻代模式相比，可以发现一些有趣的地方：
2019-12-23T21:26:42.383-0800: 0.661: [GC pause (G1 Evacuation Pause) (mixed)，0.0029192 secs]
[Parallel Time: 2.2 ms，GC Workers: 8]
......
[Update RS (ms): Min: 0.1，Avg: 0.2，Max: 0.3，Diff: 0.2，Sum: 1.4]
[Processed Buffers: Min: 0，Avg: 1.8，Max: 3，Diff: 3，Sum: 14]
[Scan RS (ms): Min: 0.0，Avg: 0.0，Max: 0.0，Diff: 0.0，Sum: 0.1]
......
[Clear CT: 0.4 ms]
[Other: 0.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.1 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Free CSet: 0.1 ms]
[Eden: 21.0M(21.0M)->0.0B(21.0M) Survivors: 4096.0K->4096.0K Heap: 337.7M(512.0M)->274.3M(512.0M)]
[Times: user=0.01 sys=0.00，real=0.00 secs]
简单解读（部分概念和名称，可以参考G1章节）：
1、 [Update RS (ms) – 因为 Remembered Sets 是并发处理的，必须确保在实际的垃圾收集之前，缓冲区中的 card 得到处理。如果card数量很多，则GC并发线程的负载可能就会很高。可能的原因是修改的字段过多，或者CPU资源受限。
2、 Processed Buffers – 各个 worker 线程处理了多少个本地缓冲区(local buffffer)。
3、 Scan RS (ms) – 用了多长时间扫描来自RSet的引用。
4、 [Clear CT: 0.4 ms] – 清理 card table 中 cards 的时间。清理工作只是简单地删除“脏”状态，此状态用来标识一个字段是否被更新的，供Remembered Sets使用。
5、 [Redirty Cards: 0.1 ms] – 将 card table 中适当的位置标记为 dirty 所花费的时间。"适当的位置"是由GC本身执行的堆内存改变所决定的，例如引用排队等。
（四）Full GC (Allocation Failure)
G1是一款自适应的增量垃圾收集器。
G1是一款自适应的增量垃圾收集器。一般来说，只有在内存严重不足的情况下才会发生Full GC。 比如堆空间不足或者to-space空间不足。在前面的示例程序基础上，增加缓存对象的数量，即可模拟Full GC。
示例日志如下：
2020-03-02T18:44:17.814-0800: 2.826: [Full GC (Allocation Failure) 403M->401M(512M)，0.0046647 secs]
[Eden: 0.0B(25.0M)->0.0B(25.0M) Survivors: 0.0B->0.0B Heap: 403.6M(512.0M)->401.5M(512.0M)]， [Metaspace: 2789K->2789K(1056768K)]
[Times: user=0.00 sys=0.00，real=0.00 secs]
在堆内存较大的情况下【8G+】，如果G1发生了FullGC，暂停时间可能会退化，达到几十秒甚至更多。如下面这张图片所示：
从其中的OldGen部分可以看到， 118 次 Full GC 消耗了31分钟，平均每次达到 20 秒，按图像比例可粗略得知，吞吐率不足 30% 。这张图片所表示的场景是在压测Flink按时间窗口进行聚合计算时发生的，主要原因是对象太多，堆内存空间不足而导致的，修改对象类型为原生数据类型之后问题得到缓解，加大堆内存空间，满足批处理/流计算的需求之后GC问题不再复现。
发生持续时间很长的FullGC暂停时，就需要我们进行排查和分析，确定是否需要修改GC配置，或者增加内存，还是需要修改程序的业务逻辑。
标签：12,0.00,0800,解读,secs,GC,2019,日志 来源： https://www.cnblogs.com/liconglong/p/16224130.html