【JVM】二十八、揭秘高效Java性能：如何精准分析Young GC日志
本文将以一步一图的方式，继续仔细分析GC日志。通过图文并茂的解析，展示Young GC的实际执行过程，帮助大家更好地理解其运作机制。
1、前文回顾
上一篇文章向大家展示了一个示例性的代码，并提供了实验所需的JVM参数。我们详细讲解了如何在Eclipse中使用特定的JVM参数来运行程序，并且大家也观察到了代码运行中触发的Young GC的日志。然后，我们鼓励大家自行进行思考和分析。
今天，我们将以一步一图的方式，继续深入探讨昨天的内容，仔细分析GC日志。通过图文并茂的解析，我们将向大家展示Young GC的实际执行过程，帮助大家更好地理解其运作机制。
2、快速查看你的程序默认JVM参数
在GC日志中，我们可以观察到以下内容：
CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:MaxNewSize=5242880 .........
这段信息向我们展示了本次运行程序时JVM所采用的参数。其中，大部分参数是我们主动设置的，同时也包含了一些默认设置的参数。这些默认参数通常不会对程序产生太大影响。
很多人可能会问，如果没有手动设置JVM参数，如何查看系统使用的默认JVM参数呢？其实方法非常简单，只需为你的JVM添加一段打印GC日志的参数，就可以在这里观察到系统默认为JVM进程分配了多少内存空间。通常情况下，系统默认分配的内存空间是较小的。
3、一次GC的概要说明
接下来，我们来分析GC日志中的一行内容：
0.268: [GC (Allocation Failure) 0.269: [ParNew: 4030K->512K(4608K), 0.0015734 secs] 4030K->574K(9728K), 0.0017518 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
这一行日志概括了本次垃圾回收（GC）的执行情况。让我们详细解释一下。
首先，"GC (Allocation Failure)"表示发生了一次垃圾回收，原因是对象分配失败。为什么会发生对象分配失败呢？原因是在程序运行过程中，需要分配一个2MB大小的数组，但是Eden区的内存空间不足，无法满足这个需求。因此，触发了一次Young GC（年轻代垃圾回收）。
本次垃圾回收（GC）何时发生的？
通过一个简单的数字“0.268”，我们可以了解在系统运行后经过多少秒发生了本次GC。例如，在这个例子中，大约在系统运行后的200多毫秒时，发生了本次GC。
关于“ParNew”的含义，大家应该很清楚。我们触发的是年轻代的Young GC，因此是使用我们指定的ParNew垃圾回收器来执行GC操作。
“4030K->512K(4608K)”表示年轻代的可用空间为4608KB，即4.5MB。为什么是4.5MB呢？
请看上图，Eden区是4MB，两个Survivor中只有一个可以存放存活对象，另一个必须始终保持空闲。因此，考虑年轻代的可用空间时，就是Eden加上一个Survivor的大小，即4.5MB。
然后“4030K->512K”表示对年轻代执行了一次GC。在GC之前，已经使用了4030KB，但在GC之后，只有512KB的对象是存活下来的。
“0.0015734 secs”表示本次GC所花费的时间，从这个数据来看，大约花费了1.5毫秒，仅用于回收3MB的对象。
“4030K->574K(9728K), 0.0017518 secs”指的是整个Java堆内存的情况。
这意味着整个Java堆内存的总可用空间为9728KB（9.5MB），实际上是年轻代的4.5MB加上老年代的5MB。在GC之前，整个Java堆内存使用了4030KB，而在GC之后，Java堆内存使用了574KB。
“[Times: user=0.00 sys=0.00, real=0.00 secs]”表示本次GC消耗的时间。可以看到，这里的最小单位是小数点后两位，但全部都是0.00 secs，也就是说本次GC仅仅耗费了几毫秒，所以从秒为单位来看，几乎可以忽略不计。
当我们阅读到这里，可能会产生一些困惑，感觉与自己之前的认知存在差异。 请不要担心，保持冷静，继续阅读。接下来，我们将通过图解的方式，为大家详细展示这个GC（垃圾回收）过程的发生。
4、图解GC执行过程
首先，关于这行日志"ParNew: 4030K->512K(4608K), 0.0015734 secs"，它表示在执行了一次名为ParNew的垃圾回收（GC）操作后，内存使用量从4030KB减少到了512KB，总的可用内存是4608KB，而这次操作耗时0.0015734秒。
在GC之前，Eden区里放置了3个1MB的数组，总共3MB，即3072KB的对象。因此，你感到困惑的是，为什么年轻代在GC之前使用的是4030KB的内存，而不是3072KB。为了解决这个问题，我们需要理解两个关键点
- 当你创建了一个数组，尽管这个数组的大小是1MB，但是JVM在存储这个数组时，还会附带一些其他信息。这些信息可能包括对象头信息、对齐填充、以及其他与垃圾回收和内存管理相关的数据结构。因此，每个数组实际占用的内存大小会大于1MB。
- 年轻代中除了Eden区之外，还包括两个Survivor区。在GC发生之前，不仅Eden区可能有对象分配，而且Survivor区也可能有存活下来的对象。因此，年轻代的总内存使用量可能会超过仅考虑Eden区的情况下的预期值。
所以如下图所示，GC之前，三个数组和其他一些未知对象加起来，就是占据了4030KB的内存。
在Eden区域中，你尝试分配一个2MB的数组，这无疑会触发"Allocation Failure"，即对象分配失败。当这种情况发生时，就会引发Young GC。
随后，ParNew垃圾收集器开始执行垃圾回收操作，它会清理掉我们之前创建的三个数组。由于这些数组没有被任何对象引用，它们被视为垃圾对象，因此会被垃圾收集器回收。如下图所示。
接下来，我们继续分析GC日志，ParNew: 4030K->512K(4608K), 0.0015734 secs。在ParNew垃圾收集器的操作中，内存使用情况从4030K减少到512K，即回收了约3.5MB的内存，这一过程耗时0.0015734秒。
具体来说，这次垃圾收集之后，有512KB的对象在Eden区被认为足够重要而幸存下来，并被转移到了Survivor1区。在此过程中，我们可以对Survivor区的命名进行一些直观的修改。将原本的Survivor1区命名为"Survivor From"区，表示对象是从这个区域存活下来的；另一个Survivor区则可以称为"Survivor To"区，代表对象可能被复制到这个区域以备下次垃圾收集。如下图。
其实结合GC日志就能看出来，这就是本次GC的全过程。
5、GC过后的堆内存使用情况
接着我们看下面的GC日志：
Heap par new generation total 4608K, used 2601K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
eden space 4096K, 51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)
from space 512K, 100% used [0x00000000ffa80000, 0x00000000ffb00000, 0x00000000ffb00000)
to space 512K, 0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
concurrent mark-sweep generation total 5120K, used 62K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
Metaspace used 2782K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 300K, capacity 386K, committed 512K, reserved 1048576K
这段日志是在JVM退出的时候打印出来的当前堆内存的使用情况，其实也很简单，一点点看一下，先看下面这段。
par new generation total 4608K, used 2601K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
eden space 4096K, 51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)
from space 512K, 100% used [0x00000000ffa80000, 0x00000000ffb00000, 0x00000000ffb00000)
to space 512K, 0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
par new generation total 4608K, used 2601K，这就是说“ParNew”垃圾回收器负责的年轻代总共有4608KB（4.5MB）可用内存，目前是使用了2601KB（2.5MB）。
让我们来思考一个问题，在JVM退出之前，为什么年轻代会占用2.5MB的内存呢？
这个问题的答案其实很简单。我们通过以下代码在gc之后分配了一个2MB的数组：byte[] array2 = new byte[2 * 1024 * 1024];。因此，在Eden区中一定会有一个2MB的数组，也就是2048KB。然后，在上次gc之后，在From Survivor区中存活了一个512KB的对象，具体是什么我们暂时不用关心。
此时，你可能会有疑问，2048KB + 512KB = 2560KB，那为什么说年轻代使用了2601KB呢？
这是因为，每个数组在内存中除了存储数据之外，还会额外占用一些空间来存放该对象的元数据。所以，你可以认为多出来的41KB可能是数组对象额外使用的内存空间。如下图所示。
接着我们继续看GC日志：
eden space 4096K, 51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)
from space 512K, 100% used [0x00000000ffa80000, 0x00000000ffb00000, 0x00000000ffb00000)
to space 512K, 0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
通过GC日志，我们可以验证我们的推测是完全准确的。在这段文本中，我们清晰地说明了Eden区和From Survivor区的内存使用情况。
Eden区是一个4MB的内存空间，当前已经使用了51%，即2.04MB。这种高使用率是由于存在一个2MB的数组导致的。这个数组占据了Eden区的大部分空间。
接下来，我们来看From Survivor区。From Survivor区的大小为512KB，当前的使用率为100%。这意味着该区域的所有空间都被占用了。根据GC日志，我们可以推断出这些被占用的空间是由之前GC操作后存活下来的未知对象所占据的。
接着看GC日志：
concurrent mark-sweep generation total 5120K, used 62K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
Metaspace used 2782K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 300K, capacity 386K, committed 512K, reserved 1048576K
concurrent mark-sweep generation total 5120K, used 62K，这个很简单，就是说Concurrent Mark-Sweep垃圾回收器，也就是CMS垃圾回收器，管理的老年代内存空间一共是5MB，此时使用了62KB的空间，这个是啥你也先不用管了，可以先忽略不计，以后我们有内存分析工具了，你都能看到。
Metaspace used 2782K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 300K, capacity 386K, committed 512K, reserved 1048576K
上述两段日志也很简单，意思就是Metaspace元数据空间和Class空间，存放一些类信息、常量池之类的东西，此时他们的总容量，使用内存，等等。