打工人技术合集

17 GC 日志解读与分析（基础配置）

本章通过具体示例来演示如何输出 GC 日志，并对输出的日志信息进行解读分析，从中提取有用的信息。

本次演示的示例代码

为了演示需要，我们先来编写一段简单的 Java 代码：

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
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
package demo.jvm0204;

import java.util.Random;

import java.util.concurrent.TimeUnit;

import java.util.concurrent.atomic.LongAdder;

/*

演示 GC 日志生成与解读

*/

public class GCLogAnalysis {

    private static Random random = new Random();

    public static void main(String[] args) {

        // 当前毫秒时间戳

        long startMillis = System.currentTimeMillis();

        // 持续运行毫秒数; 可根据需要进行修改

        long timeoutMillis = TimeUnit.SECONDS.toMillis(1);

        // 结束时间戳

        long endMillis = startMillis + timeoutMillis;

        LongAdder counter = new LongAdder();

        System.out.println("正在执行...");

        // 缓存一部分对象; 进入老年代

        int cacheSize = 2000;

        Object[] cachedGarbage = new Object[cacheSize];

        // 在此时间范围内,持续循环

        while (System.currentTimeMillis() < endMillis) {

            // 生成垃圾对象

            Object garbage = generateGarbage(100*1024);

            counter.increment();

            int randomIndex = random.nextInt(2 * cacheSize);

            if (randomIndex < cacheSize) {

                cachedGarbage[randomIndex] = garbage;

            }

        }

        System.out.println("执行结束!共生成对象次数:" + counter.longValue());

    }



    // 生成对象

    private static Object generateGarbage(int max) {

        int randomSize = random.nextInt(max);

        int type = randomSize % 4;

        Object result = null;

        switch (type) {

            case 0:

                result = new int[randomSize];

                break;

            case 1:

                result = new byte[randomSize];

                break;

            case 2:

                result = new double[randomSize];

                break;

            default:

                StringBuilder builder = new StringBuilder();

                String randomString = "randomString-Anything";

                while (builder.length() < randomSize) {

                    builder.append(randomString);

                    builder.append(max);

                    builder.append(randomSize);

                }

                result = builder.toString();

                break;

        }

        return result;

    }

}


程序并不复杂，我们指定一个运行时间作为退出条件，时间一到自动退出循环。在 generateGarbage 方法中，我们用了随机数来生成各种类型的数组对象并返回。

在 main 方法中，我们用一个数组来随机存放一部分生成的对象，这样可以模拟让部分对象晋升到老年代。具体的持续运行时间和缓存对象个数，各位同学可以自己进行调整。

一般来说，Java 中的大对象主要就是各种各样的数组，比如开发中最常见的字符串，实际上 String 内部就是使用字符数组 char[] 来存储的。

额外说一句，这个示例除了可以用来进行 GC 日志分析之外，稍微修改一下，还可以用作其他用途：

  • 比如让缓存的对象变多，在限制堆内存的情况下，就可以模拟“内存溢出”。
  • 增加运行时长，比如加到 30 分钟或者更长，我们就可以用前面介绍过的 VisualVM 等工具来实时监控和观察。
  • 当然，我们也可以使用全局静态变量来缓存，用来模拟“内存泄漏”，以及进行堆内存 Dump 的试验和分析。
  • 加大每次生成的数组的大小，可以用来模拟“大对象/巨无霸对象”（大对象/巨无霸对象主要是 G1 中的概念，比如超过 1MB 的数组，具体情况在后面的内容中再进行探讨）。

常用的 GC 参数

我们从简单到复杂，一步一步来验证前面学习的知识，学会使用，加深巩固。

启动示例程序

如果是在 IDEA、Eclipse 等集成开发环境中，直接在文件中点击鼠标右键，选择“Run…”即可执行。

如果使用 JDK 命令行，则可以使用 javac 工具来编译，使用 java 命令来执行（还记得吗？JDK 8 以上版本，这两个命令可以合并成一个）：

1
2
3
4
5
6
7
8
9
$ javac demo/jvm0204/*.java

$ java demo.jvm0204.GCLogAnalysis

正在执行...

执行结束!共生成对象次数:1423


程序执行 1 秒钟就自动结束了，因为没有指定任何启动参数，所以输出的日志内容也很简单。

还记得我们在前面的《[JVM 启动参数详解]》章节中介绍的 GC 参数吗？

我们依次加上这些参数来看看效果。

输出 GC 日志详情

然后加上启动参数 -XX:+PrintGCDetails，打印 GC 日志详情，再次执行示例。

IDEA 等集成开发环境可以在“VM options”中指定启动参数，参考前面的内容。注意不要有多余的空格。

1
2
3
java -XX:+PrintGCDetails demo.jvm0204.GCLogAnalysis


执行结果摘录如下：

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
38
39
40
41
42
43
44
45
46
47
正在执行...

[GC (Allocation Failure)

  [PSYoungGen: 65081K->10728K(76288K)]

  65081K->27102K(251392K), 0.0112478 secs]

  [Times: user=0.03 sys=0.02, real=0.01 secs]

......此处省略了多行

[Full GC (Ergonomics)

  [PSYoungGen: 80376K->0K(872960K)]

  [ParOldGen: 360220K->278814K(481280K)]

  440597K->278814K(1354240K),

  [Metaspace: 3443K->3443K(1056768K)],

  0.0406179 secs]

  [Times: user=0.23 sys=0.01, real=0.04 secs]

执行结束!共生成对象次数:746

Heap

 PSYoungGen total 872960K, used 32300K [0x000000076ab00000, 0x00000007b0180000, 0x00000007c0000000)

  eden space 792576K, 4% used [0x000000076ab00000,0x000000076ca8b370,0x000000079b100000)

  from space 80384K, 0% used [0x00000007a3800000,0x00000007a3800000,0x00000007a8680000)

  to space 138240K, 0% used [0x000000079b100000,0x000000079b100000,0x00000007a3800000)

 ParOldGen total 481280K, used 278814K [0x00000006c0000000, 0x00000006dd600000, 0x000000076ab00000)

  object space 481280K, 57% used [0x00000006c0000000,0x00000006d1047b10,0x00000006dd600000)

 Metaspace used 3449K, capacity 4494K, committed 4864K, reserved 1056768K

  class space used 366K, capacity 386K, committed 512K, reserved 1048576K


可以看到，使用启动参数 -XX:+PrintGCDetails，发生 GC 时会输出相关的 GC 日志。

这个参数的格式为: -XX:+，这是一个布尔值开关。

在程序执行完成后、JVM 关闭前，还会输出各个内存池的使用情况，从最后面的输出中可以看到。

下面我们来简单解读上面输出的堆内存信息。

Heap 堆内存使用情况

1
2
3
4
5
6
7
8
9
PSYoungGen total 872960K, used 32300K [0x......)

 eden space 792576K, 4% used [0x......)

 from space 80384K, 0% used [0x......)

 to space 138240K, 0% used [0x......)


PSYoungGen，年轻代总计 872960K，使用量 32300K，后面的方括号中是内存地址信息。

  • 其中 eden space 占用了 792576K，其中 4% used
  • 其中 from space 占用了 80384K，其中 0% used
  • 其中 to space 占用了 138240K，其中 0% used
1
2
3
4
5
ParOldGen total 481280K, used 278814K [0x......)

 object space 481280K, 57% used [0x......)


ParOldGen，老年代总计 total 481280K，使用量 278814K。

  • 其中 object space 占用了 481280K，其中 57% used
1
2
3
4
5
Metaspace used 3449K, capacity 4494K, committed 4864K, reserved 1056768K

 class space used 366K, capacity 386K, committed 512K, reserved 1048576K


Metaspace，元数据区总计使用了 3449K，容量是 4494K，JVM 保证可用的大小是 4864K，保留空间 1GB 左右。

  • 其中 class space 使用了 366K，capacity 386K

指定 GC 日志文件

我们在前面的基础上，加上启动参数 -Xloggc:gc.demo.log，再次执行。

1
2
3
4
5
6
7
# 请注意命令行启动时没有换行，此处是手工排版

java -Xloggc:gc.demo.log -XX:+PrintGCDetails

 demo.jvm0204.GCLogAnalysis


提示：从 JDK 8 开始，支持使用 %p、%t 等占位符来指定 GC 输出文件，分别表示进程 pid 和启动时间戳。

例如：-Xloggc:gc.%p.log、-Xloggc:gc-%t.log。

在某些情况下，将每次 JVM 执行的 GC 日志输出到不同的文件可以方便排查问题。

如果业务访问量大，导致 GC 日志文件太大，可以开启 GC 日志轮换，分割成多个文件，可以参考：

https://blog.gceasy.io/2016/11/15/rotating-gc-log-files

执行后在命令行输出的结果如下：

1
2
3
4
5
正在执行...

执行结束!共生成对象次数:1327


GC 日志哪去了？

查看当前工作目录，可以发现多了一个文件 gc.demo.log。 如果是 IDE 开发环境，gc.demo.log 文件可能在项目的根目录下。 当然，我们也可以指定 GC 日志文件存放的绝对路径，比如 -Xloggc:/var/log/gc.demo.log 等形式。

gc.demo.log 文件的内容如下：

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
38
39
40
41
42
43
44
45
46
47
48
49
Java HotSpot(TM) 64-Bit Server VM (25.162-b12) ......

Memory: 4k page，physical 16777216k(1519448k free)



/proc/meminfo:



CommandLine flags:

  -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=4294967296

  -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps

  -XX:+UseCompressedClassPointers -XX:+UseCompressedOops

  -XX:+UseParallelGC

0.310: [GC (Allocation Failure)

  [PSYoungGen: 61807K->10732K(76288K)]

  61807K->22061K(251392K), 0.0094195 secs]

  [Times: user=0.02 sys=0.02, real=0.01 secs]

0.979: [Full GC (Ergonomics)

  [PSYoungGen: 89055K->0K(572928K)]

  [ParOldGen: 280799K->254491K(434176K)]

  369855K->254491K(1007104K),

  [Metaspace: 3445K->3445K(1056768K)],

  0.0362652 secs]

  [Times: user=0.20 sys=0.01, real=0.03 secs]

...... 此处省略部分内容

Heap

...... 堆内存信息格式请参考前面的日志


我们可以发现，加上 -Xloggc: 参数之后，GC 日志信息输出到日志文件中。

文件里最前面是 JVM 相关信息，比如内存页面大小、物理内存大小、剩余内存等信息。

然后是 CommandLine flags 这部分内容。在分析 GC 日志文件时，命令行参数也是一项重要的参考。因为可能你拿到了日志文件，却不知道线上的配置，日志文件中打印了这个信息，能有效减少分析排查时间。

指定 -Xloggc: 参数，自动加上了 -XX:+PrintGCTimeStamps 配置。观察 GC 日志文件可以看到，每一行前面多了一个时间戳（如 0.310:），表示 JVM 启动后经过的时间（单位秒）。

细心的同学还可以发现，JDK 8 默认使用的垃圾收集器参数：-XX:+UseParallelGC。

打印 GC 事件发生的日期和时间

我们在前面的基础上，加上启动参数 -XX:+PrintGCDateStamps，再次执行。

1
2
3
4
5
java -Xloggc:gc.demo.log -XX:+PrintGCDetails

 -XX:+PrintGCDateStamps demo.jvm0204.GCLogAnalysis


执行完成后，GC 日志文件中的内容摘录如下：

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
38
39
40
41
42
43
44
45
46
47
...... 省略多行

CommandLine flags:

  -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=4294967296

  -XX:+PrintGC -XX:+PrintGCDateStamps

  -XX:+PrintGCDetails -XX:+PrintGCTimeStamps

  -XX:+UseCompressedClassPointers -XX:+UseCompressedOops

  -XX:+UseParallelGC

2019-12-15T15:09:59.235-0800: 0.296:

  [GC (Allocation Failure)

    [PSYoungGen: 63844K->10323K(76288K)]

    63844K->20481K(251392K),

    0.0087896 secs]

  [Times: user=0.02 sys=0.02, real=0.01 secs]

2019-12-15T15:09:59.889-0800: 0.951:

  [Full GC (Ergonomics)

    [PSYoungGen: 81402K->0K(577536K)]

    [ParOldGen: 270176K->261230K(445952K)]

    351579K->261230K(1023488K),

    [Metaspace: 3445K->3445K(1056768K)],

    0.0369622 secs]

  [Times: user=0.19 sys=0.00, real=0.04 secs]

Heap

  .......省略内容参考前面的格式


可以看到，加上 -XX:+PrintGCDateStamps 参数之后，GC 日志每一行前面，都打印了 GC 发生时的具体时间。如 2019-12-15T15:09:59.235-0800 表示的是“东 8 区时间 2019 年 12 月 15 日 15:09:59 秒.235 毫秒”。

指定堆内存的大小

从前面的示例中可以看到 GC 日志文件中输出的 CommandLine flags 信息。

即使我们没有指定堆内存，JVM在启动时也会自动算出一个默认值出来。例如：-XX:InitialHeapSize=268435456 \-XX:MaxHeapSize=4294967296 是笔者机器上的默认值，等价于 -Xms256m \-Xmx4g 配置。

我们现在继续增加参数，这次加上启动参数 -Xms512m \-Xmx512m，再次执行。

1
2
3
4
5
6
7
java -Xms512m -Xmx512m

 -Xloggc:gc.demo.log -XX:+PrintGCDetails

 -XX:+PrintGCDateStamps demo.jvm0204.GCLogAnalysis


此时输出的 GC 日志文件内容摘录如下：

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
38
39
40
41
......

CommandLine flags:

  -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912

  -XX:+PrintGC -XX:+PrintGCDateStamps

  -XX:+PrintGCDetails -XX:+PrintGCTimeStamps

  -XX:+UseCompressedClassPointers -XX:+UseCompressedOops

  -XX:+UseParallelGC

2019-12-15T15:15:09.677-0800: 0.358:

  [GC (Allocation Failure)

    [PSYoungGen: 129204K->21481K(153088K)]

    129204K->37020K(502784K), 0.0121865 secs]

  [Times: user=0.03 sys=0.03, real=0.01 secs]

2019-12-15T15:15:10.058-0800: 0.739:

  [Full GC (Ergonomics)

    [PSYoungGen: 20742K->0K(116736K)]

    [ParOldGen: 304175K->247922K(349696K)]

    324918K->247922K(466432K),

    [Metaspace: 3444K->3444K(1056768K)],

    0.0319225 secs]

  [Times: user=0.18 sys=0.01, real=0.04 secs]


此时堆内存的初始值和最大值都是 512MB。具体的参数可根据实际需要配置，我们为了演示，使用了一个较小的堆内存配置。

指定垃圾收集器

一般来说，使用 JDK 8 时我们可以使用以下几种垃圾收集器：

1
2
3
4
5
6
7
8
9
10
11
12
13
-XX:+UseSerialGC

-XX:+UseParallelGC

-XX:+UseParallelGC -XX:+UseParallelOldGC

-XX:+UseConcMarkSweepGC

-XX:+UseConcMarkSweepGC -XX:+UseParNewGC

-XX:+UseG1GC


它们都是什么意思呢，我们再简单回顾一下：

  • 使用串行垃圾收集器：-XX:+UseSerialGC
  • 使用并行垃圾收集器：-XX:+UseParallelGC 和 -XX:+UseParallelGC -XX:+UseParallelOldGC 是等价的，可以通过 GC 日志文件中的 flags 看出来。
  • 使用 CMS 垃圾收集器：-XX:+UseConcMarkSweepGC 和 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC 是等价的。但如果只指定 -XX:+UseParNewGC 参数则老年代 GC 会使用 SerialGC。使用CMS时，命令行参数中会自动计算出年轻代、老年代的初始值和最大值，以及最大晋升阈值等信息（例如 -XX:MaxNewSize=178958336 -XX:NewSize=178958336 -XX:OldSize=357912576）。
  • 使用 G1 垃圾收集器：-XX:+UseG1GC。原则上不能指定 G1 垃圾收集器的年轻代大小，否则不仅是画蛇添足，更是自废武功了。因为 G1 的回收方式是小批量划定区块（region）进行，可能一次普通 GC 中既有年轻代又有老年代，可能某个区块一会是老年代，一会又变成年轻代了。

如果使用不支持的 GC 组合，会怎么样呢？答案是会启动失败，报 fatal 错误，有兴趣的同学可以试一下。

下一节会依次演示各种垃圾收集器的使用，并采集和分析他们产生的日志。它们的格式差距并不大，学会分析一种 GC 日志之后，就可以举一反三，对于其他类型的 GC 日志，基本上也能看懂各项信息的大概意思。

其他参数

JVM 里还有一些 GC 日志相关的参数，例如：

  • -XX:+PrintGCApplicationStoppedTime 可以输出每次 GC 的持续时间和程序暂停时间；
  • -XX:+PrintReferenceGC 输出 GC 清理了多少引用类型。

这里就不再赘述，想了解配置详情的，可以回头复习前面的章节。

说明：大部分情况下，配置 GC 参数并不是越多越好。原则上只配置最重要的几个参数即可，其他的都保持默认值，除非你对系统的业务特征有了深入的分析和了解，才需要进行某些细微参数的调整。毕竟，古语有云：“过早优化是万恶之源”。

GC 事件的类型简介

一般来说，垃圾收集事件（Garbage Collection events）可以分为三种类型：

  • Minor GC（小型 GC）
  • Major GC（大型 GC）
  • Full GC（完全 GC）

虽然 Minor GC，Major GC 和 Full GC 这几个词汇到处都在用，但官方并没有给出标准的定义。这些术语出现在官方的各种分析工具和垃圾收集日志中，并不是很统一。官方的文档和工具之间也常常混淆，这些混淆甚至根植于标准的 JVM 工具中。

MinorGC 称为“小型 GC”，还是“次要GC”更合理呢？

辨析：在大部分情况下，发生在年轻代的 Minor GC 次数更多，有些文章将次数更多的 GC 称为“次要 GC”明显是不太合理的。

在这里，我们将 Minor GC 翻译为“小型 GC”，而不是“次要 GC”；将 Major GC 翻译为“大型GC”而不是“主要 GC”；Full GC 翻译为完全 GC；有时候也直接称为 Full GC。

其实这也是因为专有名词在中英文翻译的时候，可能会有多个英语词汇对应一个中文词语，也会有一个英文词汇对应多个中文词语，要看具体情况而定。

比如一个类似的情况：Major Version 和 Minor Version，这两个名词一般翻译为“主要版本”和“次要版本”。这当然没问题，大家都能理解，一看就知道什么意思。甚至直接翻译为“大版本号”和“小版本号”也是能讲得通的。

本节简单介绍了这几种事件类型及其区别，下面我们来看看这些事件类型的具体细节。

Minor GC（小型 GC）

收集年轻代内存的 GC 事件称为 Minor GC。关于 Minor GC 事件，我们需要了解一些相关的内容：

  1. 当 JVM 无法为新对象分配内存空间时就会触发 Minor GC（ 一般就是 Eden 区用满了）。如果对象的分配速率很快，那么 Minor GC 的次数也就会很多，频率也就会很快。
  2. Minor GC 事件不处理老年代，所以会把所有从老年代指向年轻代的引用都当做 GC Root。从年轻代指向老年代的引用则在标记阶段被忽略。
  3. 与我们一般的认知相反，Minor GC 每次都会引起 STW 停顿（stop-the-world），挂起所有的应用线程。对大部分应用程序来说，Minor GC 的暂停时间可以忽略不计，因为 Eden 区里面的对象大部分都是垃圾，也不怎么复制到存活区/老年代。但如果不符合这种情况，那么很多新创建的对象就不能被 GC 清理，Minor GC 的停顿时间就会增大，就会产生比较明显的 GC 性能影响。

简单定义：Minor GC 清理的是年轻代，又或者说 Minor GC 就是“年轻代 GC”（Young GC，简称 YGC）。

Major GC vs. Full GC

值得一提的是，这几个术语都没有正式的定义–无论是在 JVM 规范中还是在 GC 论文中。

我们知道，除了 Minor GC 外，另外两种 GC 事件则是：

  • Major GC（大型 GC）：清理老年代空间（Old Space）的 GC 事件。
  • Full GC（完全 GC）：清理整个堆内存空间的 GC 事件，包括年轻代空间和老年代空间。

其实 Major GC 和 Full GC 有时候并不能很好地区分。更复杂的情况是，很多 Major GC 是由 Minor GC 触发的，所以很多情况下这两者是不可分离的。

另外，像 G1 这种垃圾收集算法，是每次找一小部分区域来进行清理，这部分区域中可能有一部分是年轻代，另一部分区域属于老年代。

所以我们不要太纠结具体是叫 Major GC 呢还是叫 Full GC，它们一般都会造成单次较长时间的 STW 暂停。所以我们需要关注的是：某次 GC 事件，是暂停了所有线程、进而对系统造成了性能影响呢，还是与其他业务线程并发执行、暂停时间几乎可以忽略不计。

本节内容到此就结束了，下一节我们通过实例来分析各种 GC 算法产生的日志。

全部展开 回到顶部 前往底部