通过 JFR 与日志深入探索 JVM - TLAB JFR 相关事件与日志详解

全系列目录：通过 JFR 与日志深入探索 JVM - 总览篇

上一篇我们详细的分析了 TLAB 的原理以及生命周期，并且提出 JFR 相关的两个事件：在线程分配对象时，如果 TLAB 不够，则根据最大允许浪费空间，决定是回收当前 TLAB 还是重新获取一个 TLAB 进行分配还是直接在堆上分配。jdk.ObjectAllocationOutsideTLAB 代表直接在堆上分配，jdk.ObjectAllocationInNewTLAB 代表回收+重新获取 TLAB 进行分配。

我们也提到了，jdk.ObjectAllocationOutsideTLAB 是我们需要关心的，jdk.ObjectAllocationInNewTLAB 是我们不太需要关心，但是可以通过这个事件学习 TLAB 原理的。在详细说明这两种 JFR 事件之前，我们先来看看 TLAB 涉及到的各种 JVM 日志。

TLAB 相关 JVM 日志

先按照之前的章节，准备好 Java WhiteBox API。之后，编写测试代码：

//对于字节数组对象头占用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();//分配对象，大小1KBfor (int i = 1; i < 512; ++i) {tmp = new byte[OBJECT_SIZE - BYTE_ARRAY_OVERHEAD];}//强制 fullGC，回收所有 TLABwhiteBox.fullGC();//分配对象，大小100KBfor (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 相关的日志。接下来我们用这个程序来采集 JFR 事件。

`jdk.ObjectAllocationOutsideTLAB`与`jdk.ObjectAllocationInNewTLAB`

jdk.ObjectAllocationOutsideTLAB 和 jdk.ObjectAllocationInNewTLAB 这两个事件在default.jfc中( JFR 默认事件采集配置)是没有开启采集的:

<event name="jdk.ObjectAllocationInNewTLAB"><setting name="enabled">false</setting><setting name="stackTrace">true</setting>
</event><event name="jdk.ObjectAllocationOutsideTLAB"><setting name="enabled">false</setting><setting name="stackTrace">true</setting>
</event>

一般的，采集这两个事件，是需要连着堆栈一起采集，但是无法通过持续时间（因为这个事件没有持续时间这一概念）限制采集哪些，也就是只要开启就是全部采集，所以不建议长期开启这个采集。而是通过一些其他的监控项，按照需要，动态开启这个采集一段时间，之后关闭并 dump 出 JFR 文件用于分析。

那么一般根据什么指标判断呢？一般的，当 Young GC 过于频繁时，我们就要考虑是不是由于 TLAB 造成很多空间被浪费导致 GC 频繁了。至于如果采集 Young GC 频率从而动态开启，这个会在后面的动态监控章节详细说明。

我们还用上面的程序，根据之前的日志，对于 1KB 的对象，应该有两次 jdk.ObjectAllocationInNewTLAB 事件，第一次是线程第一次申请 TLAB，第二次是在分配第 512 个对象的时候，TLAB 剩余空间不足，同时剩余空间小于最大浪费空间限制，所以申请新的 TLAB 分配。对于 1KB 的分配，没有发生 jdk.ObjectAllocationOutsideTLAB。对于 100KB 的对象分配，在第五次分配时，TLAB 剩余空间不足，但是剩余空间大于最大浪费空间限制，直接在 Eden 区分配，同时将最大浪费空间限制增加 4。在第 114 次对象分配时，最大浪费空间限制达到了剩余空间，所以申请新的 TLAB 分配。所以对于 100KB 对象的 200 次分配里面，jdk.ObjectAllocationInNewTLAB也只有两次。

同时由于开启了 JFR，导致 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();//初始化 JFR 记录Recording recording = new Recording();//启用 jdk.ObjectAllocationOutsideTLAB 事件监控recording.enable("jdk.ObjectAllocationOutsideTLAB");recording.enable("jdk.ObjectAllocationInNewTLAB");// JFR 记录启动recording.start();//强制 fullGC 防止接下来程序发生 GC//同时可以区分出初始化带来的其他线程的TLAB相关的日志whiteBox.fullGC();//分配对象，大小1KBfor (int i = 0; i < 512; ++i) {tmp = new byte[OBJECT_SIZE - BYTE_ARRAY_OVERHEAD];}//强制 fullGC，回收所有 TLABwhiteBox.fullGC();//分配对象，大小100KBfor (int i = 0; i < 200; ++i) {tmp = new byte[OBJECT_SIZE * 100 - BYTE_ARRAY_OVERHEAD];}whiteBox.fullGC();//将 JFR 记录 dump 到一个文件Path path = new File(new File(".").getAbsolutePath(), "recording-" + recording.getId() + "-pid" + ProcessHandle.current().pid() + ".jfr").toPath();recording.dump(path);int countOf1KBObjectAllocationInNewTLAB = 0;int countOf100KBObjectAllocationInNewTLAB = 0;int countOf1KBObjectAllocationOutsideTLAB = 0;int countOf100KBObjectAllocationOutsideTLAB = 0;//读取文件中的所有 JFR 事件for (RecordedEvent event : RecordingFile.readAllEvents(path)) {//获取分配的对象的类型String className = event.getString("objectClass.name");if (//确保分配类型是 byte[]BYTE_ARRAY_CLASS_NAME.equalsIgnoreCase(className)) {RecordedFrame recordedFrame = event.getStackTrace().getFrames().get(0);//同时必须是咱们这里的main方法分配的对象，并且是Java堆栈中的main方法if (recordedFrame.isJavaFrame()&& "main".equalsIgnoreCase(recordedFrame.getMethod().getName())) {//获取分配对象大小long allocationSize = event.getLong("allocationSize");//统计各种事件个数if ("jdk.ObjectAllocationOutsideTLAB".equalsIgnoreCase(event.getEventType().getName())) {if (allocationSize == 102400) {countOf100KBObjectAllocationOutsideTLAB++;} else if (allocationSize == 1024) {countOf1KBObjectAllocationOutsideTLAB++;}} else if ("jdk.ObjectAllocationInNewTLAB".equalsIgnoreCase(event.getEventType().getName())) {if (allocationSize == 102400) {countOf100KBObjectAllocationInNewTLAB++;} else if (allocationSize == 1024) {countOf1KBObjectAllocationInNewTLAB++;}} else {throw new Exception("unexpected size of TLAB event");}System.out.println(event);}}}System.out.println("countOf1KBObjectAllocationInNewTLAB: " + countOf1KBObjectAllocationInNewTLAB);System.out.println("countOf100KBObjectAllocationInNewTLAB: " + countOf100KBObjectAllocationInNewTLAB);System.out.println("countOf1KBObjectAllocationOutsideTLAB: " + countOf1KBObjectAllocationOutsideTLAB);System.out.println("countOf100KBObjectAllocationOutsideTLAB: " + countOf100KBObjectAllocationOutsideTLAB);//阻塞程序，保证所有日志输出完Thread.currentThread().join();
}

输出应该近似于：

//省略其他事件的详细信息，这里每种挑一个展示
jdk.ObjectAllocationInNewTLAB {startTime = 13:07:51.681objectClass = byte[] (classLoader = bootstrap)allocationSize = 1.0 kBtlabSize = 478.2 kBeventThread = "main" (javaThreadId = 1)stackTrace = [com.github.hashjang.jfr.test.TestAllocOutsideTLAB.main(String[]) line: 96]
}jdk.ObjectAllocationInNewTLAB {startTime = 13:07:51.777objectClass = byte[] (classLoader = bootstrap)allocationSize = 100.0 kBtlabSize = 512.0 kBeventThread = "main" (javaThreadId = 1)stackTrace = [com.github.hashjang.jfr.test.TestAllocOutsideTLAB.main(String[]) line: 102]
}jdk.ObjectAllocationOutsideTLAB {startTime = 13:07:51.784objectClass = byte[] (classLoader = bootstrap)allocationSize = 100.0 kBeventThread = "main" (javaThreadId = 1)stackTrace = [com.github.hashjang.jfr.test.TestAllocOutsideTLAB.main(String[]) line: 102]
}
//省略其他事件的详细信息，这里每种挑一个展示countOf1KBObjectAllocationInNewTLAB: 2
countOf100KBObjectAllocationInNewTLAB: 2
countOf1KBObjectAllocationOutsideTLAB: 0
countOf100KBObjectAllocationOutsideTLAB: 190

可以看出jdk.ObjectAllocationInNewTLAB包含：

开始时间：startTime = 13:07:51.784
分配对象类型：objectClass = byte[] (classLoader = bootstrap)
分配大小：allocationSize = 100.0 kB
新的 TLAB 大小：tlabSize = 512.0 kB
线程：eventThread = "main" (javaThreadId = 1)
堆栈

jdk.ObjectAllocationOutsideTLAB包含：

开始时间：startTime = 13:07:51.784
分配对象类型：objectClass = byte[] (classLoader = bootstrap)
分配大小：allocationSize = 100.0 kB
线程：eventThread = "main" (javaThreadId = 1)
堆栈