一文教你如何打印及分析JVM的GC日志

JVM GC日志格式
JVM GC日志含义
- JVM GC日志分析方法
- - 开启JVM-GC日志的启动参数
  - GC查看案例
  - - JVM参数解析
    - 配置JVM参数
    - 对象是如何分配在Eden区
    - - 内存区域分析
      - 初始化数组对象
- 结论

当我们在开发Java应用程序时，JVM的GC（垃圾回收）是一个非常重要的话题。GC的作用是回收不再使用的内存，以便程序可以继续运行。在JVM中，GC的日志记录了GC的详细信息，包括GC的类型、时间、内存使用情况等。在本文中，我们将介绍JVM GC日志的格式、含义和分析方法。

JVM GC日志格式

JVM GC日志的格式通常是一系列以时间戳为基础的事件，每个事件都包含了GC的详细信息。以下是一个典型的JVM GC日志的示例：

2021-01-01T00:00:00.000+0800: 1.000: [GC (Allocation Failure) 1.000: 1024K->512K(4096K), 0.0010000 secs]

其中，时间戳的格式为[ISO 8601]，GC类型为“GC (Allocation Failure)”，GC发生的时间为1.000秒，GC前后内存使用情况分别为1024K和512K，总内存为4096K，GC耗时为0.001秒。

JVM GC日志含义

JVM GC日志包含了大量的信息，可以帮助我们了解JVM的内存使用情况和GC的性能。以下是一些常见的GC日志含义：

GC类型：GC的类型，如“GC (Allocation Failure)”表示由于内存分配失败而触发的GC。
时间戳：GC发生的时间戳，通常是以秒为单位的浮点数。
内存使用情况：GC前后内存使用情况，包括已使用内存、总内存等。
GC耗时：GC的耗时，通常是以秒或毫秒为单位的浮点数。

JVM GC日志分析方法

JVM GC日志的分析可以帮助我们了解JVM的内存使用情况和GC的性能，以便优化应用程序的性能。以下是一些常见的JVM GC日志分析方法：

使用GCViewer等工具：GCViewer是一款免费的GC日志分析工具，可以帮助我们可视化地分析JVM GC日志。使用GCViewer可以轻松地查看GC的类型、时间、内存使用情况等。
分析GC日志文件：我们可以使用文本编辑器等工具来分析GC日志文件。通过分析GC日志文件，我们可以了解GC的类型、时间、内存使用情况等，以便优化应用程序的性能。
调整GC参数：通过调整JVM的GC参数，我们可以优化GC的性能，以便提高应用程序的性能。例如，我们可以通过调整-Xmx和-Xms参数来调整JVM的堆大小，以便优化GC的性能。

开启JVM-GC日志的启动参数

如果需要打印GC日志，那么首先得把JVM-GC日志进行输出到本地文件，一般我们会在JVM启动的时候添加参数：
- -XX:+PrintGCDetails：打印GC日志细节
- -XX:+PrintGCTimeStamps：打印GC日志时间
- -Xloggc:gc_view.log：将GC日志输出到指定的磁盘文件上去，这里会把gc.log输出到项目根路径
当JVM在运行过程中如果发生GC，那么将会把GC日志输出到gc_view.log中。

GC查看案例

JVM参数中加入GC日志的打印选型，jvm参数如下所示：

-XX:NewSize=5242880 -XX:MaxNewSize=5242880 -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10485760 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+
PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log

JVM参数解析

配置JVM参数

-XX:NewSize=5242880 ：初始新生代大小
-XX:MaxNewSize=5242880：最大新生代大小
-XX:InitialHeapSize=10485760：初始堆大小
-XX:MaxHeapSize=10485760：最大堆大小
-XX:SurvivorRatio=8：Eden区就是Survivor区的8倍，所以Eden区占4M，两个Survivor都是占0.5M。
-XX:MaxTenuringThreshold=15：那么新生代对象只有达到15岁才会进入老年代。
-XX:PretenureSizeThreshold=10485760：指定了大对象阈值是10MB，那么只有大于10M的对象才能直接在老年代分配
-XX:+UseParNewGC：使用ParNew
-XX:+UseConcMarkSweepGC：CMS垃圾回收器

-XX:+PrintGCDetails：打印详细的gc日志
-XX:+PrintGCTimeStamps：这个参数可以打印出来每次GC发生的时间
-Xloggc:gc.log：这个参数可以设置将gc日志写入一个磁盘文件。

对象是如何分配在Eden区

我们针对于上述代码的内存进行分析，最开始我们定义和初始化了字节数组：new byte[1024 * 1024]，并且对于同一个引用，我们分配了3个相同大小的字节数组，每个数组都是1MB。

public static void main(String[] args) {
    byte[] arrayInit = new byte[1024 * 1024];
    arrayInit = new byte[1024 * 1024];
    arrayInit = null;
    //触发Young GC
    byte[] arrayInit2 = new byte[2 * 1024 * 1024];
}

内存区域分析

定义array1这个局部变量依次引用这三个对象，最后还把 array1 这个局部变量指向了null，那么在JVM中是如何运行的呢？

初始化数组对象

byte[] arrayInit = new byte[1024 * 1024];。

在JVM的Eden区内存储一个1MB的对象，同时在main线程的栈中会压入一个main方法的栈帧，在main方法的栈帧内部，会有一个“arrayInit ”变量，这个变量是指向堆内存Eden区的那个1MB的数组。
在这里插入图片描述接着我们看第二行代码

arrayInit = new byte[1024 * 1024];

当执行了这行代码之后，便会在堆中的Eden区中再次分配一个数组，并且让之前的局部变量指向第二个数组，然后第一个数组就没人引用了，此时第一个数组就成了没人引用的“垃圾对象”了，如下图所示。
在这里插入图片描述接着我们来看第三行代码：array1 = null; 这行代码一执行，就让arrayInit 这个变量什么都不指向了，此时会导致之前创建的2个数组全部变成垃圾对象，如下图。
在项目的根路径下，就可以看到一个gc.log，点进去查看：

0.383: [GC (Allocation Failure) 0.384: [ParNew: 3543K->512K(4608K), 0.0024598 secs] 3543K->1828K(9728K), 0.0026607 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.386: [GC (Allocation Failure) 0.387: [ParNew: 2627K->0K(4608K), 0.0015255 secs] 3943K->1828K(9728K), 0.0015985 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Heap
 par new generation   total 4608K, used 2089K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)
  from space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
  to   space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
 concurrent mark-sweep generation total 5120K, used 1828K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3101K, capacity 4620K, committed 4864K, reserved 1056768K
  class space    used 327K, capacity 392K, committed 512K, reserved 1048576K

从上面内容中可以看到进行了两次GC。

0.383: [GC (Allocation Failure)
0.384: [ParNew: 3543K->512K(4608K), 0.0024598 secs] 3543K->1828K(9728K), 0.0026607 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

从上面的内容可以得出：

在第0.383秒，发生Allocation Failure，就是给对象分配内存的时候内存空间不够了，
- [ParNew: 3543K->512K(4608K),0.0024598 secs]
  - 新生代的总内存大小为4608KB（4M的Eden区加上了 0.5M的Survivor From区，一共是4.5M，即4608M）；
  - Young GC之前，新生代占用内存大小为3543KB（三个1M的数组，加上471KB的“未知内容”）；
  - Young GC之后，剩余了512KB（“未知内容”）。
在第0.384秒的时候，使用ParNew垃圾回收器进行了Young GC。
- 3543K->1828K(9728K)
  - 整个堆内存大小为9728KB（即4M的Eden区加上0.5M的Survivor区加上5M的老年代大小，9.5M，即9728KB）。
  - 在Young GC之前，堆内存共有3543KB内存被占用（三个1M的数组，加上471KB的“未知内容”）；
  - 在Young GC之后，堆内存共有1828KB。

0.386: [GC (Allocation Failure) 
0.387: [ParNew: 2627K->0K(4608K), 0.0015255 secs] 3943K->1828K(9728K), 0.0015985 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

之后输出了Young GC之后的堆内存使用快照：

Heap
 par new generation   total 4608K, used 2089K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)
  from space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
  to   space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
 concurrent mark-sweep generation total 5120K, used 1828K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3101K, capacity 4620K, committed 4864K, reserved 1056768K
  class space    used 327K, capacity 392K, committed 512K, reserved 1048576K

可以看到新生代占用了2098KB（一个2M的数组，还有一点“未知内容”）；Eden区被占用了51%，Survivor From和Survivor To使用率为0%，CMS管理的老年代被使用了1828KB。

结论

JVM GC日志是一个非常重要的话题，可以帮助我们了解JVM的内存使用情况和GC的性能。通过分析JVM GC日志，我们可以优化应用程序的性能，提高应用程序的稳定性和可靠性。

在这里，我向大家推荐一本关于JVM优化和调优的实战系列书籍，《深入浅出Java虚拟机 — JVM原理与实战》。这本书是最新出版的，内容涵盖了与我们当前工作和开发实例密切相关的技术和实战案例。通过学习这本书，我们可以深入了解Java虚拟机的原理，并通过实践掌握优化和调优的技巧。我诚挚地推荐这本书给大家，相信它将为我们的工作和技术发展带来巨大的收益。希望大家能够抽出时间多多学习一下这本宝贵的资料。

【当当-点击链接】【京东-点击链接】