全网最硬核 JVM TLAB 分析(额外加菜) 7. TLAB 相关 JVM 日志解析
今天，又是干货满满的一天。这是全网最硬核 JVM 系列的开篇，首先从 TLAB 开始。因为文章很长，每一个人阅读习惯不一样，因此特此拆成单篇版和多篇版java
- 全网最硬核 JVM TLAB 分析（单篇版不包含额外加菜）
- 全网最硬核 JVM TLAB 分析 1. 内存分配思想引入
- 全网最硬核 JVM TLAB 分析 2. TLAB生命周期与带来的问题思考
- 全网最硬核 JVM TLAB 分析 3. JVM EMA指望算法与TLAB相关JVM启动参数
- 全网最硬核 JVM TLAB 分析 4. TLAB 基本流程全分析
- 全网最硬核 JVM TLAB 分析 5. TLAB 源代码全解析
- 全网最硬核 JVM TLAB 分析 6. TLAB 相关热门Q&A汇总
- 全网最硬核 JVM TLAB 分析(额外加菜) 7. TLAB 相关 JVM 日志解析
- 全网最硬核 JVM TLAB 分析(额外加菜) 8. 经过 JFR 监控 TLAB
11. TLAB 相关 JVM 日志解析
11.1. 准备 Java WhiteBox API
首先须要准备好Java WhiteBox APIgit
11.1.1. 什么是 WhiteBox API
WhiteBox API 是 HotSpot VM 自带的白盒测试工具，将内部的不少核心机制的 API 暴露出来，用于白盒测试 JVM，压测 JVM 特性，以及辅助学习理解 JVM 并调优参数。WhiteBox API 是 Java 7 引入的，目前 Java 8 LTS 以及 Java 11 LTS（实际上是 Java 9+ 之后的全部版本，这里只关心 LTS 版本，Java 9 引入了模块化因此 WhiteBox API 有所变化）都是有的。可是默认这个 API 并无编译在 JDK 之中，可是他的实现是编译在了 JDK 里面了。因此若是想用这个 API，须要用户本身编译须要的 API，并加入 Java 的 BootClassPath 并启用 WhiteBox API。github
11.1.2. WhiteBox API 如何实现的
WhiteBox API 是一个 Java 类，位于 JDK 的测试包中，默认没有编译进标准发行版的 JDK 中。算法
test/lib/sun/hotspot/WhiteBox.javabootstrap
package sun.hotspot;
public class WhiteBox {
//仅举两个例子，省略其余 api 以及代码
// Force Young GC
public native void youngGC();
// Force Full GC
public native void fullGC();
}
复制代码
能够看出，其实里面的全部 API 都是 JNI 调用，具体实现是：api
src/hotspot/share/prims/whitebox.cpp数组
WB_ENTRY(void, WB_FullGC(JNIEnv* env, jobject o))
Universe::heap()->soft_ref_policy()->set_should_clear_all_soft_refs(true);
Universe::heap()->collect(GCCause::_wb_full_gc);
#if INCLUDE_G1GC
if (UseG1GC) {
// Needs to be cleared explicitly for G1
Universe::heap()->soft_ref_policy()->set_should_clear_all_soft_refs(false);
}
#endif // INCLUDE_G1GC
WB_END
WB_ENTRY(void, WB_YoungGC(JNIEnv* env, jobject o))
Universe::heap()->collect(GCCause::_wb_young_gc);
WB_END
{CC"youngGC", CC"()V", (void*)&WB_YoungGC },
{CC"fullGC", CC"()V", (void*)&WB_FullGC },
//省略其余代码
复制代码
能够看出，JNI 调用实现直接调用了底层 JVM 的相关接口，至关于把 JVM 的一些关键机制暴露出来，用于白盒测试。可是如以前所说，JDK 发行版没有包括 test 下的测试代码，也就是 WhiteBox API 所在的 jar 包并无打进默认的 JDK 中。这就须要咱们本身编译一下这个代码。markdown
11.1.3. 什么是 BootClassPath
Java 内有三种不一样的类加载器：应用类加载器（application classloader），扩展类加载器（extension classloader）还有根类加载器（bootstrap classloader）多线程
- 应用类加载器，加载咱们classpath目录下的全部类文件
- 扩展类加载器，加载标准 Java 类库扩展的类，就是你的jre目录下的/lib/ext目录下的全部类
- 根类加载器（bootstrap classloader），扫描 BootClassPath 下的 标准 Java 类库的类加载器。标准 Java 类库限制了一些包路径的类，必须经过根类加载器加载。
对于 WhiteBox API，因为是他的包为sun.hotspot，普通的类加载器是不能加载这个包路径的类的，须要经过根类加载器加载。app
11.1.4. 怎么指定 BootClassPath
在 Java 8，经过 -Xbootclasspath: 或者 -Xbootclasspath/p:指定，例如：
-Xbootclasspath:/home/project/whitebox.jar
-Xbootclasspath/p:/home/project/whitebox.jar
复制代码
在 Java 9 以后的版本，这两个参数已通过期了，须要改为-Xbootclasspath/a:，例如：
-Xbootclasspath/a:/home/project/whitebox.jar
复制代码
不然会报错-Xbootclasspath is no longer a supported option.
这里对应的 JDK 源码是： src/hotspot/share/runtime/arguments.cpp
// -bootclasspath:
} else if (match_option(option, "-Xbootclasspath:", &tail)) {
jio_fprintf(defaultStream::output_stream(),
"-Xbootclasspath is no longer a supported option.\n");
return JNI_EINVAL;
// -bootclasspath/a:
} else if (match_option(option, "-Xbootclasspath/a:", &tail)) {
//将参数添加到 bootclasspath 中
Arguments::append_sysclasspath(tail);
// -bootclasspath/p:
} else if (match_option(option, "-Xbootclasspath/p:", &tail)) {
jio_fprintf(defaultStream::output_stream(),
"-Xbootclasspath/p is no longer a supported option.\n");
return JNI_EINVAL;
}
复制代码
11.1.5. 使用 WhiteBox API
1. 编译 WhiteBox API
将https://github.com/openjdk/jdk/tree/master/test/lib路径下的sun目录取出，编译成一个 jar 包，名字假设是 whitebox.jar
2. 编写测试程序
将 whitebox.jar 添加到你的项目依赖，以后写代码
public static void main(String[] args) throws Exception {
WhiteBox whiteBox = WhiteBox.getWhiteBox();
//获取 ReservedCodeCacheSize 这个 JVM flag 的值
Long reservedCodeCacheSize = whiteBox.getUintxVMFlag("ReservedCodeCacheSize");
System.out.println(reservedCodeCacheSize);
//打印堆内存各项指标
whiteBox.printHeapSizes();
//执行full GC
whiteBox.fullGC();
//保持进程不退出，保证日志打印完整
Thread.currentThread().join();
}
复制代码
3. 启动程序查看效果
使用启动参数 -Xbootclasspath/a:/home/project/whitebox.jar -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xlog:gc 启动程序。其中前三个 Flag 表示启用 WhiteBox API，最后一个表示打印 GC info 级别的日志到控制台。
个人输出：
[0.025s][info][gc] Using G1
251658240
Minimum heap 8388608 Initial heap 268435456 Maximum heap 4276092928 Space alignment 2097152 Heap alignment 2097152
[0.899s][info][gc] GC(0) Pause Full (WhiteBox Initiated Full GC) 5M->0M(20M) 45.183ms
复制代码
至此，咱们就准备好了 WhiteBox 调试环境
11.2. 测试 TLAB 查看日志
编写测试代码：
//对于字节数组对象头占用16字节
private static final int BYTE_ARRAY_OVERHEAD = 16;
//咱们要测试的对象大小是100kb
private static final int OBJECT_SIZE = 100 * 1024;
//须要使用静态field，而不是方法内本地变量，不然编译后循环内的new byte[]所有会被省略，只剩最后一次的
public static byte[] tmp;
public static void main(String[] args) throws Exception {
WhiteBox whiteBox = WhiteBox.getWhiteBox();
//强制 fullGC 防止接下来程序发生 GC
//同时能够区分出初始化带来的其余线程的TLAB相关的日志
whiteBox.fullGC();
//分配对象，大小1KB
for (int i = 1; i < 512; ++i) {
tmp = new byte[OBJECT_SIZE - BYTE_ARRAY_OVERHEAD];
}
//强制 fullGC，回收全部 TLAB
whiteBox.fullGC();
//分配对象，大小100KB
for (int i = 1; i < 500; ++i) {
tmp = new byte[OBJECT_SIZE * 100 - BYTE_ARRAY_OVERHEAD];
}
whiteBox.fullGC();
//阻塞程序，保证全部日志输出完
Thread.currentThread().join();
}
复制代码
以后，咱们以以下的启动参数（前三个启动参数是咱们前面章节提到的启用 WhiteBox API 须要的参数）启动这个程序，查看日志（关于日志配置，请参考以前的章节）。
-Xbootclasspath/a:./jdk-white-box-17.0-SNAPSHOT.jar
-XX:+UnlockDiagnosticVMOptions
-XX:+WhiteBoxAPI
-Xms512m
-Xmx512m
-XX:+UseTLAB
-Xlog:gc+tlab=trace
-Xlog:gc
复制代码
能够看到下面相似的日志，咱们来根据代码分析下，首先是运行到第一个 fullGC 结束以前的全部日志，首先是 JVM 启动的时候会输出用的是什么 GC 的日志，这里是默认的 G1：
[0.022s][info][gc] Using G1
复制代码
还会输出 TLAB 的通用配置：
[0.030s][trace][gc,tlab] TLAB min: 328 initial: 60293 max: 65536
复制代码
也就是这里 TLAB 最小为 328 MarkWordSize，初始为 60293 MarkWordSize，最大为 65536 MarkWordSize。默认的 64位 JVM 的 MarkWordSize 为 8 字节，也就是堆内存 8 字节对齐。
而后，因为 JVM 启动时，默认会初始化不少线程，包括：
- main 线程：执行 main 方法的线程
- Attach listener 线程：Attach Listener 线程是负责接收到外部的命令，而对该命令进行执行的而且把结果返回给发送者。一般咱们会用一些命令去要求jvm给咱们一些反馈信息，如：java -version、jmap、jstack等等。 若是该线程在jvm启动的时候没有初始化，那么，则会在用户第一次执行jvm命令时，获得启动。
- Signal Dispatcher线程：Attach Listener线程的职责是接收外部jvm命令，当命令接收成功后，会交给signal dispather 线程去进行分发到各个不一样的模块处理命令，而且返回处理结果。 signal dispather线程也是在第一次接收外部jvm命令时，进行初始化工做。
- Reference Handler 线程：JVM在建立main线程后就建立Reference Handler线程，它主要用于处理引用对象自己（软引用、弱引用、虚引用）的垃圾回收问题 。
- Finalizer线程：这个线程也是在main线程以后建立的，主要用于在垃圾收集前，调用对象的finalize()方法。
- DestroyJavaVM线程：执行main()的线程在main执行完后调用JNI中的 jni_DestroyJavaVM() 方法唤起DestroyJavaVM 线程，它将在虚拟机中全部其它非守护线程所有结束后销毁虚拟机。
在运行过程当中，根据你的JIT编译配置，GC参数，还会有：
- CompilerThread 线程：JIT编译相关线程，主要是负责 C1 C2 即时编译以及 OSR（On stack Replacement） 替换等任务
- GC 相关线程：执行GC任务的线程
除了这些以外，Java 8 以后 ForkJoinPool 还会建立一个默认大小为 cpu 核数 -1 的线程池：CommonForkJoinPool，是用来处理 ParallelStream 的默认线程池还有 Future 框架 CompletableFuture 的默认线程池。
这些线程中的一部分会在 JVM 初始化的时候建立一些对象使用，那么就确定会涉及到 TLAB，因此会有以下日志：
[0.042s][trace][gc,tlab] ThreadLocalAllocBuffer::compute_size(2) returns 65536
[0.042s][trace][gc,tlab] TLAB: fill thread: 0x000002a66a471710 [id: 12916] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 1024KB refills: 1 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.155s][trace][gc,tlab] ThreadLocalAllocBuffer::compute_size(25) returns 65536
[0.155s][trace][gc,tlab] TLAB: fill thread: 0x000002a60028e900 [id: 15380] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 1024KB refills: 1 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.340s][trace][gc,tlab] ThreadLocalAllocBuffer::compute_size(2) returns 256
[0.340s][trace][gc,tlab] TLAB: fill thread: 0x000002a66a471710 [id: 12916] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 2048KB refills: 2 waste 0.1% gc: 0B slow: 576B fast: 0B
//省略其余线程的 TLAB 日志，这里 23480 是 Main 线程。读者能够经过程序输出日志中执行循环分配对象的线程 TLAB 日志判断哪个是 Main 线程
复制代码
其中，[0.042s][trace][gc,tlab] ThreadLocalAllocBuffer::compute_size(2) returns 65536的对应的就是调用了compute_size计算初始 TLAB 大小，传入的 2 就是当前这个线程分配的对象所需的大小（MarkWordSize），计算出初始大小为 65536，由于 MarkWordSize = 8 因此 就是 65536*8=524288 字节，也就是 512 KB。下一行日志，表明这个线程初始化申请一块内存做为 TLAB 了，[0.042s][trace][gc,tlab] TLAB: fill thread: 0x000002a66a471710 [id: 12916] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 1024KB refills: 1 waste 0.0% gc: 0B slow: 0B fast: 0B，这个 TLAB 的信息包括：
- 线程号
0x000002a66a471710 [id: 12916] - 指望大小，就是刚刚计算出来的 512KB：
desired_size: 512KB - 慢分配次数，就是不在当前 TLAB 直接分配的分配次数：
slow allocs: 0 - 当前浪费空间限制，也就是从新申请 TLAB 形成的浪费限制大小，refill waste: 8192B，也就是最多能浪费 8192 字节
- 当前 _allocation_fraction 相关信息，
alloc: 1.00000 1024KB，表明当前 _allocation_fraction 是 1.00000，TLAB 一共用了 1024 KB - 发生 refills 从新申请 TLAB 的次数：
refills: 1 - 浪费比例：
waste 0.0% - GC 回收形成的浪费大小：
gc: 0B - 慢
refill形成的浪费：slow: 0B - 快
refill形成的浪费：fast: 0B
咱们这里来计算下为什么当前浪费空间为 8192 字节，也就是 8KB。TLABRefillWasteFraction 咱们并无修改，也就是默认的 64，那么初始的最大浪费空间 = TLAB 大小 / TLABRefillWasteFraction，也就是 512KB / 64 = 8KB
第一次强制 FullGC 以后，看到以下相关日志：
//首先输出了每个线程的当前 TLAB 的信息
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a66a471710 [id: 12916] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 15 waste 7.1% gc: 360616B slow: 13880B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a60028d180 [id: 24604] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a60028e900 [id: 15380] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 1 waste 99.9% gc: 524008B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a6002dc380 [id: 10316] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a600319040 [id: 3856] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a60031a1f0 [id: 16808] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a600326970 [id: 292] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a600328620 [id: 10932] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a60032ac90 [id: 14528] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 1 waste 99.8% gc: 521328B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a600343ec0 [id: 20040] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a600ca03f0 [id: 14304] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a600e157e0 [id: 24148] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 1 waste 60.9% gc: 1248B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a600f17090 [id: 13736] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 1 waste 99.9% gc: 523976B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a600f0e850 [id: 19208] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 1 waste 99.9% gc: 521688B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a601381710 [id: 9804] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a6013aef00 [id: 23640] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a6013f7650 [id: 1860] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a601ad77b0 [id: 17292] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 1 waste 99.9% gc: 521752B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a601971200 [id: 17448] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a601972220 [id: 11844] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.915s][trace][gc,tlab] GC(0) TLAB: gc thread: 0x000002a601705560 [id: 7832] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 8192KB refills: 0 waste 0.0% gc: 0B slow: 0B fast: 0B
//GC TLAB 统计
[0.915s][debug][gc,tlab] GC(0) TLAB totals: thrds: 7 refills: 21 max: 15 slow allocs: 0 max 0 waste: 38.0% gc: 2974616B max: 524008B slow: 13880B max: 13880B fast: 0B max: 0B
//每一个线程 TLAB 指望大小的变化
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a66a471710 [id: 12916] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a60028d180 [id: 24604] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a60028e900 [id: 15380] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a6002dc380 [id: 10316] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a600319040 [id: 3856] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a60031a1f0 [id: 16808] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a600326970 [id: 292] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a600328620 [id: 10932] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a60032ac90 [id: 14528] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a600343ec0 [id: 20040] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a600ca03f0 [id: 14304] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a600e157e0 [id: 24148] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a600f17090 [id: 13736] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.980s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a600f0e850 [id: 19208] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.980s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a601381710 [id: 9804] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.980s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a6013aef00 [id: 23640] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.980s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a6013f7650 [id: 1860] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.980s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a601ad77b0 [id: 17292] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.980s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a601971200 [id: 17448] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.980s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a601972220 [id: 11844] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
[0.980s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a601705560 [id: 7832] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536
//GC 信息
[0.980s][info ][gc ] GC(0) Pause Full (WhiteBox Initiated Full GC) 7M->0M(512M) 65.162ms
复制代码
首先是输出了每个线程的当前 TLAB 的信息。与前面发生 refill 分配 TLAB 时类似。只不过多了 GC 全局序号，从 0 开始， GC(0) 表明的就是第一次 GC 相关的日志 而后是 GC TLAB 统计：[0.915s][debug][gc,tlab] GC(0) TLAB totals: thrds: 7 refills: 21 max: 15 slow allocs: 0 max 0 waste: 38.0% gc: 2974616B max: 524008B slow: 13880B max: 13880B fast: 0B max: 0B：
- 一共有7个线程用了 TLAB：
thrds: 7，也就是前面带GC(0)的 TLAB 信息日志中，只有 7 个线程的 refills 是大于 0 的。 - 本次 GC 全部线程 refills 的次数
refills: 21 - 历史最大的某次 GC 内 refills 的次数
max: 15 - 本次 GC 全部线程慢分配的次数
slow allocs: 0 - 历史最大的某次 GC 内慢分配的次数
max: 0 - 本次 GC 全部线程 TLAB 内存浪费比例
waste: 38.0% - 各类浪费内存大小：`gc: 2974616B max: 524008B slow: 13880B max: 13880B fast: 0B max: 0B``
接着打印了每一个线程 TLAB 指望大小的变化：[0.979s][trace][gc,tlab] GC(0) TLAB new size: thread: 0x000002a66a471710 [id: 12916] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536，这里仍是 MarkWordSize 而不是实际字节大小。 最后是本次 GC 信息：[0.980s][info ][gc ] GC(0) Pause Full (WhiteBox Initiated Full GC) 7M->0M(512M) 65.162ms，表明是 FullGC，而且是 WhiteBox 触发的，堆内存使用从 7M 回收到了 0M，堆内存总大小是 512M，一共停顿时间是 65.162 ms。
以后咱们的程序申请了 512 个大小为 1KB 的对象。为什么new byte[OBJECT_SIZE - BYTE_ARRAY_OVERHEAD]大小是 1KB 呢？由于数组对象头默认是 16 字节，因此再加上 1012 个 byte 就是 1KB。循环结束后，输出了下面两行日志：
[0.989s][trace][gc,tlab] ThreadLocalAllocBuffer::compute_size(128) returns 65536
[0.989s][trace][gc,tlab] TLAB: fill thread: 0x000002a66a471710 [id: 12916] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 1024KB refills: 1 waste 0.0% gc: 0B slow: 0B fast: 0B
[0.989s][trace][gc,tlab] ThreadLocalAllocBuffer::compute_size(128) returns 65536
[0.989s][trace][gc,tlab] TLAB: fill thread: 0x000002a66a471710 [id: 12916] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 1024KB refills: 2 waste 0.1% gc: 0B slow: 1024B fast: 0B
复制代码
能够看出是发生了两次 refill，第一次是线程第一次建立对象时申请的，第二次是申请到第 512 个对象，TLAB 大小是 512 KB，以前的 511KB 已经被占用了，根据前一篇的 TLAB 原理分析，咱们知道因为须要填充 dummy objects 因此要保留一个数组对象头的大小，因此剩下可分配的空间其实不足 1KB，因此须要 refill。而且，浪费的空间（1KB）小于当前浪费空间限制（8KB），因此能够从新申请新的 TLAB 进行分配。
而后咱们的程序在 FullGC 以后，继续申请了 200 个大小为 100KB 的大对象。这里咱们忽略 GC 相关日志，只看分配对象的时候产生的日志。
[3036.734s][trace][gc,tlab] ThreadLocalAllocBuffer::compute_size(12800) returns 65536
[3036.734s][trace][gc,tlab] TLAB: fill thread: 0x000002a66a471710 [id: 12916] desired_size: 512KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 1024KB refills: 1 waste 0.0% gc: 0B slow: 0B fast: 0B
[3047.276s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1028
[3047.276s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1032
[3047.276s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1036
[3047.276s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1040
[3047.276s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1044
[3047.276s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1048
//省略中间分配日志。。。
[3047.279s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1452
[3047.279s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1456
[3047.279s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1460
[3047.279s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1464
[3047.279s][trace][gc,tlab] ThreadLocalAllocBuffer::compute_size(12800) returns 65536
[3047.279s][trace][gc,tlab] TLAB: fill thread: 0x000002a66a471710 [id: 12916] desired_size: 512KB slow allocs: 110 refill waste: 11712B alloc: 1.00000 13312KB refills: 2 waste 1.2% gc: 0B slow: 12288B fast: 0B
[3047.279s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1028
[3047.279s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1032
[3047.279s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1036
[3047.279s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1040
//省略中间分配日志。。。
[3047.281s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1340
复制代码
100KB 的对象，换算成 MarkWordSize 就是 12800，对应日志：[3036.734s][trace][gc,tlab] ThreadLocalAllocBuffer::compute_size(12800) returns 65536，本次计算 TLAB 大小依然是 65536 MarkWordSize，也就是 512KB。在分配第五个对象开始， TLAB 的剩余内存就不够了。可是初始最大浪费空间是 8KB，因此只能直接在 Eden 区分配，并根据 TLABWasteIncrement（默认为 4） 设置的值递增最大浪费空间，也就是每次递增 4 * MarkWordSize 也就是 32 字节。体如今了日志:
[3047.276s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1028
[3047.276s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1032
[3047.276s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1036
[3047.276s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1040
复制代码
能够看出，每次 TLAB 外分配都让最大浪费空间限制加 4。当剩余空间小于最大浪费空间限制时，线程 refill 申请了一块新的 TLAB 进行分配：
[3047.279s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1456
[3047.279s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1460
[3047.279s][trace][gc,tlab] TLAB: slow thread: 0x000002a66a471710 [id: 12916] obj: 12800 free: 1464 waste: 1464
[3047.279s][trace][gc,tlab] ThreadLocalAllocBuffer::compute_size(12800) returns 65536
[3047.279s][trace][gc,tlab] TLAB: fill thread: 0x000002a66a471710 [id: 12916] desired_size: 512KB slow allocs: 110 refill waste: 11712B alloc: 1.00000 13312KB refills: 2 waste 1.2% gc: 0B slow: 12288B fast: 0B
复制代码
至此，咱们就分析了基本全部 TLAB 相关的日志。
相关文章
- 1. 全网最硬核 JVM TLAB 分析(额外加菜) 8. 经过 JFR 监控 TLAB
- 2. 全网最硬核 JVM TLAB 分析（单篇版不包含额外加菜）
- 3. 全网最硬核 JVM TLAB 分析 5. TLAB 源代码全解析
- 4. 全网最硬核 JVM TLAB 分析 6. TLAB 相关热门Q&A汇总
- 5. 全网最硬核 JVM TLAB 分析 4. TLAB 基本流程全分析
- 6. 全网最硬核 JVM TLAB 分析 3. JVM EMA指望算法与TLAB相关JVM启动参数
- 7. 全网最硬核 JVM TLAB 分析 1. 内存分配思想引入
- 8. 全网最硬核 JVM TLAB 分析 2. TLAB生命周期与带来的问题思考
- 9. JVM - TLAB
- 10. JVM-TLAB
- 更多相关文章...
- • XML DOM 解析器 - XML DOM 教程
- • XML DOM 解析器错误 - XML DOM 教程
- • NewSQL-TiDB相关
- • 互联网组织的未来：剖析GitHub员工的任性之源
相关标签/搜索
每日一句
-
每一个你不满意的现在，都有一个你没有努力的曾经。
欢迎关注本站公众号,获取更多信息
相关文章
- 1. 全网最硬核 JVM TLAB 分析(额外加菜) 8. 经过 JFR 监控 TLAB
- 2. 全网最硬核 JVM TLAB 分析（单篇版不包含额外加菜）
- 3. 全网最硬核 JVM TLAB 分析 5. TLAB 源代码全解析
- 4. 全网最硬核 JVM TLAB 分析 6. TLAB 相关热门Q&A汇总
- 5. 全网最硬核 JVM TLAB 分析 4. TLAB 基本流程全分析
- 6. 全网最硬核 JVM TLAB 分析 3. JVM EMA指望算法与TLAB相关JVM启动参数
- 7. 全网最硬核 JVM TLAB 分析 1. 内存分配思想引入
- 8. 全网最硬核 JVM TLAB 分析 2. TLAB生命周期与带来的问题思考
- 9. JVM - TLAB
- 10. JVM-TLAB