英文:

why my JVM did 3 times of FullGC when it started

问题

我的工作是一个 Flink TaskManager 任务。当它启动时，会触发 3 次垃圾回收（GC）。我不知道为什么当它达到 MetadataGCThreshold 时，年老代空间会增加，而元空间（Metaspace）没有改变，甚至在 GC 之间还会增加。

我原以为 FullGC 会减少年老代空间，并释放一些元空间的空间。😇

Java HotSpot(TM) 64-Bit Server VM (25.211-b12)，用于 linux-amd64 JRE (1.8.0_211-b12)，构建于 2019 年 4 月 1 日 20:39:34，使用 gcc 7.3.0
内存: 4k 页，物理内存 4194304k（空闲 3951532k），交换空间 0k（空闲 0k）
命令行标志: -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/flink-jvm -XX:InitialHeapSize=2899312640 -XX:MaxDirectMemorySize=9223370937343148032 -XX:MaxHeap
Size=2899312640 -XX:NewSize=2147483648 -XX:+PrintFlagsFinal -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops 

# 第一次 GC，为什么年老代空间会增加呢？！
2.452: [Full GC (Metadata GC Threshold) 2.452: [Tenured: 0K->14532K(735232K)， 0.0623627 秒] 167782K->14532K(2622720K)， [Metaspace: 20876K->20876K(1067008K)]， 0.0624443 秒] [Times: user=0.05 
sys=0.01， real=0.07 秒] 

11.656: [Full GC (System.gc()) 11.656: [Tenured: 14532K->27057K(735232K)， 0.1974158 秒] 395065K->27057K(2622720K)， [Metaspace: 32454K->32454K(1077248K)]， 0.1975190 秒] [Times: user=0.18 sys=
0.02， real=0.20 秒] 

65.942: [Full GC (Metadata GC Threshold) 65.942: [Tenured: 27057K->55025K(735232K)， 0.2259224 秒] 512544K->55025K(2622720K)， [Metaspace: 53760K->53760K(1097728K)]， 0.2262134 秒] [Times: user
=0.18 sys=0.03， real=0.23 秒] 

=================================================================
跟进
感谢 Stephen 的回答，我通过 `-XX:MetaspaceSize=134217728` 设置了 Metaspace 的初始大小。我启动了两次任务，第二次带有这个 JVM 参数。由于出现了 `Metadata GC Threshold`，所以没有发生 FullGC。

###### 之前：第一次
bash-4.2$ tailf gc_log_2020-08-26_07-19-05_pid84.log 
Java HotSpot(TM) 64-Bit Server VM (25.241-b26)，用于 linux-amd64 JRE (1.8.0_241-b26)，构建于 2020 年 1 月 6 日 08:59:51，使用 gcc 7.3.0
内存: 4k 页，物理内存 4194304k（空闲 3920180k），交换空间 0k（空闲 0k）
命令行标志: -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/flink-jvm -XX:InitialHeapSize=2899312640 -XX:MaxDirectMemorySize=9223370937343148032 -XX:MaxHeapSize=2899312640 -XX:NewSize=2147483648 -XX:+PrintFlagsFinal -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops 
2.359: [Full GC (Metadata GC Threshold) 2.359: [Tenured: 0K->14643K(735232K)， 0.0526437 秒] 167782K->14643K(2622720K)， [Metaspace: 20937K->20937K(1067008K)]， 0.0527307 秒] [Times: user=0.04 sys=0.01， real=0.05 秒] 
14.576: [Full GC (System.gc()) 14.576: [Tenured: 14643K->27136K(735232K)， 0.1894478 秒] 417611K->27136K(2622720K)， [Metaspace: 32274K->32274K(1077248K)]， 0.1895372 秒] [Times: user=0.15 sys=0.02， real=0.19 秒] 

###### 添加了 metadata 参数之后（-XX:MetaspaceSize=134217728），第二次带参数
bash-4.2$ tailf gc_log_2020-08-26_07-23-19_pid85.log 
Java HotSpot(TM) 64-Bit Server VM (25.241-b26)，用于 linux-amd64 JRE (1.8.0_241-b26)，构建于 2020 年 1 月 6 日 08:59:51，使用 gcc 7.3.0
内存: 4k 页，物理内存 4194304k（空闲 3920136k），交换空间 0k（空闲 0k）
命令行标志: -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/flink-jvm -XX:InitialHeapSize=2899312640 -XX:MaxDirectMemorySize=9223370937343148032 -XX:MaxHeapSize=2899312640 -XX:MetaspaceSize=134217728 -

<details>
<summary>英文:</summary>

My job is a Flink TaskManager job. When it starts, it starts 3 times of GC. I don&#39;t know why when it reached the MetadataGCThreshold it increased Tenured Space, while Metaspace didn&#39;t change, and even increased between GCs.

I thought FullGC would decrease Tenured Space, and some space of Metaspace. &#128559;

```text
Java HotSpot(TM) 64-Bit Server VM (25.211-b12) for linux-amd64 JRE (1.8.0_211-b12), built on Apr  1 2019 20:39:34 by &quot;java_re&quot; with gcc 7.3.0
Memory: 4k page, physical 4194304k(3951532k free), swap 0k(0k free)
CommandLine flags: -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/flink-jvm -XX:InitialHeapSize=2899312640 -XX:MaxDirectMemorySize=9223370937343148032 -XX:MaxHeap
Size=2899312640 -XX:NewSize=2147483648 -XX:+PrintFlagsFinal -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops 

# first GC, the Tenured space even increase?!
2.452: [Full GC (Metadata GC Threshold) 2.452: [Tenured: 0K-&gt;14532K(735232K), 0.0623627 secs] 167782K-&gt;14532K(2622720K), [Metaspace: 20876K-&gt;20876K(1067008K)], 0.0624443 secs] [Times: user=0.05 
sys=0.01, real=0.07 secs] 

11.656: [Full GC (System.gc()) 11.656: [Tenured: 14532K-&gt;27057K(735232K), 0.1974158 secs] 395065K-&gt;27057K(2622720K), [Metaspace: 32454K-&gt;32454K(1077248K)], 0.1975190 secs] [Times: user=0.18 sys=
0.02, real=0.20 secs] 

65.942: [Full GC (Metadata GC Threshold) 65.942: [Tenured: 27057K-&gt;55025K(735232K), 0.2259224 secs] 512544K-&gt;55025K(2622720K), [Metaspace: 53760K-&gt;53760K(1097728K)], 0.2262134 secs] [Times: user
=0.18 sys=0.03, real=0.23 secs] 

=================================================================
FollowUP
thanks to Stephen's answer, I set the initialSize of MetaSpace by -XX:MetaspaceSize=134217728. I start the job twice, second time with this jvm param. had no FullGC because of Metadata GC Threshold.

######  之前: first time
bash-4.2$ tailf gc_log_2020-08-26_07-19-05_pid84.log 
Java HotSpot(TM) 64-Bit Server VM (25.241-b26) for linux-amd64 JRE (1.8.0_241-b26), built on Jan  6 2020 08:59:51 by "java_re" with gcc 7.3.0
Memory: 4k page, physical 4194304k(3920180k free), swap 0k(0k free)
CommandLine flags: -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/flink-jvm -XX:InitialHeapSize=2899312640 -XX:MaxDirectMemorySize=9223370937343148032 -XX:MaxHeapSize=2899312640 -XX:NewSize=2147483648 -XX:+PrintFlagsFinal -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops 
2.359: [Full GC (Metadata GC Threshold) 2.359: [Tenured: 0K->14643K(735232K), 0.0526437 secs] 167782K->14643K(2622720K), [Metaspace: 20937K->20937K(1067008K)], 0.0527307 secs] [Times: user=0.04 sys=0.01, real=0.05 secs] 
14.576: [Full GC (System.gc()) 14.576: [Tenured: 14643K->27136K(735232K), 0.1894478 secs] 417611K->27136K(2622720K), [Metaspace: 32274K->32274K(1077248K)], 0.1895372 secs] [Times: user=0.15 sys=0.02, real=0.19 secs] 

######	添加了metadata参数之后(-XX:MetaspaceSize=134217728), second time with param
bash-4.2$ tailf gc_log_2020-08-26_07-23-19_pid85.log 
Java HotSpot(TM) 64-Bit Server VM (25.241-b26) for linux-amd64 JRE (1.8.0_241-b26), built on Jan  6 2020 08:59:51 by "java_re" with gcc 7.3.0
Memory: 4k page, physical 4194304k(3920136k free), swap 0k(0k free)
CommandLine flags: -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/flink-jvm -XX:InitialHeapSize=2899312640 -XX:MaxDirectMemorySize=9223370937343148032 -XX:MaxHeapSize=2899312640 -XX:MetaspaceSize=134217728 -XX:NewSize=2147483648 -XX:+PrintFlagsFinal -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops 
5.196: [Full GC (System.gc()) 5.196: [Tenured: 0K->27063K(735232K), 0.2379232 secs] 973363K->27063K(2622720K), [Metaspace: 32544K->32544K(1077248K)], 0.2380344 secs] [Times: user=0.25 sys=0.03, real=0.24 secs] 

答案1

得分: 3

> 为什么我的 JVM 在启动时会执行三次 FullGC？

第一次和第三次的 Full GC 是由于 metaspace 达到当前阈值并且需要扩展而触发的。由于 metaspace 主要用于存储与代码相关的内容，这意味着 Flink 正在加载大量的代码或者生成了许多动态代理之类的内容。

你可以考虑增加初始的 metaspace 大小。

第二次 Full GC 是由显式的 System.gc() 调用触发的。我猜测这是 Flink 在做的操作。

> 我以为 FullGC 会减少 Tenured 空间。

不一定。如果 Full GC 是由 metaspace 填充触发的，那么你可能会发现新空间中的许多对象已经进入了 tenured 状态。在第一种情况下，很明显在 GC 之前，tenured 空间是空的。

> ... 而在 GC 之间，metaspace 没有发生变化，甚至在两次 GC 之间还增加了

这意味着 GC 在 metaspace 中没有找到任何垃圾。我只会在一个 ClassLoader 实例（以及其所有类和所有实例）变得不可达时才期望 metaspace 的使用量会减少。在启动期间，预计 metaspace 的使用量会增加。只有当应用程序启动后，JVM 完全热身，并且 metaspace 的使用量在启动后继续增加时，才可能引起关注。

英文:

> Why my JVM did 3 times of FullGC when it started?

The first and third Full GCs were triggered by metaspace hitting its current threshold and needing to grow. Since metaspace is primarily used to hold code-related things, this implies that Flink is loading a lot of code or generating a lot of dynamic proxies or something like that.

You might consider increasing the initial metaspace size.

The second Full GC was triggered by an explicit System.gc() call. My guess is that Flink is doing that.

> I thought FullGC would decrease Tenured space.

Not necessarily. If the Full GC was triggered by metaspace filling, then you could well find that a lot of objects in new space were tenured. In the first case, it is clear that that has happened, since prior to the GC, tenured space was empty.

> ... while metaspace don't change, and even increase between GCs

That means that the GC is not finding any garbage in metaspace. I would only expect metaspace to usage to decrease if a ClassLoader instance (and all of its classes, and all of their instances) became unreachable. It is expected that metaspace usage will increase during startup. It is only potentially concerning if it continues increasing after the application has started and the JVM has full warmed up.