如何读懂Java GC日志

Java应用程序的GC日志对分析定位很多性能问题有着非常大的帮助。默认情况下，Java应用程序不会自动产生GC日志。如果需要输出GC日志，必须在JVM启动时增加对应的参数，场景的参数如表5-8所示。

2. GC日志分析一

例如，在Tomcat的JVM启动参数中加入参数：-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:..\logs\gc.log，在Tomcat运行后即可在logs目录下生成对应的GC日志，如图5-3-1所示。

输出的GC日志内容如下：

Java HotSpot(TM) 64-Bit Server VM (25.101-b13) for windows-amd64 JRE (1.8.0_101-b13), built on Jun 22 2016 01:21:29 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8078128k(2694664k free), swap 16154412k(4180772k free)
CommandLine flags: -XX:InitialHeapSize=129250048 -XX:+ManagementServer -XX:MaxHeapSize=2068000768 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 36864K, used 31744K [0x00000000d6e00000, 0x00000000d9700000, 0x0000000100000000)
  eden space 31744K, 100% used [0x00000000d6e00000,0x00000000d8d00000,0x00000000d8d00000)
  from space 5120K, 0% used [0x00000000d9200000,0x00000000d9200000,0x00000000d9700000)
  to   space 5120K, 0% used [0x00000000d8d00000,0x00000000d8d00000,0x00000000d9200000)
 ParOldGen       total 84992K, used 0K [0x0000000084a00000, 0x0000000089d00000, 0x00000000d6e00000)
  object space 84992K, 0% used [0x0000000084a00000,0x0000000084a00000,0x0000000089d00000)
 Metaspace       used 13952K, capacity 14326K, committed 14592K, reserved 1062912K
  class space    used 1560K, capacity 1705K, committed 1792K, reserved 1048576K
2020-02-14T15:34:30.245+0800: 1.292: [GC (Allocation Failure) [PSYoungGen: 31744K->5104K(36864K)] 31744K->7267K(121856K), 0.0131568 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
Heap after GC invocations=1 (full 0):
 PSYoungGen      total 36864K, used 5104K [0x00000000d6e00000, 0x00000000d9700000, 0x0000000100000000)
  eden space 31744K, 0% used [0x00000000d6e00000,0x00000000d6e00000,0x00000000d8d00000)
  from space 5120K, 99% used
[0x00000000d8d00000,0x00000000d91fc040,0x00000000d9200000)
  to   space 5120K, 0% used [0x00000000d9200000,0x00000000d9200000,0x00000000d9700000)
 ParOldGen       total 84992K, used 2163K [0x0000000084a00000, 0x0000000089d00000, 0x00000000d6e00000)
  object space 84992K, 2% used [0x0000000084a00000,0x0000000084c1ce70,0x0000000089d00000)
 Metaspace       used 13952K, capacity 14326K, committed 14592K, reserved 1062912K
  class space    used 1560K, capacity 1705K, committed 1792K, reserved 1048576K
}

……

{Heap before GC invocations=8 (full 0):
 PSYoungGen      total 144896K, used 88289K [0x00000000d6e00000, 0x00000000e9700000, 0x0000000100000000)
  eden space 125440K, 54% used [0x00000000d6e00000,0x00000000db13e380,0x00000000de880000)
  from space 19456K, 99% used [0x00000000de880000,0x00000000dfb7a2b0,0x00000000dfb80000)
  to   space 26624K, 0% used [0x00000000e7d00000,0x00000000e7d00000,0x00000000e9700000)
 ParOldGen       total 84992K, used 39157K [0x0000000084a00000, 0x0000000089d00000, 0x00000000d6e00000)
  object space 84992K, 46% used [0x0000000084a00000,0x000000008703d6c8,0x0000000089d00000)
 Metaspace       used 20699K, capacity 21010K, committed 21248K, reserved 1069056K
  class space    used 2353K, capacity 2457K, committed 2560K, reserved 1048576K
2020-02-14T15:34:35.879+0800: 6.926: [GC (Metadata GC Threshold) [PSYoungGen: 88289K->14355K(274432K)] 127447K->53769K(359424K), 0.1285266 secs] [Times: user=0.48 sys=0.02, real=0.13 secs] 
Heap after GC invocations=8 (full 0):
 PSYoungGen      total 274432K, used 14355K [0x00000000d6e00000, 0x00000000e9400000, 0x0000000100000000)
  eden space 250880K, 0% used [0x00000000d6e00000,0x00000000d6e00000,0x00000000e6300000)
  from space 23552K, 60% used [0x00000000e7d00000,0x00000000e8b04f28,0x00000000e9400000)
  to   space 25088K, 0% used [0x00000000e6300000,0x00000000e6300000,0x00000000e7b80000)
 ParOldGen       total 84992K, used 39413K [0x0000000084a00000, 0x0000000089d00000, 0x00000000d6e00000)
  object space 84992K, 46% used [0x0000000084a00000,0x000000008707d6d8,0x0000000089d00000)
 Metaspace       used 20699K, capacity 21010K, committed 21248K, reserved
 1069056K
  class space    used 2353K, capacity 2457K, committed 2560K, reserved 1048576K
}
{Heap before GC invocations=9 (full 1):
 PSYoungGen      total 274432K, used 14355K [0x00000000d6e00000, 0x00000000e9400000, 0x0000000100000000)
  eden space 250880K, 0% used [0x00000000d6e00000,0x00000000d6e00000,0x00000000e6300000)
  from space 23552K, 60% used [0x00000000e7d00000,0x00000000e8b04f28,0x00000000e9400000)
  to   space 25088K, 0% used [0x00000000e6300000,0x00000000e6300000,0x00000000e7b80000)
 ParOldGen       total 84992K, used 39413K [0x0000000084a00000, 0x0000000089d00000, 0x00000000d6e00000)
  object space 84992K, 46% used [0x0000000084a00000,0x000000008707d6d8,0x0000000089d00000)
 Metaspace       used 20699K, capacity 21010K, committed 21248K, reserved 1069056K
  class space    used 2353K, capacity 2457K, committed 2560K, reserved 1048576K
2020-02-14T15:34:36.007+0800: 7.054: [Full GC (Metadata GC Threshold) [PSYoungGen: 14355K->0K(274432K)] [ParOldGen: 39413K->32862K(83456K)] 53769K->32862K(357888K), [Metaspace: 20699K->20699K(1069056K)], 0.1843152 secs] [Times: user=0.62 sys=0.00, real=0.18 secs] 
Heap after GC invocations=9 (full 1):
 PSYoungGen      total 274432K, used 0K [0x00000000d6e00000, 0x00000000e9400000, 0x0000000100000000)
  eden space 250880K, 0% used [0x00000000d6e00000,0x00000000d6e00000,0x00000000e6300000)
  from space 23552K, 0% used [0x00000000e7d00000,0x00000000e7d00000,0x00000000e9400000)
  to   space 25088K, 0% used [0x00000000e6300000,0x00000000e6300000,0x00000000e7b80000)
 ParOldGen       total 83456K, used 32862K [0x0000000084a00000, 0x0000000089b80000, 0x00000000d6e00000)
  object space 83456K, 39% used [0x0000000084a00000,0x0000000086a17ba0,0x0000000089b80000)
 Metaspace       used 20699K, capacity 21010K, committed 21248K, reserved 1069056K
  class space    used 2353K, capacity 2457K, committed 2560K, reserved 1048576K
}

从日志中可以看到年轻代的垃圾回收和年老代的垃圾回收情况，并且在垃圾回收执行的前后都输出了堆内存的使用情况。

（1）“Java HotSpot(TM) 64-Bit Server VM (25.101-b13) for windows-amd64 JRE (1.8.0_101-b13), built on Jun 22 2016 01:21:29 by "java_re" with MS VC++ 10.0 (VS2010)”这一段输出了JVM虚拟机的版本以及当前JVM的运行环境。

（2）“Memory: 4k page, physical 8078128k(2694664k free), swap 16154412k(4180772k free)”这一段输出了操作系统的物理内存和虚拟内存的总量以及使用情况。

（3）“CommandLine flags: -XX:InitialHeapSize=129250048 -XX:+ManagementServer -XX:Max
HeapSize=2068000768 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:
+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+UseCompressedClassPointers -XX:+
UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC”这一段输出了JVM的GC垃圾回收器信息以及GC日志的打印参数。

2. GC日志分析二

如图5-3-2所示是JVM中一次年轻代内存区域GC垃圾回收的输出日志，一次完整的GC日志一般被一个“{}”所包括。

（1）“Heap before GC invocations=1 (full 0)”描述了发生了一次GC垃圾回收，“full 0”表示发生了0次Full GC，在之后描述了发生GC垃圾回收之前和之后年轻代区域（PSYoungGen）、eden区域（eden space）、From Survivor空间区域（from space）、To Survivor空间区域（to space）、年老代区域（ParOldGen）、元数据区域（Metaspace）、class space 的内存空间使用情况。

（2）“2020-02-14T15:34:30.245+0800: 1.292: [GC (Allocation Failure) [PSYoungGen: 31744K->5104K(36864K)] 31744K->7267K(121856K), 0.0131568 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]”描述了在2020-02-14T15:34:30.245这个时间发生了一次年轻代GC垃圾回收、GC发生原因是Allocation Failure（年轻代中没有足够的空间能够存储新的数据了）、GC发生时年轻代内存使用从31744KB减少为5104KB（[PSYoungGen: 31744K->5104K(36864K)]）、GC发生时堆内存的总使用从31744KB减少为7267KB（31744K->7267K(121856K)）、GC总耗时时长为0.0131568秒、用户耗时0.03秒、系统耗时0.01秒、实际耗时0.01秒。

本文节选自《软件性能测试、分析与调优实践之路（第2版）》，获作者和出版社授权发布。