博客

如何分析GC日志？

  • Post category:Java

如何分析GC日志？

GC日志的产生

在Java运行时，当内存分配器发现无法找到足够内存空间给新对象分配时，就会导致GC的发生。在GC进行时，JVM会对应用程序进行暂停，去回收无用内存对象。产生的GC日志记录了每次GC的信息和GC期间堆的使用情况。

记录GC日志

我们可以通过以下命令记录GC日志：

java -XX:+PrintGC -XX:+PrintGCDetails -Xloggc:<log_file_path> YourProgram

其中：

  • -XX:+PrintGC：打印GC信息。
  • -XX:+PrintGCDetails：打印GC详细信息。
  • -Xloggc:<log_file_path>：将GC日志记录到指定文件中。

GC日志分析

1. 分析GC类型

GC类型有很多种，每种都有自己的影响和解决方法。我们可以通过GC日志中的以下字段来确定GC类型：

  • Full GC
  • Minor GC
  • Major GC
  • Concurrent GC
  • Serial GC
  • Parallel GC
  • G1GC

下面介绍以下几种类型的GC：

  • Minor GC：一般是指Young Generation区域的GC，收集年轻代的对象。通过GC日志可以看到[GC (Allocation Failure)]，这种情况是分配内存空间失败导致的GC。
  • Major GC：指Old Generation区域的GC，收集老年代的对象。
  • Full GC：是对整个Java堆的清理，包括Young Gen、Tenured Gen（也就是老年代）以及Perm Gen区域（永久代）的GC。

2. 分析GC时间和原因

在GC日志中，我们可以看到诸如以下信息，通过向前跟踪，我们可以确认GC时间和原因。

2021-04-27T12:48:58.456+0800: 1.030: [GC (Allocation Failure) 1.032: [ParNew: 34155K->3775K(38336K), 0.0051219 secs] 34155K->9435K(123904K), 0.0052869 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

我们可以看到，GC发生在2021-04-27T12:48:58.456+0800时刻，由于空间分配失败（Allocation Failure）导致的GC。

3. 分析GC前后堆内存状况

通过GC日志，我们可以采集到GC发生时Young Gen和Old Gen的大小、使用空间、总空间等信息，从而查看GC前后堆内存的变化情况，这对于我们了解程序内的内存使用情况非常重要。

2021-04-27T12:48:58.462+0800: 1.035: [GC (Allocation Failure) 1.036: [ParNew: 38336K->3466K(38336K), 0.0034323 secs] 78827K->60557K(207872K), 0.0035211 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

在以上GC日志中，我们可以看到Young Gen由原来的38M变成了3.4M，Old Gen由原来的78.8M变成了60.5M，总堆内存从207.9M变成了20.7M，这表明该场景下发生了大量的内存回收，程序的内存使用过于频繁。

示例说明

示例1

2021-04-27T13:08:51.583+0800: 359.358: [GC (Allocation Failure) 359.358: [PSYoungGen: 461760K->16833K(471872K)] 553086K->126234K(1544192K), 0.0449684 secs] [Times: user=0.08 sys=0.05, real=0.05 secs]

以下是该GC日志的分析：

  • GC发生在2021-04-27T13:08:51.583+0800时刻。
  • 此GC为Young Gen的GC，分配失败导致的GC。
  • Young Gen在GC前（461760K）与GC后（16833K）的差额为444927K，总容量为471872K。
  • JVM堆总容量在GC前（553086K）与GC后（126234K）的差额为426852K，总容量为1544192K。

从以上分析中，可以看到Young Gen的使用空间在短暂时间内急剧增加，尤其在分配内存的时候，很容易达到Young Gen的额定容量，因此需要关注程序的内存使用情况。

示例2

2021-04-27T14:18:11.284+0800: 4469.047: [Full GC (Metadata GC Threshold) [PSYoungGen: 0K->0K(87296K)] [ParOldGen: 139950K->141324K(139776K)] 139950K->141324K(227072K), [Metaspace: 30784K->30784K(1089536K)], 0.2603214 secs] [Times: user=0.55 sys=0.00, real=0.26 secs]

以下是该GC日志的分析：

  • GC发生在2021-04-27T14:18:11.284+0800时刻。
  • 此GC为Full GC，扫描了整个Java堆内存。
  • 整个堆的使用空间在GC前（139950K）和GC后（141324K）没有太大变化。
  • Java堆最大容量为227072K。

从以上分析中，可以看到整个Java堆内存扫描花费的时间（0.2603214秒），因此需要深入了解该场景的具体耗时和内存占用原因。

Tags: