【JVM】05. 性能调优（二）：GC日志分析

fangwei (56)in #study • 2 months ago

上一篇文章主要介绍了如何使用监控命令和工具来监控JVM的性能，而本篇则更侧重于通过GC日志来分析JVM的垃圾回收情况。这两篇文章的内容可以相互补充，帮助我们更全面地了解JVM的性能调优。

1 设置GC日志参数

GC日志的详细程度可以通过JVM启动参数进行设置。以下是一些常用的GC日志参数：

-Xloggc:./gc-%t.log：指定GC日志的输出文件。在这里，./ 表示日志文件将输出到当前目录。gc-%t.log 表示日志文件的命名规则，其中 %t 是一个时间戳，用于确保每次启动JVM时生成的日志文件名都是唯一的。
-XX:+PrintGCDetails：启用详细GC日志输出。这个参数会让JVM在GC发生时记录更多关于GC事件的信息，包括GC前后的内存使用情况、GC耗时等。
-XX:+PrintGCDateStamps：在GC日志中包含日期和时间戳。这样可以帮助分析者确定GC事件发生的具体时间。
-XX:+PrintGCTimeStamps：在GC日志中包含自JVM启动以来的相对时间戳。这对于分析GC事件的时间分布和频率很有用。
-XX:+PrintGCCause：打印导致GC发生的原因。这有助于理解为什么会触发GC，以及是否可以通过调整参数来优化GC触发的条件。
-XX:+UseGCLogFileRotation：启用GC日志文件的轮转。当日志文件达到一定大小时，JVM会自动创建新的日志文件，而不是覆盖旧的日志。
-XX:NumberOfGCLogFiles：设置轮转的GC日志文件数量。
-XX:GCLogFileSize：设置每个GC日志文件的最大大小。当文件大小达到这个限制时，JVM会创建新的日志文件，而旧的日志文件会被保留，直到达到-XX:NumberOfGCLogFiles指定的文件数量限制。

以下是GC日志参数设置示例：

-Xloggc:./gc-%t.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps  -XX:+PrintGCTimeStamps -XX:+PrintGCCause -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M

综合这些参数，JVM会在当前目录下生成以时间戳命名的GC日志文件，并保留最多10个文件，每个文件最大100MB。这些日志文件包含了详细的GC事件信息，包括日期和时间戳、GC原因等，对于性能分析和调优非常有用。

2 GC日志分析

运行microservice-eureka-server.jar，设置GC日志参数

java -jar -Xloggc:./gc-%t.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M microservice-eureka-server.jar

此时，会在当前路径下生成 gc-2024-05-09_23-14-17.log.0.current 文件，文件内会打印GC日志（默认使用UseParallelGC垃圾收集器，对于CMS和G1收集器的日志会有一点不一样）

GC日志-调整元空间参数前.png

GC日志中有两个比较重要的信息，一个是项目的配置参数。这里不仅包含GC日志参数，还有相关的VM内存参数，如下：

CommandLine flags: -XX:GCLogFileSize=104857600 -XX:InitialHeapSize=532373376 -XX:MaxHeapSize=8517974016 -XX:NumberOfGCLogFiles=10 -XX:+PrintGC -XX:+PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC

GC日志中另一个比较重要的信息就是GC时间点及GC之后相关内存情况，其中Full GC相关日志如下：

2024-05-09T23:14:19.331+0800: 2.305: [Full GC (Metadata GC Threshold) [PSYoungGen: 6925K->0K(151552K)] [ParOldGen: 131K->6749K(202752K)] 7056K->6749K(354304K), [Metaspace: 20760K->20760K(1069056K)], 0.0301181 secs] [Times: user=0.02 sys=0.00, real=0.03 secs]

对于2.305：这是从jvm启动开始计算到这次GC经过的时间，前面还有具体的发生时间日期。
Full GC(Metadata GC Threshold)指这是一次Full GC，括号里是GC的原因， PSYoungGen是年轻代的GC，ParOldGen是老年代的GC，Metaspace是元空间的GC
6925K->0K(151552K)，这三个数字分别对应GC之前占用年轻代的大小，GC之后年轻代占用，以及整个年轻代的大小。
131K->6749K(202752K)，这三个数字分别对应GC之前占用老年代的大小，GC之后老年代占用，以及整个老年代的大小。
7056K->6749K(354304K)，这三个数字分别对应GC之前占用堆内存的大小，GC之后堆内存占用，以及整个堆内存的大小。
20760K->20760K(1069056K)，这三个数字分别对应GC之前占用元空间的大小，GC之后元空间内存占用，以及整个元空间的大小。
0.0301181是该时间点GC总耗费时间。

从日志可以发现两次Full GC都是由于元空间不够导致的，所以我们可以考虑将元空间调大点，如下：

java -jar -Xloggc:./gc-adjust-%t.log -XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M microservice-eureka-server.jar

调整完之后重新启动重新，可以看到GC日志中已经没有因为元空间不够导致的Full GC了。

GC日志-调整元空间参数后.png