1. TLAB 相关 JVM 日志解析

1.1. 准备 Java WhiteBox API

首先需要准备好Java WhiteBox API

1.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。

1.1.2. WhiteBox API 如何实现的

WhiteBox API 是一个 Java 类，位于 JDK 的测试包中，默认没有编译进标准发行版的 JDK 中。

test/lib/sun/hotspot/WhiteBox.java

package sun.hotspot;
public class WhiteBox {
  //仅举两个例子，省略其他 api 以及代码
  // Force Young GC
  public native void youngGC();
  // Force Full GC
  public native void fullGC();
}

可以看出，其实里面的所有 API 都是 JNI 调用，具体实现是：

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 中。这就需要我们自己编译一下这个代码。

1.1.3. 什么是 BootClassPath

Java 内有三种不同的类加载器：应用类加载器（application classloader），扩展类加载器（extension classloader）还有根类加载器（bootstrap classloader）

应用类加载器，加载我们classpath目录下的所有类文件
扩展类加载器，加载标准 Java 类库扩展的类，就是你的jre目录下的/lib/ext目录下的所有类
根类加载器（bootstrap classloader），扫描 BootClassPath 下的标准 Java 类库的类加载器。标准 Java 类库限制了一些包路径的类，必须通过根类加载器加载。

对于 WhiteBox API，由于是他的包为sun.hotspot，普通的类加载器是不能加载这个包路径的类的，需要通过根类加载器加载。

1.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;
}

1.1.5. 使用 WhiteBox API

编译 WhiteBox API

将https://github.com/openjdk/jdk/tree/master/test/lib路径下的sun目录取出，编译成一个 jar 包，名字假设是 whitebox.jar

编写测试程序

将 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();
}

启动程序查看效果

使用启动参数 -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 调试环境

1.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 相关的日志。

2. 监控 TLAB 慢分配与 TLAB 外分配 - JFR 相关事件解析

我们可以通过 JFR 来监控 TLAB 慢分配或者 TLAB 外分配事件。也就是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 可能会被占用一部分，所以上面说的这些次数可能不太准确，不过没关系，大体上应该是对的。

同时由于开启了 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)
堆栈

我们一般通过 JMC 查看 JFR 监控的文件，通过事件查看器就可以查看其中的事件，可以参考我的另一系列：JFR 全解（后续更新）

全网最硬核 JVM TLAB 分析（下）原创

1. TLAB 相关 JVM 日志解析

1.1. 准备 Java WhiteBox API

1.1.1. 什么是 WhiteBox API

1.1.2. WhiteBox API 如何实现的

1.1.3. 什么是 BootClassPath

1.1.4. 怎么指定 BootClassPath

1.1.5. 使用 WhiteBox API

1.2. 测试 TLAB 查看日志

2. 监控 TLAB 慢分配与 TLAB 外分配 - JFR 相关事件解析

推荐阅读

专题推荐

本月精选性能专题

本月精选线上案例

本月精选原创好文

联系我们

网媒渠道

友情链接