知优码

您现在的位置是:首页 > Java语言 > Java进阶

Java进阶

java虚拟机JVM第14讲:JVM参数之GC日志配置

知优码 2019-11-17Java进阶
说到 Java 虚拟机,不得不提的就是 Java 虚拟机的 GC(Garbage Collection)日志。而对于 GC 日志,我们不仅要学会看懂,而且要学会如何设置对应的 GC 日志参数。今天就让

说到 Java 虚拟机,不得不提的就是 Java 虚拟机的 GC(Garbage Collection)日志。而对于 GC 日志,我们不仅要学会看懂,而且要学会如何设置对应的 GC 日志参数。今天就让我们来学习一下 Java 虚拟机中所有与 GC 日志有关的参数。相信掌握了这些参数之后,对于大家线上打印 GC 日志是有不少帮助的。

为了能够更直观地显示出每个参数的作用,我们将以下面的 Demo 为例子去设置 GC 日志参数。

/**
 * @author 陈树义
 * @date 2018.09.29
 */
public class GCDemo {
    public static void main(String[] args) {
        // allocate 4M space
        byte[] b = new byte[4 * 1024 * 1024];
        System.out.println("first allocate");
        // allocate 4M space
        b = new byte[4 * 1024 * 1024];
        System.out.println("second allocate");
    }
}

在上面的程序中,我们两次分配了 4M 的内存空间。为了认为制造 GC,我们启动时的 JVM 参数固定加上下面几个参数:

-XX:+UseSerialGC -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8
  • -XX:+UseSerialGC 表示强制使用Serial+SerialOld收集器组合
  • -Xms20m 表示堆空间初始大小为 20 M。
  • -Xmx20m 表示堆空间最大大小为 20 M。
  • -Xmn10m 表示新生代大小为 10M。
  • -XX:SurvivorRatio=8 表示Eden:Survivor=8:1

经过上面这个设置,此时我们的堆空间的内存比例情况如下:Eden区 8M,FromSurvivor 1M,ToSurvivor 1M,老年代 10M。

下面就让我们来看看油管 GC 的参数有哪些吧。

打印GC日志

在 GC 日志参数中,最简单的一个参数就是打印 GC 日志:-XX:PrintGC。我们用下面的命令运行程序:

java -XX:+UseSerialGC -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8 -XX:+PrintGC com.chenshuyi.GCDemo

输出结果:

first allocate
second allocate
[GC (Allocation Failure)  4767K->4374K(19456K), 0.0045179 secs]

可以看到程序在第一次分配数组空间的时候发生了 GC,并且把 GC 前后以及堆空间大小都打印了出来。该日志显示 GC 前堆空间使用量为 4767K(4M左右)。GC 后堆空间为 4374K,当前可用堆大小为 19456K。

但你会发现使用 PrintGC 参数打印出来的日志比较简单,无法查看更详细的信息。如果你要查看更详细的信息,那么就需要下面这个参数。

打印详细GC日志

如果要查看更加详细的 GC 日志,那么就要使用 -XX:+PrintGCDetils 参数。下面我们使用该参数运行程序:

java -XX:+UseSerialGC -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8 -XX:+PrintGC com.chenshuyi.GCDemo

程序输出:

first allocate
second allocate
[GC (Allocation Failure) [DefNew: 4603K->278K(9216K), 0.0036744 secs] 4603K->4374K(19456K), 0.0037100 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Heap
 def new generation   total 9216K, used 4538K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  52% used [0x00000007bec00000, 0x00000007bf0290e0, 0x00000007bf400000)
  from space 1024K,  27% used [0x00000007bf500000, 0x00000007bf545920, 0x00000007bf600000)
  to   space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)
 tenured generation   total 10240K, used 4096K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
   the space 10240K,  40% used [0x00000007bf600000, 0x00000007bfa00010, 0x00000007bfa00200, 0x00000007c0000000)
 Metaspace       used 2649K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 286K, capacity 386K, committed 512K, reserved 1048576K

从上面的日志可以看出,该参数能打印出更加详细的 GC 信息,包括:年轻代的信息、永久代的信息。

[GC (Allocation Failure) [DefNew: 4603K->278K(9216K), 0.0036744 secs] 4603K->4374K(19456K), 0.0037100 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

该参数还会在退出之前打印出整个堆的详细信息:

Heap
 def new generation   total 9216K, used 4538K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  52% used [0x00000007bec00000, 0x00000007bf0290e0, 0x00000007bf400000)
  from space 1024K,  27% used [0x00000007bf500000, 0x00000007bf545920, 0x00000007bf600000)
  to   space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)
 tenured generation   total 10240K, used 4096K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
   the space 10240K,  40% used [0x00000007bf600000, 0x00000007bfa00010, 0x00000007bfa00200, 0x00000007c0000000)
 Metaspace       used 2649K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 286K, capacity 386K, committed 512K, reserved 1048576K

GC前后打印堆信息

上面两个命令基本上可以应付 90% 的使用场景了,但有时候我们在 GC 前后还想获取更加详细的信息。那么我们可以使用 PrintHeapAtGC 参数,该参数会在 GC 前后打印堆信息。

使用下面的命令运行程序:

java -XX:+UseSerialGC -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8 -XX:+PrintHeapAtGC com.chenshuyi.GCDemo

输出结果:

first allocate
second allocate
{Heap before GC invocations=0 (full 0):
 def new generation   total 9216K, used 4767K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  58% used [0x00000007bec00000, 0x00000007bf0a7e98, 0x00000007bf400000)
  from space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)
  to   space 1024K,   0% used [0x00000007bf500000, 0x00000007bf500000, 0x00000007bf600000)
 tenured generation   total 10240K, used 0K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
   the space 10240K,   0% used [0x00000007bf600000, 0x00000007bf600000, 0x00000007bf600200, 0x00000007c0000000)
 Metaspace       used 2646K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 286K, capacity 386K, committed 512K, reserved 1048576K
Heap after GC invocations=1 (full 0):
 def new generation   total 9216K, used 278K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,   0% used [0x00000007bec00000, 0x00000007bec00000, 0x00000007bf400000)
  from space 1024K,  27% used [0x00000007bf500000, 0x00000007bf545950, 0x00000007bf600000)
  to   space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)
 tenured generation   total 10240K, used 4096K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
   the space 10240K,  40% used [0x00000007bf600000, 0x00000007bfa00010, 0x00000007bfa00200, 0x00000007c0000000)
 Metaspace       used 2646K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 286K, capacity 386K, committed 512K, reserved 1048576K
}

仔细看一下,会发现在 GC 发生前后都打印了一次堆空间信息。

通过这个参数,我们可以详细了解每次 GC 时堆空间的详细信息。

打印GC发生的时间 -XX:+PrintGCTimeStamps

这个参数非常简单,就是在每次 GC 日志的前面加上一个时间戳。这个时间戳表示 JVM 启动后到现在所逝去的时间。

使用下面的参数运行程序:

java -XX:+UseSerialGC -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8 -XX:+PrintGC -XX:+PrintGCTimeStamps com.chenshuyi.GCDemo

输出结果:

first allocate
second allocate
0.130: [GC (Allocation Failure)  4767K->4374K(19456K), 0.0051351 secs]

上面日志第 3 行中的「0.130」就是该 GC 发生的时间。

-XX:+PrintGCApplicationConcurrentTime 打印应用程序的执行时间

使用下面的命令运行程序:

java -XX:+UseSerialGC -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8 -XX:+PrintGC -XX:+PrintGCApplicationConcurrentTime com.chenshuyi.GCDemo

运行结果:

first allocate
second allocate
Application time: 0.0371892 seconds
[GC (Allocation Failure)  4767K->4374K(19456K), 0.0040074 secs]
Application time: 0.0010712 seconds

-XX:+PrintGCApplicationStoppedTime 打印应用由于GC而产生的停顿时间

使用下面的命令运行程序:

java -XX:+UseSerialGC -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8 -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime com.chenshuyi.GCDemo

运行结果:

first allocate
second allocate
[GC (Allocation Failure)  4767K->4374K(19456K), 0.0045644 secs]
Total time for which application threads were stopped: 0.0047873 seconds, Stopping threads took: 0.0000329 seconds

可以看到最后一行打印出了因为 GC 而暂停的时间。

保存GC日志 -Xloggc

这个参数可以将 GC 日志输出到文件中保存起来。

使用下面的参数运行程序:

java -XX:+UseSerialGC -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8 -XX:+PrintGC -XX:+PrintReferenceGC -Xloggc:gc.log com.chenshuyi.GCDemo

运行之后在本目录会生成一个 gc.log 文件,打开该文件:

Java HotSpot(TM) 64-Bit Server VM (25.181-b13) for bsd-amd64 JRE (1.8.0_181-b13), built on Jul  7 2018 01:02:31 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 8388608k(45132k free)

/proc/meminfo:

CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:NewSize=10485760 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+PrintReferenceGC -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseSerialGC 
0.124: [GC (Allocation Failure)  4767K->4374K(19456K), 0.0047748 secs]

可以看到堆的相关信息,以及 GC 的信息。

总结

除了上面这些参数,还有可以查看弱引用的参数:-XX:+PrintReferenceGC。它跟踪软引用、弱引用、虚引用和Finallize队列的信息,但是使用场景较为狭窄。基本上掌握上面的几个常用的 GC 日志参数就足够排查使用,最重要的是弄清楚每个参数的作用和用法。

最后用列表的形式总结一下,加深一下印象。

参数 含义
-XX:PrintGC 打印GC日志
-XX:+PrintGCDetails 打印详细的GC日志。还会在退出前打印堆的详细信息。
-XX:+PrintHeapAtGC 每次GC前后打印堆信息。
-XX:+PrintGCTimeStamps 打印GC发生的时间。
-XX:+PrintGCApplicationConcurrentTime 打印应用程序的执行时间
-XX:+PrintGCApplicationStoppedTime 打印应用由于GC而产生的停顿时间
-XX:+PrintReferenceGC 跟踪软引用、弱引用、虚引用和Finallize队列。
-XLoggc 将GC日志以文件形式输出。