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

逃离我推掉我的手 2023-01-03 01:57 199阅读 0赞

> 全系列目录：[通过 JFR 与日志深入探索 JVM - 总览篇][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。之后，编写测试代码：

之后，我们以如下的启动参数（前三个启动参数是我们前面章节提到的启用 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`][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();
        //分配对象，大小1KB
        for (int i = 0; i < 512; ++i) {
            tmp = new byte[OBJECT_SIZE - BYTE_ARRAY_OVERHEAD];
        }
        //强制 fullGC，回收所有 TLAB
        whiteBox.fullGC();
        //分配对象，大小100KB
        for (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.681
      objectClass = byte[] (classLoader = bootstrap)
      allocationSize = 1.0 kB
      tlabSize = 478.2 kB
      eventThread = "main" (javaThreadId = 1)
      stackTrace = [
        com.github.hashjang.jfr.test.TestAllocOutsideTLAB.main(String[]) line: 96
      ]
    }
    
    
    jdk.ObjectAllocationInNewTLAB {
      startTime = 13:07:51.777
      objectClass = byte[] (classLoader = bootstrap)
      allocationSize = 100.0 kB
      tlabSize = 512.0 kB
      eventThread = "main" (javaThreadId = 1)
      stackTrace = [
        com.github.hashjang.jfr.test.TestAllocOutsideTLAB.main(String[]) line: 102
      ]
    }
    
    jdk.ObjectAllocationOutsideTLAB {
      startTime = 13:07:51.784
      objectClass = byte[] (classLoader = bootstrap)
      allocationSize = 100.0 kB
      eventThread = "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)`
 *  堆栈

[JFR _ JVM -]: https://zhanghaoxin.blog.csdn.net/article/details/111386635
[default.jfc]: https://github.com/openjdk/jdk/blob/master/src/jdk.jfr/share/conf/jfr/default.jfc