java gc 日志_JVM基础系列第14讲:JVM参数之GC日志配置

博主个人独立站点开通啦!欢迎点击访问:https://shuyi.tech

说到 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:+PrintGCDetails 参数。下面我们使用该参数运行程序:

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 发生前后都打印了一次堆空间信息。

38e37527e9a6214c8fda2bab6515deb9.png

通过这个参数,我们可以详细了解每次 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日志以文件形式输出。

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值