JVM 体系难学的一个地方就是理论一大堆,却难以实践。今天就尝试着在本地实践一把,体会 JVM 内存分配和垃圾回收的过程,尽可能的能够通过本地实际操作感受一下之前学习到的一些理论知识,作为一名初学者,也许很多分析和观点不一定对,但总归是实践了一把,欢迎和大家一起讨论。

环境准备

首先看下我本地的 JDK 版本和一些默认参数:

➜  Contents java -XX:+PrintCommandLineFlags -version
-XX:InitialHeapSize=134217728 -XX:MaxHeapSize=2147483648 -XX:+PrintCommandLineFlags -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
openjdk version "1.8.0_202"
OpenJDK Runtime Environment (AdoptOpenJDK)(build 1.8.0_202-b08)
OpenJDK 64-Bit Server VM (AdoptOpenJDK)(build 25.202-b08, mixed mode)

我这里新生代使用的是 Parallel Scavenge,老年代使用的是 Parallel Old。

VM 概要:

垃圾收集器: 名称 = 'PS MarkSweep', 收集 = 0, 总花费时间 = 0.000 秒
垃圾收集器: 名称 = 'PS Scavenge', 收集 = 6, 总花费时间 = 0.099 秒

在《深入理解 Java 虚拟机》中介绍了几条普遍的内存分配规则:

  • 对象优先在 Eden 分配
  • 大对象直接进入老年代
  • 长期存活的对象将进入老年代
  • 动态对象年龄判定
  • 空间分配担保

老版本的书中,作者在测验的时候使用的是 Client 模式的虚拟机,最新版使用的是 Serial / Serial Old 收集器,同时也有说明与 ParNew / Serial Old 收集器的组合规则基本一致。

从网上和部分书籍中查询到的相关资料:

  • ​-XX:+UseParallelGC​​ 的年老代回收器默认根据 JDK 版本而不同,JDK 1.7 和 1.8 默认都是 Parallel Scavenge(新生代)+Parallel Old(老年代)
  • UseParallelGC is “Parallel Scavenge” + “Serial Old”
  • 在Parallel Scavenge 收集器架构中本身有 PS MarkSweep 收集器来进行老年代收集,但由于 PS MarkSweep 与 Serial Old 实现非常接近,因此官方的许多资料都直接以 Serial Old 代替 PS MarkSweep 进行讲解

综合以上信息再结合最新版的《深入理解 Java 虚拟机》,虽然使用的环境与作者有所区别,但是那几条普遍的内存分配规则还是可以参考的。

参数准备

JVM 参数如下(数据可能不太合理,但主要是为了观察 JVM 的分配和 GC 操作):

-verbose:gc
-Xms1024M
-Xmx1024M
-XX:SurvivorRatio=8
-XX:NewRatio=1
-XX:+PrintCommandLineFlags
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintHeapAtGC

可以使用 VisualVM 看下效果:

JVM 优化实操 - 内存分配与回收策略_老年代

可以看到堆总共占用内存是 1024M,新生代中的中 Eden 区 410M,S0 和 S0 都是 51M,老年代占用512M。

测试用代码:

package dongguabai.demo.testing.jvm;

import java.io.IOException;
import java.util.Date;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;

/**
* @author Dongguabai
* @Description
* @Date 创建于 2020-11-18 17:03
*/
public class JVMTestMain {

/**
* 无法被回收的对象
*/
private static final byte[] BYTE = new byte[1 * 1024 * 1024];
//生产环境不要使用 newCachedThreadPool
private static final ExecutorService EXECUTOR_SERVICE = Executors.newCachedThreadPool();

private byte[] bytes = new byte[2 * 1024 * 1024 * 10];

public static void main(String[] args) throws IOException {
sleep(10);
System.out.println("start----->"+new Date());
int i = 1;
while (true) {
int j = i;
//不会出现第一个 Minor GC 后 Survivor 放不下
EXECUTOR_SERVICE.submit(() -> process(j > 10 && j % 10 < 3 ? 120 : 0));
sleep(1);
i++;
}
}

private static JVMTestMain process(long timeout) {
final JVMTestMain jvmTestMain = create();
sleep(timeout);
return jvmTestMain;
}

private static void sleep(long timeout) {
try {
TimeUnit.SECONDS.sleep(timeout);
} catch (InterruptedException e) {
e.printStackTrace();
}
}

/**
* 20M
*/
private static JVMTestMain create() {
return new JVMTestMain();
}
}

内存分配与垃圾回收估算

上面的代码也很简单,就是每秒会产生 20M 的对象,10s 后,每 10s 有 80% 的垃圾是可以立即回收。那么可以简单估算一下内存分配垃圾回收的流程(仅考虑可以直接观察到的对象,所以对象占用估算会偏小,垃圾回收频率会偏低):

  1. 对象优先分配在 Eden 区,大概 20s 左右会触发第一次 Minor GC(就算 Eden 区全满,也才 410M,放入老年代也是可以的,所以不会触发 Full GC),此时共产生了 401M 对象(含 1M 大小的 ​​BYTE​​ 对象),这其中有 41M 左右的对象会是幸存者;
  2. 第 1 步幸存对象大小是 41M ,如果幸存对象大于 S0 区,根据空间分配担保,(如果担保成功)会直接进入老年代,但是明显是放得下的,那么幸存对象会放到 S0 区,也就是说第一次 Minor GC 会回收掉 360M 左右的垃圾。 回收后 Eden 区使用 0M,S0 区 41M(1M 的 ​​BYTE​​ 对象永远存在,还有 40M 对象存活 120s),S1 区 0M,老年代 0M。根据动态对象年龄判断规则,如果不到 S0 的一半,不会直接进入老年代(进入 S0 区后等待下一次 Minor GC,如果某次一批幸存对象,假设年龄是 n,它们占用内存之和达到了 S 区的一半,那么年龄大于等于 n 的对象同样会进入老年代);
  3. 第一次 Minor GC 后再过 20s,此时会触发第二次 Minor GC,此时又新产生 80M 对象幸存,第 2 步中 S0 区域还有 41M 存活对象,也就是总共 121M 对象幸存,这时候 Survivor 是放不下的,那么这时候就会有老年代的空间分配担保,将新产生的幸存对象都放到老年代中去。当然,在发生 Minor GC 之前,VM 会先检查老年代最大可用的连续空间是否大于新生代所有对象总空间,因为会有极端情况,即新生代所有对象都不可被回收,如果允许,那么会继续检查老年代最大可用的连续空间是否大于历次晋升到老年代对象的平均大小,如果大于,会尝试进行一次 Minor GC,如果小于(由于JDK 6 之后 ​​-XX:HandlePromotionFailure​​ 不会影响空间担保策略)则会直接进行一次 Full GC;
  4. 结合第 3 步中的讨论,第二次 Minor GC 后会有 80M 对象进入老年代,S1 区使用 41M,其他区使用 0M;
  5. 第二次 Minor GC 后再过 20s,这时候会触发第三次 Minor GC,此时有 80M 的对象无法回收,根据老年代的空间分配担保,这批对象直接进入老年代,即第三次 Minor GC 后,老年代使用 160M,S0 区使用 41M,其他区使用 0M;
  6. 现在看来平均 20s 会有约 80M 的对象进入老年代,那么大概 2min 左右老年代会使用 480M,再过大概 20s 左右,新生代也会满,执行 Minor GC 之前这时候会判断老年代的可用空间(512M - 480M = 32M)是否会小于历次平均晋升到老年代的大小(约 80M),发现是小于的,那么会触发一次 Full GC;这么估算来看,平均 2min 不到会发生一次 Full GC,每 20s 发生一次 Minor GC;

查看实际内存分配和垃圾回收

估算完毕,就开始验证了,启动上面的代码,从 VisualVM 上观察内存分配情况,同时也注意观察 GC 日志:

-XX:InitialHeapSize=1073741824 -XX:MaxHeapSize=1073741824 -XX:NewRatio=1 -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
start----->Thu Nov 19 13:46:52 CST 2020
{Heap before GC invocations=1 (full 0):
PSYoungGen total 472064K, used 416359K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 99% used [0x00000007a0000000,0x00000007b9699ce8,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007bcd00000,0x00000007bcd00000,0x00000007c0000000)
to space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
ParOldGen total 524288K, used 0K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 0% used [0x0000000780000000,0x0000000780000000,0x00000007a0000000)
Metaspace used 8740K, capacity 9062K, committed 9088K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
2020-11-19T13:47:07.193-0800: [GC (Allocation Failure) [PSYoungGen: 416359K->44371K(472064K)] 416359K->44387K(996352K), 0.0341294 secs] [Times: user=0.09 sys=0.06, real=0.03 secs]
Heap after GC invocations=1 (full 0):
PSYoungGen total 472064K, used 44371K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 0% used [0x00000007a0000000,0x00000007a0000000,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007b9a00000,0x00000007bc554ed0,0x00000007bcd00000)
to space 52224K, 0% used [0x00000007bcd00000,0x00000007bcd00000,0x00000007c0000000)
ParOldGen total 524288K, used 16K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 0% used [0x0000000780000000,0x0000000780004000,0x00000007a0000000)
Metaspace used 8740K, capacity 9062K, committed 9088K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=2 (full 0):
PSYoungGen total 472064K, used 445813K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 95% used [0x00000007a0000000,0x00000007b88087d0,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007b9a00000,0x00000007bc554ed0,0x00000007bcd00000)
to space 52224K, 0% used [0x00000007bcd00000,0x00000007bcd00000,0x00000007c0000000)
ParOldGen total 524288K, used 16K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 0% used [0x0000000780000000,0x0000000780004000,0x00000007a0000000)
Metaspace used 8819K, capacity 9134K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
2020-11-19T13:47:25.257-0800: [GC (Allocation Failure) [PSYoungGen: 445813K->44227K(472064K)] 445829K->167131K(996352K), 0.1468007 secs] [Times: user=0.20 sys=0.16, real=0.15 secs]
Heap after GC invocations=2 (full 0):
PSYoungGen total 472064K, used 44227K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 0% used [0x00000007a0000000,0x00000007a0000000,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007bcd00000,0x00000007bf830ee0,0x00000007c0000000)
to space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
ParOldGen total 524288K, used 122904K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 23% used [0x0000000780000000,0x0000000787806060,0x00000007a0000000)
Metaspace used 8819K, capacity 9134K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=3 (full 0):
PSYoungGen total 472064K, used 455070K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 97% used [0x00000007a0000000,0x00000007b9136a30,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007bcd00000,0x00000007bf830ee0,0x00000007c0000000)
to space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
ParOldGen total 524288K, used 122904K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 23% used [0x0000000780000000,0x0000000787806060,0x00000007a0000000)
Metaspace used 8894K, capacity 9262K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
2020-11-19T13:47:44.327-0800: [GC (Allocation Failure) [PSYoungGen: 455070K->44208K(472064K)] 577974K->290000K(996352K), 0.0490633 secs] [Times: user=0.15 sys=0.19, real=0.05 secs]
Heap after GC invocations=3 (full 0):
PSYoungGen total 472064K, used 44208K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 0% used [0x00000007a0000000,0x00000007a0000000,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007b9a00000,0x00000007bc52c040,0x00000007bcd00000)
to space 52224K, 0% used [0x00000007bcd00000,0x00000007bcd00000,0x00000007c0000000)
ParOldGen total 524288K, used 245792K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 46% used [0x0000000780000000,0x000000078f0080c0,0x00000007a0000000)
Metaspace used 8894K, capacity 9262K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=4 (full 0):
PSYoungGen total 472064K, used 452583K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 97% used [0x00000007a0000000,0x00000007b8ecdcf8,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007b9a00000,0x00000007bc52c040,0x00000007bcd00000)
to space 52224K, 0% used [0x00000007bcd00000,0x00000007bcd00000,0x00000007c0000000)
ParOldGen total 524288K, used 245792K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 46% used [0x0000000780000000,0x000000078f0080c0,0x00000007a0000000)
Metaspace used 8946K, capacity 9262K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
2020-11-19T13:48:03.389-0800: [GC (Allocation Failure) [PSYoungGen: 452583K->44256K(472064K)] 698375K->392456K(996352K), 0.0362459 secs] [Times: user=0.16 sys=0.10, real=0.04 secs]
Heap after GC invocations=4 (full 0):
PSYoungGen total 472064K, used 44256K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 0% used [0x00000007a0000000,0x00000007a0000000,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007bcd00000,0x00000007bf838050,0x00000007c0000000)
to space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
ParOldGen total 524288K, used 348200K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 66% used [0x0000000780000000,0x000000079540a110,0x00000007a0000000)
Metaspace used 8946K, capacity 9262K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=5 (full 0):
PSYoungGen total 472064K, used 446120K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 95% used [0x00000007a0000000,0x00000007b88721d8,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007bcd00000,0x00000007bf838050,0x00000007c0000000)
to space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
ParOldGen total 524288K, used 348200K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 66% used [0x0000000780000000,0x000000079540a110,0x00000007a0000000)
Metaspace used 8967K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
2020-11-19T13:48:22.463-0800: [GC (Allocation Failure) [PSYoungGen: 446120K->44243K(472064K)] 794320K->494852K(996352K), 0.0771502 secs] [Times: user=0.26 sys=0.08, real=0.08 secs]
Heap after GC invocations=5 (full 0):
PSYoungGen total 472064K, used 44243K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 0% used [0x00000007a0000000,0x00000007a0000000,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007b9a00000,0x00000007bc534ed0,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 450608K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 85% used [0x0000000780000000,0x000000079b80c160,0x00000007a0000000)
Metaspace used 8967K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=6 (full 1):
PSYoungGen total 472064K, used 44243K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 0% used [0x00000007a0000000,0x00000007a0000000,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007b9a00000,0x00000007bc534ed0,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 450608K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 85% used [0x0000000780000000,0x000000079b80c160,0x00000007a0000000)
Metaspace used 8967K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
2020-11-19T13:48:22.541-0800: [Full GC (Ergonomics) [PSYoungGen: 44243K->0K(472064K)] [ParOldGen: 450608K->494667K(524288K)] 494852K->494667K(996352K), [Metaspace: 8967K->8967K(1056768K)], 0.2978595 secs] [Times: user=1.43 sys=0.15, real=0.29 secs]
Heap after GC invocations=6 (full 1):
PSYoungGen total 472064K, used 0K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 0% used [0x00000007a0000000,0x00000007a0000000,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 494667K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 94% used [0x0000000780000000,0x000000079e312e40,0x00000007a0000000)
Metaspace used 8967K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=7 (full 2):
PSYoungGen total 472064K, used 400995K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 95% used [0x00000007a0000000,0x00000007b8798d28,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 494667K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 94% used [0x0000000780000000,0x000000079e312e40,0x00000007a0000000)
Metaspace used 8967K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
2020-11-19T13:48:41.527-0800: [Full GC (Ergonomics) [PSYoungGen: 400995K->81920K(472064K)] [ParOldGen: 494667K->515150K(524288K)] 895662K->597071K(996352K), [Metaspace: 8967K->8967K(1056768K)], 0.0412432 secs] [Times: user=0.09 sys=0.06, real=0.04 secs]
Heap after GC invocations=7 (full 2):
PSYoungGen total 472064K, used 81920K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 19% used [0x00000007a0000000,0x00000007a50001b8,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515150K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f713b20,0x00000007a0000000)
Metaspace used 8967K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=8 (full 3):
PSYoungGen total 472064K, used 419840K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 100% used [0x00000007a0000000,0x00000007b9a00000,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515150K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f713b20,0x00000007a0000000)
Metaspace used 8970K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
2020-11-19T13:48:56.651-0800: [Full GC (Ergonomics) [PSYoungGen: 419840K->204845K(472064K)] [ParOldGen: 515150K->515133K(524288K)] 934990K->719978K(996352K), [Metaspace: 8970K->8970K(1056768K)], 0.0767524 secs] [Times: user=0.43 sys=0.02, real=0.07 secs]
Heap after GC invocations=8 (full 3):
PSYoungGen total 472064K, used 204845K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 48% used [0x00000007a0000000,0x00000007ac80b4e0,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515133K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f70f5c8,0x00000007a0000000)
Metaspace used 8970K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=9 (full 4):
PSYoungGen total 472064K, used 404541K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 96% used [0x00000007a0000000,0x00000007b8b0f438,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515133K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f70f5c8,0x00000007a0000000)
Metaspace used 8975K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
2020-11-19T13:49:06.610-0800: [Full GC (Ergonomics) [PSYoungGen: 404541K->225287K(472064K)] [ParOldGen: 515133K->515133K(524288K)] 919674K->740420K(996352K), [Metaspace: 8975K->8975K(1056768K)], 0.0998759 secs] [Times: user=0.29 sys=0.16, real=0.10 secs]
Heap after GC invocations=9 (full 4):
PSYoungGen total 472064K, used 225287K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 53% used [0x00000007a0000000,0x00000007adc01d70,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515133K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f70f568,0x00000007a0000000)
Metaspace used 8975K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=10 (full 5):
PSYoungGen total 472064K, used 399981K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 95% used [0x00000007a0000000,0x00000007b869b5f8,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515133K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f70f568,0x00000007a0000000)
Metaspace used 8975K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
2020-11-19T13:49:14.640-0800: [Full GC (Ergonomics) [PSYoungGen: 399981K->225305K(472064K)] [ParOldGen: 515133K->515133K(524288K)] 915114K->740438K(996352K), [Metaspace: 8975K->8975K(1056768K)], 0.0841838 secs] [Times: user=0.37 sys=0.06, real=0.08 secs]
Heap after GC invocations=10 (full 5):
PSYoungGen total 472064K, used 225305K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 53% used [0x00000007a0000000,0x00000007adc06448,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515133K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f70f560,0x00000007a0000000)
Metaspace used 8975K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=11 (full 6):
PSYoungGen total 472064K, used 417045K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 99% used [0x00000007a0000000,0x00000007b9745658,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515133K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f70f560,0x00000007a0000000)
Metaspace used 8985K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
2020-11-19T13:49:23.662-0800: [Full GC (Ergonomics) [PSYoungGen: 417045K->204820K(472064K)] [ParOldGen: 515133K->515138K(524288K)] 932178K->719958K(996352K), [Metaspace: 8985K->8985K(1058816K)], 0.0718540 secs] [Times: user=0.50 sys=0.00, real=0.07 secs]
Heap after GC invocations=11 (full 6):
PSYoungGen total 472064K, used 204820K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 48% used [0x00000007a0000000,0x00000007ac805130,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515138K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f710a28,0x00000007a0000000)
Metaspace used 8985K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=12 (full 7):
PSYoungGen total 472064K, used 416666K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 99% used [0x00000007a0000000,0x00000007b96e6ae0,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515138K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f710a28,0x00000007a0000000)
Metaspace used 8985K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
2020-11-19T13:49:33.693-0800: [Full GC (Ergonomics) [PSYoungGen: 416666K->204822K(472064K)] [ParOldGen: 515138K->515138K(524288K)] 931805K->719960K(996352K), [Metaspace: 8985K->8985K(1058816K)], 0.0759945 secs] [Times: user=0.50 sys=0.00, real=0.07 secs]
Heap after GC invocations=12 (full 7):
PSYoungGen total 472064K, used 204822K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 48% used [0x00000007a0000000,0x00000007ac805958,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515138K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f7109c8,0x00000007a0000000)
Metaspace used 8985K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=13 (full 8):
PSYoungGen total 472064K, used 417571K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 99% used [0x00000007a0000000,0x00000007b97c8e08,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515138K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f7109c8,0x00000007a0000000)
Metaspace used 8986K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
2020-11-19T13:49:43.722-0800: [Full GC (Ergonomics) [PSYoungGen: 417571K->204804K(472064K)] [ParOldGen: 515138K->515139K(524288K)] 932709K->719944K(996352K), [Metaspace: 8986K->8986K(1058816K)], 0.0775249 secs] [Times: user=0.50 sys=0.00, real=0.08 secs]
Heap after GC invocations=13 (full 8):
PSYoungGen total 472064K, used 204804K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 48% used [0x00000007a0000000,0x00000007ac8012d8,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515139K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f710ef0,0x00000007a0000000)
Metaspace used 8986K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=14 (full 9):
PSYoungGen total 472064K, used 417444K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 99% used [0x00000007a0000000,0x00000007b97a9210,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515139K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f710ef0,0x00000007a0000000)
Metaspace used 8988K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
2020-11-19T13:49:53.761-0800: [Full GC (Ergonomics) [PSYoungGen: 417444K->204803K(472064K)] [ParOldGen: 515139K->515140K(524288K)] 932584K->719944K(996352K), [Metaspace: 8988K->8988K(1058816K)], 0.0730824 secs] [Times: user=0.49 sys=0.01, real=0.07 secs]
Heap after GC invocations=14 (full 9):
PSYoungGen total 472064K, used 204803K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 48% used [0x00000007a0000000,0x00000007ac800e58,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515140K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711370,0x00000007a0000000)
Metaspace used 8988K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=15 (full 10):
PSYoungGen total 472064K, used 418005K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 99% used [0x00000007a0000000,0x00000007b9835458,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515140K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711370,0x00000007a0000000)
Metaspace used 8988K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
2020-11-19T13:50:03.798-0800: [Full GC (Ergonomics) [PSYoungGen: 418005K->204801K(472064K)] [ParOldGen: 515140K->515142K(524288K)] 933145K->719944K(996352K), [Metaspace: 8988K->8988K(1058816K)], 0.0742675 secs] [Times: user=0.51 sys=0.00, real=0.08 secs]
Heap after GC invocations=15 (full 10):
PSYoungGen total 472064K, used 204801K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 48% used [0x00000007a0000000,0x00000007ac800690,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515142K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711b38,0x00000007a0000000)
Metaspace used 8988K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=16 (full 11):
PSYoungGen total 472064K, used 417694K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 99% used [0x00000007a0000000,0x00000007b97e7ba8,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515142K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711b38,0x00000007a0000000)
Metaspace used 8990K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
2020-11-19T13:50:13.831-0800: [Full GC (Ergonomics) [PSYoungGen: 417694K->204800K(472064K)] [ParOldGen: 515142K->515143K(524288K)] 932837K->719944K(996352K), [Metaspace: 8990K->8990K(1058816K)], 0.0820065 secs] [Times: user=0.51 sys=0.01, real=0.08 secs]
Heap after GC invocations=16 (full 11):
PSYoungGen total 472064K, used 204800K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 48% used [0x00000007a0000000,0x00000007ac800320,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515143K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711ea8,0x00000007a0000000)
Metaspace used 8990K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=17 (full 12):
PSYoungGen total 472064K, used 418182K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 99% used [0x00000007a0000000,0x00000007b9861960,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515143K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711ea8,0x00000007a0000000)
Metaspace used 8990K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
2020-11-19T13:50:23.853-0800: [Full GC (Ergonomics) [PSYoungGen: 418182K->204800K(472064K)] [ParOldGen: 515143K->515143K(524288K)] 933326K->719944K(996352K), [Metaspace: 8990K->8990K(1058816K)], 0.0779615 secs] [Times: user=0.52 sys=0.01, real=0.08 secs]
Heap after GC invocations=17 (full 12):
PSYoungGen total 472064K, used 204800K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 48% used [0x00000007a0000000,0x00000007ac800320,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515143K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711ea8,0x00000007a0000000)
Metaspace used 8990K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=18 (full 13):
PSYoungGen total 472064K, used 417797K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 99% used [0x00000007a0000000,0x00000007b9801430,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515143K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711ea8,0x00000007a0000000)
Metaspace used 8993K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
2020-11-19T13:50:33.887-0800: [Full GC (Ergonomics) [PSYoungGen: 417797K->204800K(472064K)] [ParOldGen: 515143K->515143K(524288K)] 932940K->719944K(996352K), [Metaspace: 8993K->8993K(1058816K)], 0.0784022 secs] [Times: user=0.52 sys=0.00, real=0.08 secs]
Heap after GC invocations=18 (full 13):
PSYoungGen total 472064K, used 204800K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 48% used [0x00000007a0000000,0x00000007ac800320,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515143K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711ea8,0x00000007a0000000)
Metaspace used 8993K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
}
{Heap before GC invocations=19 (full 14):
PSYoungGen total 472064K, used 419746K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 99% used [0x00000007a0000000,0x00000007b99e8be0,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515143K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711ea8,0x00000007a0000000)
Metaspace used 9007K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
2020-11-19T13:50:43.904-0800: [Full GC (Ergonomics) [PSYoungGen: 419746K->204820K(472064K)] [ParOldGen: 515143K->515143K(524288K)] 934890K->719963K(996352K), [Metaspace: 9007K->9007K(1058816K)], 0.0816246 secs] [Times: user=0.51 sys=0.00, real=0.08 secs]
Heap after GC invocations=19 (full 14):
PSYoungGen total 472064K, used 204820K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 48% used [0x00000007a0000000,0x00000007ac805188,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515143K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711de8,0x00000007a0000000)
Metaspace used 9007K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
}
Heap
PSYoungGen total 472064K, used 358935K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 85% used [0x00000007a0000000,0x00000007b5e85e98,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515143K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711de8,0x00000007a0000000)
Metaspace used 9022K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1039K, capacity 1135K, committed 1152K, reserved 1048576K

Process finished with exit code 137 (interrupted by signal 9: SIGKILL)

接下来将 GC 日志拆开来看,第一次 Minor GC:

{Heap before GC invocations=1 (full 0):
PSYoungGen total 472064K, used 416359K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 99% used [0x00000007a0000000,0x00000007b9699ce8,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007bcd00000,0x00000007bcd00000,0x00000007c0000000)
to space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
ParOldGen total 524288K, used 0K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 0% used [0x0000000780000000,0x0000000780000000,0x00000007a0000000)
Metaspace used 8740K, capacity 9062K, committed 9088K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K

2020-11-19T13:47:07.193-0800: [GC (Allocation Failure) [PSYoungGen: 416359K->44371K(472064K)] 416359K->44387K(996352K), 0.0341294 secs] [Times: user=0.09 sys=0.06, real=0.03 secs]

Heap after GC invocations=1 (full 0):
PSYoungGen total 472064K, used 44371K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 0% used [0x00000007a0000000,0x00000007a0000000,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007b9a00000,0x00000007bc554ed0,0x00000007bcd00000)
to space 52224K, 0% used [0x00000007bcd00000,0x00000007bcd00000,0x00000007c0000000)
ParOldGen total 524288K, used 16K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 0% used [0x0000000780000000,0x0000000780004000,0x00000007a0000000)
Metaspace used 8740K, capacity 9062K, committed 9088K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}

GC 原因是内存分配失败,回收前年轻代使用了 416359K,约 406.8M,回收后是 44371K,即 43.3M(从下图中也可以看出该存活对象被分配到了 S1 区),回收了约 360M 垃圾,总堆大小是 996352K,约 980M,回收前是 416359K,约 406.6M,回收后是 44387K,约 43.3M,消耗时间是 0.0341294s。

截取的回收前内存分配:

JVM 优化实操 - 内存分配与回收策略_老年代_02

回收后的内存分配图:

JVM 优化实操 - 内存分配与回收策略_sed_03

根据这两张图其实可以发现与上文中估算的差不多,第一次 Minor GC 后 S1 区使用了约 43.3M,但是因为系统还使用了如线程池等,中间也会产生一些对象,此时 Eden 区使用了约 34.0M。

再看第二次 Minor GC 的情况,GC 日志如下:

{Heap before GC invocations=2 (full 0):
PSYoungGen total 472064K, used 445813K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 95% used [0x00000007a0000000,0x00000007b88087d0,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007b9a00000,0x00000007bc554ed0,0x00000007bcd00000)
to space 52224K, 0% used [0x00000007bcd00000,0x00000007bcd00000,0x00000007c0000000)
ParOldGen total 524288K, used 16K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 0% used [0x0000000780000000,0x0000000780004000,0x00000007a0000000)
Metaspace used 8819K, capacity 9134K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K

2020-11-19T13:47:25.257-0800: [GC (Allocation Failure) [PSYoungGen: 445813K->44227K(472064K)] 445829K->167131K(996352K), 0.1468007 secs] [Times: user=0.20 sys=0.16, real=0.15 secs]

Heap after GC invocations=2 (full 0):
PSYoungGen total 472064K, used 44227K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 0% used [0x00000007a0000000,0x00000007a0000000,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007bcd00000,0x00000007bf830ee0,0x00000007c0000000)
to space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
ParOldGen total 524288K, used 122904K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 23% used [0x0000000780000000,0x0000000787806060,0x00000007a0000000)
Metaspace used 8819K, capacity 9134K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}

GC 原因是内存分配失败,回收前年轻代使用了 445813K,约 435.3M,回收后是 44227K,即 43.2M,总共回收了约 400M,总堆大小是 996352K,约 980M,回收前是 445829K,约 435.4M,回收后是 167131K,约 163.2M,消耗时间是 0.1468007s。

回收前的内存分配:

JVM 优化实操 - 内存分配与回收策略_bc_04

回收后的内存分配:

JVM 优化实操 - 内存分配与回收策略_sed_05

通过对第二次 Minor GC 的分析可以看出,之前的估算偏低很多了,第二次 Minor GC 之后有约 120M 对象被直接分配到了老年代。那么老年代堆积速度会大大加快。Minor GC 的平均触发间隔也在 18s 左右。

第三个 Minor GC 后的内存分配图:

JVM 优化实操 - 内存分配与回收策略_老年代_06

可以看到 S 区由于无法继续分配,造成 Minor GC 后 Eden 区的对象只能被分配在老年代,平均每次 Minor GC 有 120M 对象被分配在老年代,那么大约(512M / 120M + 1)5 次 Minor GC 后很快就触发了 Full GC:

{Heap before GC invocations=5 (full 0):
PSYoungGen total 472064K, used 446120K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 95% used [0x00000007a0000000,0x00000007b88721d8,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007bcd00000,0x00000007bf838050,0x00000007c0000000)
to space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
ParOldGen total 524288K, used 348200K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 66% used [0x0000000780000000,0x000000079540a110,0x00000007a0000000)
Metaspace used 8967K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K

2020-11-19T13:48:22.463-0800: [GC (Allocation Failure) [PSYoungGen: 446120K->44243K(472064K)] 794320K->494852K(996352K), 0.0771502 secs] [Times: user=0.26 sys=0.08, real=0.08 secs]

Heap after GC invocations=5 (full 0):
PSYoungGen total 472064K, used 44243K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 0% used [0x00000007a0000000,0x00000007a0000000,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007b9a00000,0x00000007bc534ed0,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 450608K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 85% used [0x0000000780000000,0x000000079b80c160,0x00000007a0000000)
Metaspace used 8967K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}

{Heap before GC invocations=6 (full 1):
PSYoungGen total 472064K, used 44243K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 0% used [0x00000007a0000000,0x00000007a0000000,0x00000007b9a00000)
from space 52224K, 84% used [0x00000007b9a00000,0x00000007bc534ed0,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 450608K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 85% used [0x0000000780000000,0x000000079b80c160,0x00000007a0000000)
Metaspace used 8967K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K

2020-11-19T13:48:22.541-0800: [Full GC (Ergonomics) [PSYoungGen: 44243K->0K(472064K)] [ParOldGen: 450608K->494667K(524288K)] 494852K->494667K(996352K), [Metaspace: 8967K->8967K(1056768K)], 0.2978595 secs] [Times: user=1.43 sys=0.15, real=0.29 secs]

Heap after GC invocations=6 (full 1):
PSYoungGen total 472064K, used 0K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 0% used [0x00000007a0000000,0x00000007a0000000,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 494667K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 94% used [0x0000000780000000,0x000000079e312e40,0x00000007a0000000)
Metaspace used 8967K, capacity 9326K, committed 9344K, reserved 1056768K
class space used 1035K, capacity 1134K, committed 1152K, reserved 1048576K
}

此次 Minor GC 距离上一次 Minor GC 约 19s,Eden 区快满了这时候触发 Minor GC,但是 S 区也放不下,老年代也放不下,会触发 Full GC。

Minor GC / Full GC 前内存分布:

JVM 优化实操 - 内存分配与回收策略_老年代_07

Minor GC / Full GC 后内存分布:

JVM 优化实操 - 内存分配与回收策略_sed_08

优化

我这里最初测试使用的 JVM 参数不是很合理,当然一个很常见的优化是合理增加内存配置。

结合后面频繁 Full GC 的日志来看:

{Heap before GC invocations=19 (full 14):
PSYoungGen total 472064K, used 419746K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 99% used [0x00000007a0000000,0x00000007b99e8be0,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515143K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711ea8,0x00000007a0000000)
Metaspace used 9007K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
2020-11-19T13:50:43.904-0800: [Full GC (Ergonomics) [PSYoungGen: 419746K->204820K(472064K)] [ParOldGen: 515143K->515143K(524288K)] 934890K->719963K(996352K), [Metaspace: 9007K->9007K(1058816K)], 0.0816246 secs] [Times: user=0.51 sys=0.00, real=0.08 secs]
Heap after GC invocations=19 (full 14):
PSYoungGen total 472064K, used 204820K [0x00000007a0000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 419840K, 48% used [0x00000007a0000000,0x00000007ac805188,0x00000007b9a00000)
from space 52224K, 0% used [0x00000007b9a00000,0x00000007b9a00000,0x00000007bcd00000)
to space 44544K, 0% used [0x00000007bd480000,0x00000007bd480000,0x00000007c0000000)
ParOldGen total 524288K, used 515143K [0x0000000780000000, 0x00000007a0000000, 0x00000007a0000000)
object space 524288K, 98% used [0x0000000780000000,0x000000079f711de8,0x00000007a0000000)
Metaspace used 9007K, capacity 9332K, committed 9600K, reserved 1058816K
class space used 1036K, capacity 1135K, committed 1152K, reserved 1048576K
}

能看到 Eden 区每次都能回收快一半,但是 S 区却都用不了,Full GC 频率约为 10s 每次,这时候程序会产生约 200M 对象,主要是因为 S 区装不下 Minor GC 后的对象,而被迫分配到了老年代,再加上 80% 对象都是可以被快速回收的,它们根本就不该进入老年代。所以可以考虑增加年轻代大小,减少老年代大小,尽量保证能够快速回收的对象不要因为放不下而进入老年代。同时代码也要注意优化,我这里将 ​​newCachedThreadPool()​​​ 改为使用 ​​newFixedThreadPool(10)​​(当然,一般都会自定义线程池):

private static final ExecutorService EXECUTOR_SERVICE = Executors.newFixedThreadPool(10);

调整后的 JVM 参数为:

-verbose:gc
-Xms3072M
-Xmx3072M
-Xmn2048M
-XX:SurvivorRatio=8
-XX:+PrintCommandLineFlags
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintHeapAtGC

这么配置之后 Eden 区域有大约 1.6G 可用,S 区有大约 200M 可用,根据之前的经验每次 Minor GC 后约 120M 对象待分配,而且这里对线程池进行了修改,线程数量不会无限增加,同时我这个示例会出现某些线程会出现休眠 120s 的情况,实际运行后 GC 日志:

-XX:InitialHeapSize=3221225472 -XX:MaxHeapSize=3221225472 -XX:MaxNewSize=2147483648 -XX:NewSize=2147483648 -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
start----->Thu Nov 19 19:15:05 CST 2020
{Heap before GC invocations=1 (full 0):
PSYoungGen total 1887744K, used 1661769K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 1678336K, 99% used [0x0000000740000000,0x00000007a56d24b8,0x00000007a6700000)
from space 209408K, 0% used [0x00000007b3380000,0x00000007b3380000,0x00000007c0000000)
to space 209408K, 0% used [0x00000007a6700000,0x00000007a6700000,0x00000007b3380000)
ParOldGen total 1048576K, used 0K [0x0000000700000000, 0x0000000740000000, 0x0000000740000000)
object space 1048576K, 0% used [0x0000000700000000,0x0000000700000000,0x0000000740000000)
Metaspace used 9420K, capacity 9810K, committed 9984K, reserved 1058816K
class space used 1069K, capacity 1170K, committed 1280K, reserved 1048576K
2020-11-19T19:17:34.814-0800: [GC (Allocation Failure) [PSYoungGen: 1661769K->187840K(1887744K)] 1661769K->187864K(2936320K), 0.3349722 secs] [Times: user=0.25 sys=0.36, real=0.33 secs]
Heap after GC invocations=1 (full 0):
PSYoungGen total 1887744K, used 187840K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 1678336K, 0% used [0x0000000740000000,0x0000000740000000,0x00000007a6700000)
from space 209408K, 89% used [0x00000007a6700000,0x00000007b1e700a0,0x00000007b3380000)
to space 209408K, 0% used [0x00000007b3380000,0x00000007b3380000,0x00000007c0000000)
ParOldGen total 1048576K, used 24K [0x0000000700000000, 0x0000000740000000, 0x0000000740000000)
object space 1048576K, 0% used [0x0000000700000000,0x0000000700006000,0x0000000740000000)
Metaspace used 9420K, capacity 9810K, committed 9984K, reserved 1058816K
class space used 1069K, capacity 1170K, committed 1280K, reserved 1048576K

Minor GC 后的内存分配:

JVM 优化实操 - 内存分配与回收策略_sed_09

可以发现暂时几乎没有对象进入老年代,但是还要考虑动态年龄的问题,避免 S 区可回收对象晋升到老年代,所以还可以继续调整,将老年代多分点给年轻代;而且每隔 2min 左右才发生一次 Minor GC,此时以下难以回收的对象(休眠了 120s)也能被回收了,重新调整为:

-verbose:gc
-Xms3072M
-Xmx3072M
-Xmn2560M
-XX:SurvivorRatio=6
-XX:+PrintCommandLineFlags
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintHeapAtGC

GC 日志:

{Heap before GC invocations=1 (full 0):
PSYoungGen total 2293760K, used 1953793K [0x0000000720000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 1966080K, 99% used [0x0000000720000000,0x0000000797400620,0x0000000798000000)
from space 327680K, 0% used [0x00000007ac000000,0x00000007ac000000,0x00000007c0000000)
to space 327680K, 0% used [0x0000000798000000,0x0000000798000000,0x00000007ac000000)
ParOldGen total 524288K, used 0K [0x0000000700000000, 0x0000000720000000, 0x0000000720000000)
object space 524288K, 0% used [0x0000000700000000,0x0000000700000000,0x0000000720000000)
Metaspace used 9418K, capacity 9818K, committed 9984K, reserved 1058816K
class space used 1069K, capacity 1170K, committed 1280K, reserved 1048576K
2020-11-19T19:49:43.527-0800: [GC (Allocation Failure) [PSYoungGen: 1953793K->187872K(2293760K)] 1953793K->187896K(2818048K), 0.0712026 secs] [Times: user=0.21 sys=0.28, real=0.07 secs]
Heap after GC invocations=1 (full 0):
PSYoungGen total 2293760K, used 187872K [0x0000000720000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 1966080K, 0% used [0x0000000720000000,0x0000000720000000,0x0000000798000000)
from space 327680K, 57% used [0x0000000798000000,0x00000007a37780c0,0x00000007ac000000)
to space 327680K, 0% used [0x00000007ac000000,0x00000007ac000000,0x00000007c0000000)
ParOldGen total 524288K, used 24K [0x0000000700000000, 0x0000000720000000, 0x0000000720000000)
object space 524288K, 0% used [0x0000000700000000,0x0000000700006000,0x0000000720000000)
Metaspace used 9418K, capacity 9818K, committed 9984K, reserved 1058816K
class space used 1069K, capacity 1170K, committed 1280K, reserved 1048576K

Minor GC 后的内存分配:

JVM 优化实操 - 内存分配与回收策略_老年代_10

References

欢迎关注公众号

​​​​​

JVM 优化实操 - 内存分配与回收策略_老年代_11