April 7, 2019 · JAVA 本文字数: 1.9k 阅读时长:9 min 全站字数:361.8k

GC日志阅读

  1. GC日志格式
  2. GC日志实验
    1. 内存分配代码
    2. JDK8的JVM参数说明
    3. GC日志分析
  3. 参考资料

GC日志格式

JDK8的GC日志可以通过+PrintGCDetails开启。以ParallelGC为例,YoungGC日志解释如下图所示:

YoungGC日志

FullGC日志

GC日志实验

内存分配代码

分配内存的示例Java代码:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
package name.zhangmin.gc;

/**
* @author zhangmin
* @date 2019/4/7
*/
public class GCLogTest {
private static final int MB = 1024 * 1024;

public static void testAllocation() {
byte[] a1, a2, a3, a4, a5;
a1 = new byte[2 * MB];
a2 = new byte[2 * MB];
a3 = new byte[2 * MB];
a4 = new byte[4 * MB];
a5 = new byte[10 * MB];
}

public static void main(String[] args) {
GCLogTest.testAllocation();
}
}

JDK8的JVM参数说明

JDK8默认启动参数:-Xms2048M -Xmx2048M -XX:+PrintGC -Xloggc:/log/Jdk7GC.GCDeatil.log

  • 垃圾回收器的名称:Parallel Scavenge (PS Scavenge)(新生代)
  • 垃圾回收器的名称:Parallel Old (PS MarkSweep) (老年代)
  • 等于启动参数使用 -XX:+UseParallelOldGC

GC日志相关的命令行参数:

  1. -verbose:gcGC日志开关。打开后可以显示最忙和最空闲收集行为发生的时间、收集前后的内存大小、收集需要的时间等。
  2. -XX:+PrintGCdetailsGC的详细信息。
  3. -XX:+PrintGCTimeStamps垃圾收集发生的时间,自JVM启动以后以秒计量。
  4. -XX:+PrintHeapAtGC了解堆的更详细的信息。
  5. -XX:+PrintTenuringDistribution了解获得使用期的对象权。
  6. -Xloggc:$CATALINA_BASE/logs/gc.log GC日志产生的路径
  7. -XX:+PrintGCApplicationStoppedTimeGC造成应用暂停的时间
  8. -XX:+PrintGCDateStampsGC发生的时间信息

JVM内存相关的配置参数:

  1. -Xms:初始堆大小,默认为物理内存的1/64(<1GB);默认(MinHeapFreeRatio参数可以调整)空余堆内存小于40%时,JVM就会增大堆直到-Xmx的最大限制
  2. -Xmx:最大堆大小,默认(MaxHeapFreeRatio参数可以调整)空余堆内存大于70%时,JVM会减少堆直到 -Xms的最小限制
  3. -Xmn:新生代的内存空间大小,注意:此处的大小是(eden+ 2 survivor space)。与jmap -heap中显示的New gen是不同的。整个堆大小=新生代大小 + 老生代大小 + 永久代大小
  4. -XX:SurvivorRatio:新生代中Eden区域与Survivor区域的容量比值,默认值为8。两个Survivor区与一个Eden区的比值为2:8,一个Survivor区占整个年轻代的1/10。
  5. -Xss:每个线程的堆栈大小
  6. -XX:PermSize:设置永久代(perm gen)初始值。默认值为物理内存的1/64。
  7. -XX:MaxPermSize:设置持久代最大值。物理内存的1/4。

程序运行的JVM参数:

1
java -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+PrintHeapAtGC name.zhangmin.gc.GCLogTest

参数-Xms20M -Xmx20M -Xmn10M这3个参数限制了Java堆大小为20MB,不可扩展,其中10MB分配给新生代,剩下的10MB分配给老年代。

参数-XX:SurvivorRatio=8定义了新生代中Eden区与一个Survivor区的空间比例是8:1,从输出结果也可以清晰的看到”eden space 8192K、from space 1024K、to space 1024K”的信息,新生代总可用空间为9216KB(Eden区+1个Survivor区的总容量)。

当分配对象a4时发生一次Minor GC,因为分配的内存已经超过了新生代的大小总数9216KB。

日志最开始的GC和Full GC表示垃圾回收的停顿类型;
PSYoungGen中最前面的PS代表垃圾收集器是Parallel Scavenge收集器,回收的区域是新生代(YoungGen);
ParOldGen中最前面的Par代表垃圾收集器是Parallel Old收集器,回收的区域是老年代(OldGen);

另外需要注意的是,并行收集器组合 Parallel Scavenge + Parallel Old年轻代采用复制算法,老年代采用标记-整理,会在回收的同时还会对内存进行压缩。

GC日志分析

第一次垃圾回收:新生代内存占用从7197K降到了864K, 总内存占用从7197K降到了4968K.
空间减少是由于老年代会进行内存的整理压缩,从而降低内存占用.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24

{Heap before GC invocations=1 (full 0):
PSYoungGen total 9216K, used 7197K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
 eden space 8192K, 87% used [0x00000007bf600000,0x00000007bfd07778,0x00000007bfe00000)
 from space 1024K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007c0000000)
to space 1024K, 0% used [0x00000007bfe00000,0x00000007bfe00000,0x00000007bff00000)
ParOldGen total 10240K, used 0K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
object space 10240K, 0% used [0x00000007bec00000,0x00000007bec00000,0x00000007bf600000)
Metaspace used 3206K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 347K, capacity 388K, committed 512K, reserved 1048576K

2019-04-07T18:14:11.335-0800: [GC (Allocation Failure) [PSYoungGen: 7197K->864K(9216K)]
7197K->4968K(19456K), 0.0044228 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

Heap after GC invocations=1 (full 0):
PSYoungGen total 9216K, used 864K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
eden space 8192K, 0% used [0x00000007bf600000,0x00000007bf600000,0x00000007bfe00000)
from space 1024K, 84% used [0x00000007bfe00000,0x00000007bfed8000,0x00000007bff00000)
to space 1024K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007c0000000)
ParOldGen total 10240K, used 4104K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
object space 10240K, 40% used [0x00000007bec00000,0x00000007bf002020,0x00000007bf600000)
Metaspace used 3206K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 347K, capacity 388K, committed 512K, reserved 1048576K
}

第二次垃圾回收:继续回收内存, 因为代码中需要分配总共20MB的内存.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
{Heap before GC invocations=2 (full 0):
PSYoungGen total 9216K, used 7246K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
eden space 8192K, 77% used [0x00000007bf600000,0x00000007bfc3b910,0x00000007bfe00000)
from space 1024K, 84% used [0x00000007bfe00000,0x00000007bfed8000,0x00000007bff00000)
to space 1024K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007c0000000)
ParOldGen total 10240K, used 4104K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
object space 10240K, 40% used [0x00000007bec00000,0x00000007bf002020,0x00000007bf600000)
Metaspace used 3209K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 348K, capacity 388K, committed 512K, reserved 1048576K

2019-04-07T18:14:11.341-0800: [GC (Allocation Failure) --[PSYoungGen: 7246K->7246K(9216K)]
11350K->13398K(19456K), 0.0030803 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

Heap after GC invocations=2 (full 0):
PSYoungGen total 9216K, used 7246K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
eden space 8192K, 77% used [0x00000007bf600000,0x00000007bfc3b910,0x00000007bfe00000)
from space 1024K, 84% used [0x00000007bfe00000,0x00000007bfed8000,0x00000007bff00000)
to space 1024K, 76% used [0x00000007bff00000,0x00000007bffc4010,0x00000007c0000000)
ParOldGen total 10240K, used 6152K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
object space 10240K, 60% used [0x00000007bec00000,0x00000007bf202030,0x00000007bf600000)
Metaspace used 3209K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 348K, capacity 388K, committed 512K, reserved 1048576K
}

第三次垃圾回收:内存依然不足, 触发Full GC, 新生代和老年代同时回收.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
{Heap before GC invocations=3 (full 1):
PSYoungGen total 9216K, used 7246K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
eden space 8192K, 77% used [0x00000007bf600000,0x00000007bfc3b910,0x00000007bfe00000)
from space 1024K, 84% used [0x00000007bfe00000,0x00000007bfed8000,0x00000007bff00000)
to space 1024K, 76% used [0x00000007bff00000,0x00000007bffc4010,0x00000007c0000000)
ParOldGen total 10240K, used 6152K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
object space 10240K, 60% used [0x00000007bec00000,0x00000007bf202030,0x00000007bf600000)
Metaspace used 3209K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 348K, capacity 388K, committed 512K, reserved 1048576K

2019-04-07T18:14:11.345-0800: [Full GC (Ergonomics) [PSYoungGen: 7246K->4751K(9216K)] [ParOldGen: 6152K->6145K(10240K)]
13398K->10896K(19456K), [Metaspace: 3209K->3209K(1056768K)], 0.0070121 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]

Heap after GC invocations=3 (full 1):
PSYoungGen total 9216K, used 4751K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
eden space 8192K, 58% used [0x00000007bf600000,0x00000007bfaa3dd8,0x00000007bfe00000)
from space 1024K, 0% used [0x00000007bfe00000,0x00000007bfe00000,0x00000007bff00000)
to space 1024K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007c0000000)
ParOldGen total 10240K, used 6145K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
object space 10240K, 60% used [0x00000007bec00000,0x00000007bf200530,0x00000007bf600000)
Metaspace used 3209K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 348K, capacity 388K, committed 512K, reserved 1048576K
}

第四次垃圾回收:由于在此创建10MB, Full GC之后依然无法满足需求,
抛出OutOfMemoryError. 程序错误退出.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
{Heap before GC invocations=4 (full 2):
PSYoungGen total 9216K, used 4751K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
eden space 8192K, 58% used [0x00000007bf600000,0x00000007bfaa3dd8,0x00000007bfe00000)
from space 1024K, 0% used [0x00000007bfe00000,0x00000007bfe00000,0x00000007bff00000)
to space 1024K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007c0000000)
ParOldGen total 10240K, used 6145K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
object space 10240K, 60% used [0x00000007bec00000,0x00000007bf200530,0x00000007bf600000)
Metaspace used 3209K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 348K, capacity 388K, committed 512K, reserved 1048576K

2019-04-07T18:14:11.353-0800: [Full GC (Allocation Failure)
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
trueat name.zhangmin.gc.GCLogTest.testAllocation(GCLogTest.java:16)

[PSYoungGen: 4751K->4734K(9216K)] [ParOldGen: 6145K->6145K(10240K)]
10896K->10879K(19456K), [Metaspace: 3209K->3209K(1056768K)], 0.0055622 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
trueat name.zhangmin.gc.GCLogTest.main(GCLogTest.java:20)

Heap after GC invocations=4 (full 2):
PSYoungGen total 9216K, used 4734K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
eden space 8192K, 57% used [0x00000007bf600000,0x00000007bfa9f9e8,0x00000007bfe00000)
from space 1024K, 0% used [0x00000007bfe00000,0x00000007bfe00000,0x00000007bff00000)
to space 1024K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007c0000000)
ParOldGen total 10240K, used 6145K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
object space 10240K, 60% used [0x00000007bec00000,0x00000007bf200530,0x00000007bf600000)
Metaspace used 3209K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 348K, capacity 388K, committed 512K, reserved 1048576K
}
Heap
PSYoungGen total 9216K, used 5073K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
eden space 8192K, 61% used [0x00000007bf600000,0x00000007bfaf45b8,0x00000007bfe00000)
from space 1024K, 0% used [0x00000007bfe00000,0x00000007bfe00000,0x00000007bff00000)
to space 1024K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007c0000000)
ParOldGen total 10240K, used 6145K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
object space 10240K, 60% used [0x00000007bec00000,0x00000007bf200530,0x00000007bf600000)
Metaspace used 3241K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 352K, capacity 388K, committed 512K, reserved 1048576K

参考资料

  1. Java GC 日志详解(一图读懂)
  2. JDK1.8 GC日志查看(参考深入理解JAVA虚拟机)
  3. JDK8的GC类型 与 高并发生产环境中不同GC类型带来的性能提升