本文为《深入学习 JVM 系列》第二十二篇文章
影响垃圾收集性能有三个主要的属性，垃圾收集调优又有三个基本原则，以及垃圾收集调优时需要采集的信息。如果想要对垃圾收集进行调优，则需要根据实际场景对不同属性做出取舍，理解调优的原则以及收集什么信息。
性能属性
吞吐量
吞吐量是评价垃圾收集器能力的重要指标之一，指不考虑垃圾收集引起的停顿时间或内存消耗，每单位时间可以执行的工作量的指标。通常，吞吐量的增加是以延迟增加和/或内存占用增加为代价的。
一般吞吐量需求(Generic requirements for throughput) 类似这样:
- 每天必须处理 100万个订单；
- 每秒应执行 2500 个事务
可以看出，吞吐量需求不是针对单个操作的,，而是在给定的时间内，系统必须完成多少个操作。
延迟
延迟是衡量应用程序接收到执行某些工作的激励与该工作完成之间经过的时间。延迟要求忽略吞吐量。通常，提高响应能力或降低延迟是以降低吞吐量和/或增加内存占用为代价的。
延迟指标通常如下所述：
- 应用程序应在 60 毫秒内执行交易请求以完成
- 90%的订单付款操作必须在3秒以内处理完成
这类性能指标要确保程序在工作过程中，GC 暂停不能暂用太长时间，否则就满足不了指标。
内存占用
内存占用量是在某种吞吐量、某种延迟和/或某种可用性和可管理性水平上运行应用程序所需的内存量的度量。内存占用通常表示为运行应用程序所需的 Java 堆数量和/或运行应用程序所需的内存总量。通常，通过增加 Java 堆大小来增加内存占用可以提高吞吐量或减少延迟，或两者兼而有之。随着应用程序可用内存的减少，通常会牺牲吞吐量或延迟。
例如系统部署到小于1G 内存的服务器上，因为计算资源不可随意挥霍，所以在满足延迟和吞吐量需求的基础上必须要满足内存占用。
原则
- Minor GC 回收原则。每次 Minor GC 都尽可能多地收集垃圾对象，减少 Full GC 的频率。Full GC 持续时间总是最长的，会影响吞吐量和延迟的性能。
- GC 内存最大化原则。在预算以内，堆内存越大越好，吞吐量和延迟性能都会越好。这也意味着新生代可以适当调整大小，以更好应对短寿命对象的创建率，减少提升到老年代的分配数量。
- 三选二原则。在上述三个性能属性（吞吐量、延迟、内存占用）中任意选择两个进行 JVM 垃圾收集调优。
关于 GC 调优需要收集什么信息，以及怎么查看，我们将先通过命令行查看 GC 日志，后续通过可视化工具来获取关键信息。
GC日志分析
我们需要通过 JVM 参数（默认为 JDK8）预先设置 GC 日志，通常有以下几种 JVM 参数设置：
-XX:+PrintGC 输出GC日志 -XX:+PrintGCDetails 输出GC的详细日志 -XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式） -XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800） -XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息 -XX:+PrintReferenceGC 输出的内容包含系统的软引用、弱引用、虚引用和Finallize队列 -Xloggc:../logs/gc.log 日志文件的输出路径 复制代码
这里使用如下参数来打印日志，基于 JDK8，默认使用 Parallel Scavenge 收集器和 Parallel Old 收集器。
@Data @AllArgsConstructor @NoArgsConstructor public class Goods { private String name; private Double price; private String[] types; } //-Xms60M -Xmx60M -XX:+PrintGCDetails -XX:+PrintGCTimeStamps public class OutOfMemoryTest { public static void main(String[] args) throws InterruptedException { Map<String, Goods> map = new HashMap<>(); int counter = 1; while (true) { Thread.sleep(10); Goods goods = new Goods(); String[] types = new String[counter]; for (int i = 0; i < types.length; i++) { types[i] = "type" + i; } goods.setName("hresh" + counter); goods.setPrice(Double.valueOf(counter)); goods.setTypes(types); map.put(goods.getName(), goods); // if (counter % 100 == 0) { // System.out.println("put" + counter); // } counter++; } } } 复制代码
截取 Full GC 的部分日志内容如下：
16.619: [Full GC (Ergonomics) [PSYoungGen: 15359K->15359K(17920K)] [ParOldGen: 40924K->40924K(40960K)] 56284K->56284K(58880K), [Metaspace: 3768K->3768K(1056768K)], 0.0320617 secs] [Times: user=0.31 sys=0.00, real=0.03 secs] 16.651: [Full GC (Ergonomics) [PSYoungGen: 15359K->15359K(17920K)] [ParOldGen: 40926K->40926K(40960K)] 56286K->56286K(58880K), [Metaspace: 3768K->3768K(1056768K)], 0.0337364 secs] [Times: user=0.31 sys=0.00, real=0.03 secs] 16.685: [Full GC (Ergonomics) [PSYoungGen: 15359K->15359K(17920K)] [ParOldGen: 40927K->40927K(40960K)] 56287K->56287K(58880K), [Metaspace: 3768K->3768K(1056768K)], 0.0322237 secs] [Times: user=0.30 sys=0.00, real=0.03 secs] 16.717: [Full GC (Ergonomics) [PSYoungGen: 15359K->15359K(17920K)] [ParOldGen: 40929K->40929K(40960K)] 56289K->56289K(58880K), [Metaspace: 3768K->3768K(1056768K)], 0.0314023 secs] [Times: user=0.30 sys=0.01, real=0.04 secs] 16.749: [Full GC (Ergonomics) [PSYoungGen: 15359K->15359K(17920K)] [ParOldGen: 40931K->40931K(40960K)] 56291K->56291K(58880K), [Metaspace: 3768K->3768K(1056768K)], 0.0327116 secs] [Times: user=0.31 sys=0.00, real=0.03 secs] 复制代码
关于 GC 日志，Minor GC 和 Full GC 的含义可以参考本文。
分析上述输出结果，可以得知：
- 从 16.619 到 16.749 发生了 4次 Full GC，大概耗费了 130 ms，有4次 GC 暂停；
- 比如说 16.749 这一刻的 GC，花费总时长为 310 ms，暂停时间为 0.0327116 s，不过因为是多核 CPU 机器，而且使用的是并行 GC，所以暂停时间大约为 30ms；
- 这四次 GC 暂停总时长大约为 130ms，这里存在疑惑，按理说暂停时长应该小于运行时长，个人猜测可能是 real 的值不够那么精确；
- 在 GC 完成后，几乎所有的老年代空间（40960K）依然被占用（40931K）。
通过上述日志可以发现老年代空间几乎被占满了，而且 GC 之后也没有释放，那么过不了多久，就会抛出 OOM 异常。
老年代内存占用经过 GC 后没有改善，仍然接近全满，那么会造成性能瓶颈，可能是内存太小，又或者存在内存泄漏。除了可以通过观察老年代的内存使用情况，还可以观察每次 GC 的暂停时间（即我们之前学习的 STW，在日志中可以参考 real所表示的时间），如果暂停总时长占比特别高，那么会损坏系统的吞吐量。如果个别 GC 暂停时间过长，则会影响系统的延迟指标。
除了在程序启动时配置相关参数，还可以在程序运行时使用 JDK 自带的命令来查看 GC 信息。
jstat命令
jstat 命令（帮助文档）可用来打印目标 Java 进程的性能数据。它包括多条子命令，如下所示：
% jstat -options -class //打印类加载相关的数据 -compiler //打印即时编译相关的数据 // 以gc开头的子命令，打印垃圾回收相关的数据 -gc //显示和gc相关的堆信息 -gccapacity //显示各个代的容量以及使用情况 -gccause //显示垃圾回收的相关信息（通-gcutil）,同时显示最后一次或当前正在发生的垃圾回收的诱因 -gcmetacapacity //显示metaspace的大小 -gcnew // 显示新生代信息 -gcnewcapacity //显示新生代大小和使用情况 -gcold //显示老年代和永久代的信息 -gcoldcapacity //显示老年代的大小 -gcutil //显示垃圾收集信息 -printcompilation //打印即时编译相关的数据 复制代码
默认情况下，jstat 只会打印一次性能数据。
// JDK8 % jstat -gc 67537 S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 2560.0 2560.0 0.0 1223.1 15360.0 3956.4 40960.0 8.0 4864.0 3055.9 512.0 322.2 1 0.001 0 0.000 0.001 复制代码
实际应用中，我们肯定是想观察某个进程一段时间内性能数据，这时可以这样做：将它配置为每隔一段时间打印一次，直至目标 Java 进程终止，或者达到我们所配置的最大打印次数。具体示例如下所示：
//JDK8 % jstat -gc 67558 1s 4 S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 2560.0 2560.0 0.0 1255.1 15360.0 3956.4 40960.0 8.0 4864.0 3055.9 512.0 322.2 1 0.004 0 0.000 0.004 2560.0 2560.0 0.0 1255.1 15360.0 3956.4 40960.0 8.0 4864.0 3055.9 512.0 322.2 1 0.004 0 0.000 0.004 2560.0 2560.0 0.0 1255.1 15360.0 3956.4 40960.0 8.0 4864.0 3055.9 512.0 322.2 1 0.004 0 0.000 0.004 2560.0 2560.0 0.0 1255.1 15360.0 3956.4 40960.0 8.0 4864.0 3055.9 512.0 322.2 1 0.004 0 0.000 0.004 复制代码
上述命令格式如下：
jstat -outputOptions [-t] [-hlines] VMID [interval [count]] 复制代码
- outputOptions：指的是上文提到的子命令，一个或多个输出选项；
- t：将时间戳列显示为输出的第一列。时间戳是自目标 JVM 启动时间以来的时间。
- lines：每个样本（输出行）显示一个列标题，其中
n是一个正整数。默认值为0，即显示第一行数据的列标题。 - VMID：虚拟机标识符，它是指示目标 JVM 的字符串。请参阅虚拟机标识符。当监控本地环境的 Java 进程时，VMID 可以简单理解为 PID。
- interval：以指定单位、秒 (s) 或毫秒 (ms) 为单位的采样间隔。默认单位是毫秒。这必须是一个正整数。
- count：用于指定输出多少次记录，缺省则会一直打印
在-gc子命令的输出中，前四列分别为两个 Survivor 区的容量（Capacity）和已使用量（Utility）。我们可以看到，这两个 Survivor 区的容量相等，而且始终有一个 Survivor 区的内存使用量为 0，关于这点在讲解 JVM 垃圾回收时有说过原因。
关于 jstat 命令的输出结果，想要知道每列代表什么含义，以及怎么计算的，其实在 JDK lib 包下的 tools.jar 里存在一个文件叫做 jstat_options，这个文件里定义了上面的每种类型的输出结果。比如说 gc。
如上图所示，我们可以在 IDEA 中打开该文件。这里只截取部分内容：
如果垃圾收集器使用的是 G1 收集器，输出结果则变为：
//JDK9 % jstat -gc 31678 1s 4 S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 0.0 3072.0 0.0 3072.0 161792.0 2048.0 97280.0 9290.0 5376.0 5084.5 512.0 433.9 1 0.004 0 0.000 0.004 0.0 3072.0 0.0 3072.0 161792.0 2048.0 97280.0 9290.0 5376.0 5084.5 512.0 433.9 1 0.004 0 0.000 0.004 0.0 3072.0 0.0 3072.0 161792.0 2048.0 97280.0 9290.0 5376.0 5084.5 512.0 433.9 1 0.004 0 0.000 0.004 0.0 3072.0 0.0 3072.0 161792.0 2048.0 97280.0 9290.0 5376.0 5084.5 512.0 433.9 1 0.004 0 0.000 0.004 复制代码
可以看出，S0C 和 S0U 始终为 0，即其中一个 Survivor 容量和使用量始终为 0 。
这是因为，当使用 G1 GC 时，Java 虚拟机不再设置 Eden 区、Survivor 区，老年代区的内存边界，而是将堆划分为若干个等长内存区域（Region）。
每一个 Region 都可以根据需要，扮演新生代的 Eden 空间，Survivor 空间，或者老年代空间，并且可以在不同区域类型之间来回切换。
换句话说，逻辑上我们只有一个 Survivor 区。当需要迁移 Survivor 区中的数据时（即 Copying GC），我们只需另外申请一个或多个内存区域，作为新的 Survivor 区。
因此，Java 虚拟机决定在使用 G1 GC 时，将所有 Survivor 内存区域的总容量以及已使用量存放至 S1C 和 S1U 中，而 S0C 和 S0U 则被设置为 0。
那么实际应用中，我们使用 jstat 命令如何来分析 Java 进程的性能呢？
我们来下面这样一段性能输出结果：
% jstat -gc 33678 1s 9 Timestamp S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 200.0 8448.0 8448.0 8448.0 0.0 67712.0 67712.0 169344.0 169344.0 21248.0 20534.3 3072.0 2807.7 34 0.720 658 133.684 134.404 201.0 8448.0 8448.0 8448.0 0.0 67712.0 67712.0 169344.0 169343.2 21248.0 20534.3 3072.0 2807.7 34 0.720 662 134.712 135.432 202.0 8448.0 8448.0 8102.5 0.0 67712.0 67598.5 169344.0 169343.6 21248.0 20534.3 3072.0 2807.7 34 0.720 667 135.840 136.559 203.0 8448.0 8448.0 8126.3 0.0 67712.0 67702.2 169344.0 169343.6 21248.0 20547.2 3072.0 2807.7 34 0.720 669 136.178 136.898 204.0 8448.0 8448.0 8126.3 0.0 67712.0 67702.2 169344.0 169343.6 21248.0 20547.2 3072.0 2807.7 34 0.720 669 136.178 136.898 205.0 8448.0 8448.0 8134.6 0.0 67712.0 67712.0 169344.0 169343.5 21248.0 20547.2 3072.0 2807.7 34 0.720 671 136.234 136.954 206.0 8448.0 8448.0 8134.6 0.0 67712.0 67712.0 169344.0 169343.5 21248.0 20547.2 3072.0 2807.7 34 0.720 671 136.234 136.954 207.0 8448.0 8448.0 8154.8 0.0 67712.0 67712.0 169344.0 169343.5 21248.0 20547.2 3072.0 2807.7 34 0.720 673 136.289 137.009 208.0 8448.0 8448.0 8154.8 0.0 67712.0 67712.0 169344.0 169343.5 21248.0 20547.2 3072.0 2807.7 34 0.720 673 136.289 137.009 复制代码
我们先查看第一行的数据：
- jstat 连接到 JVM 的时间, 是JVM启动后的 200秒。此信息从第一行的 “Timestamp” 列得知。
- 从第一行的 “YGC” 列得知年轻代共执行了34次GC, 由 “FGC” 列得知整个堆内存已经执行了 658次 full GC。
- 年轻代的GC耗时总共为
0.720 秒, 显示在“YGCT” 这一列。
- Full GC 的总计耗时为
133.684 秒, 由“FGCT”列得知。 这立马就吸引了我们的目光, 总的 JVM 运行时间只有 200 秒, 但其中有 66% 的部分被 Full GC 消耗了。
再看第二行的数据：
- 在接下来的一秒内共执行了 4 次 Full GC。参见 “FGC“ 列。
- 这4次 Full GC 暂停占用了差不多 1秒的时间(根据 FGCT列的差得知)。与第一行相比，Full GC 耗费了
928 毫秒，总时长为 1s, 那么 Full GC 则占用了92.8%的时间。
- 根据 “OC 和 “OU” 列得知, 整个老年代的空间为
169,344.0 KB(“OC“), 在 4 次 Full GC 后依然占用了169,344.2 KB(“OU“)。用了928ms的时间却只释放了 800 字节的内存, 怎么看都觉得很不正常。
通过前两行数据可以发现程序存在严重的问题，后续的数据可以确定该问题依然存在。
通过 jstat 的输出能够快速发现以下问题：
- 可以比较 Java 进程的启动时间以及总 GC 时间（GCT 列），或者两次测量的间隔时间以及总 GC 时间的增量，来得出 GC 时间占运行时间的比例。就暴露出 GC 开销过大的问题. 不同系统对 GC 开销有不同的容忍度, 由性能需求决定, 一般来讲, 超过
10%的 GC 开销都是有问题的。
- “YGC” 和 “FGC” 列的快速变化往往也是有问题的征兆。频繁的 GC 暂停会累积，并导致更多的线程停顿(stop-the-world pauses)，进而影响吞吐量。
- 如果看到 “OU” 列中,老年代的使用量约等于老年代的最大容量(OC), 并且不降低的话, 就表示虽然执行了老年代 GC, 但基本上属于无效GC。
后续我们会继续学习日志分析工具，可以更直观的观测 GC 状态，下篇文章我们不见不散。
