今天，又是乾貨滿滿的一天。這是全網最硬核 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 相關的日誌。