Today, another dry day. This is the first in a series of the most hardcore JVMS on the web, starting with TLAB. Since the article is very long and everyone has different reading habits, it is hereby divided into single and multiple editions

  • TLAB Analysis of the most hardcore JVM in the web (single version does not include additional ingredients)
  • TLAB analysis of the most core JVM in the whole network 1. Introduction of memory allocation idea
  • TLAB analysis of the most core JVM in the entire network 2. TLAB life cycle and problem thinking
  • 3. JVM EMA expectation algorithm and TLAB related JVM startup parameters
  • 4. Complete analysis of TLAB basic process
  • Network most core JVM TLAB analysis 5 TLAB source code full analysis
  • 6. TLAB related hot Q&A summary
  • 7. Tlab-related JVM log parsing
  • 8. Monitor TLAB through JFR

11. Parsing TLAB-related JVM logs

11.1. Prepare the Java WhiteBox API

First, you need to have the Java WhiteBox API ready

11.1.1. What is the WhiteBox API

The WhiteBox API is a white-box testing tool that comes with HotSpot VM and exposes many of the core mechanisms of the INTERNAL API for white-box testing of the JVM, for testing JVM features, and for learning to understand the JVM and tuning parameters. The WhiteBox API was introduced in Java 7 and is currently available in Java 8 LTS and Java 11 LTS. Java 9 introduced modularity, so the WhiteBox API changed). By default, this API is not compiled in the JDK, but its implementation is. So if you want to use this API, you need to compile the required API, add Java BootClassPath, and enable the WhiteBox API.

11.1.2. How is the WhiteBox API implemented

The WhiteBox API is a Java class that is in the TEST package of the JDK and is not compiled into the standard distribution JDK by default.

test/lib/sun/hotspot/WhiteBox.java

package sun.hotspot; Public class WhiteBox {// Force Young GC public native void youngGC(); // Force Full GC public native void fullGC(); }Copy the code

As you can see, all apis are JNI calls. The implementation is:

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); YoungGC WB_END {CC ", "CC" V "(), (void *) & WB_YoungGC}, {CC" fullGC, "CC" V "(), (void *) & WB_FullGC}, / / omit other codeCopy the code

As you can see, the JNI call implementation directly invokes the relevant interfaces of the underlying JVM, exposing some of the JVM’s key mechanisms for white-box testing. However, as mentioned earlier, the JDK distribution does not include the test code under Test, which means that the WhiteBox API jar package is not embedded in the default JDK. This requires us to compile the code ourselves.

11.1.3. What is BootClassPath

There are three different class loaders in Java: Application Classloaders, Extension Classloaders, and root classloaders.

  • Apply the classloader to load all the class files in our classpath directory
  • The extension class loader, which loads the standard Java class library extensions, is all classes in the /lib/ext directory of your JRE directory
  • Bootstrap classloader, which scans the standard Java class libraries in BootClassPath. The standard Java class library restricts some package paths to classes that must be loaded through the root class loader.

For the WhiteBox API, because the package is sun.hotspot, the normal class loader cannot load the class in this package path, and it needs to be loaded through the root class loader.

11.1.4. How do I specify BootClassPath

In Java 8, this is specified by -xbootclasspath: or -xbootclasspath /p:, for example:

-Xbootclasspath:/home/project/whitebox.jar
-Xbootclasspath/p:/home/project/whitebox.jar
Copy the code

In versions after Java 9, these two arguments have expired and need to be changed to -xbootclasspath /a:, for example:

-Xbootclasspath/a:/home/project/whitebox.jar
Copy the code

-xbootCLASspath is no longer a supported option.

Corresponding to the JDK source code is here: 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)) {// add Arguments to 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; }Copy the code

11.1.5. Use the WhiteBox API

1. Compile the WhiteBox API

Remove https://github.com/openjdk/jdk/tree/master/test/lib path under sun directory, compiled into a jar package, name is whitebox hypothesis. The jar

2. Write test programs

Add the Whitebox.jar to your project dependencies and then write the code

public static void main(String[] args) throws Exception { WhiteBox whiteBox = WhiteBox.getWhiteBox(); Long ReservedCodeCacheSize = whiteBox.getuintXVmFlag ("ReservedCodeCacheSize");  System.out.println(reservedCodeCacheSize); PrintHeapSizes (); // printHeapSizes(); // Run fullGC whitebox.fullgc (); Thread currentThread().join(); }Copy the code

3. Start the program to see the effect

Use the launch parameters – Xbootclasspath/a: / home/project/whitebox jar – XX: XX: + UnlockDiagnosticVMOptions – + WhiteBoxAPI Xlog: gc start the program. The first three Flag indicates enabling the WhiteBox API, and the last Flag indicates printing GC Info-level logs to the console.

My output:

[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.183 msCopy the code

At this point, we have the WhiteBox debug environment ready

11.2. Check TLAB logs

Write test code:

Private static final int BYTE_ARRAY_OVERHEAD = 16; Private static final int OBJECT_SIZE = 100 * 1024; Public static byte[] TMP; public static byte[] TMP; public static void main(String[] args) throws Exception { WhiteBox whiteBox = WhiteBox.getWhiteBox(); // Force fullGC to prevent GC from occurring in the next program // Also distinguish tLAB-related logs of other threads from initialization whitebox.fullgc (); For (int I = 1; i < 512; ++i) { tmp = new byte[OBJECT_SIZE - BYTE_ARRAY_OVERHEAD]; } // Force fullGC to reclaim all TLAB whitebox.fullgc (); For (int I = 1; int I = 1; i < 500; ++i) { tmp = new byte[OBJECT_SIZE * 100 - BYTE_ARRAY_OVERHEAD]; } whiteBox.fullGC(); Thread currentThread().join(); Thread currentThread().join(); }Copy the code

After that, we start the program with the following startup parameters (the first three startup parameters are the ones we mentioned in the previous section to enable the WhiteBox API) and look at the logging (see the previous section for logging configuration).

- Xbootclasspath/a: / JDK - white - box - 17.0 - the SNAPSHOT. The jar - XX: XX: + UnlockDiagnosticVMOptions - + WhiteBoxAPI Xms512m -- Xmx512m -XX:+UseTLAB -Xlog:gc+tlab=trace -Xlog:gcCopy the code

The JVM starts with a log of what GC is used. This is the default for G1:

[s] 0.022 [info] [gc] Using the G1Copy the code

The general TLAB configuration is also output:

[0.030s][trace][gc,tlab] TLAB min: 328 initial: 60293 max: 65536
Copy the code

In other words, the TLAB minimum is 328 MarkWordSize, the initial is 60293 MarkWordSize, and the maximum is 65536 MarkWordSize. The default 64-bit JVM has a MarkWordSize of 8 bytes, which means that the heap memory is 8 bytes aligned.

Then, as the JVM starts, many threads are initialized by default, including:

  • Main thread: The thread executing the main method
  • Attach Listener thread: The Attach Listener thread is responsible for receiving an external command, executing it and returning the result to the sender. Usually we ask the JVM to give us feedback with commands such as Java-version, jmap, jStack, and so on. If the thread is not initialized when the JVM starts, it will be started when the user first executes the JVM command.
  • Signal Dispatcher thread: The Attach Listener thread is responsible for receiving external JVM commands. When the commands are successfully received, the Signal Dispather thread is sent to the different modules to process the commands and return the results. The signal Dispather thread also initializes the first time it receives an external JVM command.
  • Reference Handler thread: The JVM creates a Reference Handler thread after the main thread is created. It is mainly used to handle the garbage collection of the Reference object itself (soft Reference, weak Reference, virtual Reference).
  • Finalizer thread: This thread is also created after the Main thread and is primarily used to call the Finalize () method of an object before garbage collection.
  • DestroyJavaVM thread: The thread executing main() calls the jni_DestroyJavaVM() method in JNI after main has finished to call the DestroyJavaVM thread, which will destroy the virtual machine after all other non-daemon threads in the virtual machine have finished.

During runtime, depending on your JIT compilation configuration, GC parameters, there will also be:

  • CompilerThread: JIT compile-related thread, which is responsible for C1, C2 just-in-time compilation and OSR (On Stack Replacement) Replacement
  • Gc-related thread: The thread that performs GC tasks

In addition, after Java 8, the ForkJoinPool creates a thread pool with a default size of -1: CommonForkJoinPool is the default thread pool for processing ParallelStream and the Future framework CompletableFuture.

Some of these threads will create objects to use during JVM initialization, so TLAB will definitely be involved, so there will be a log like this:

[s] 0.042 [trace] [gc, tlab] ThreadLocalAllocBuffer: : compute_size (2) returns 65536 [s] 0.042 [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: 0 b [s] 0.155 [trace] [gc, tlab] ThreadLocalAllocBuffer: : compute_size (25) returns 65536 [s] 0.155 [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: 0 b [s] 0.340 [trace] [gc, tlab] ThreadLocalAllocBuffer: : compute_size (2) returns 256 [s] 0.340 [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 // Delete TLAB logs from other threads. The reader can determine which is the Main thread by looking at the TLAB log of the thread that executes the loop allocation object in the program output logCopy the code

Among them, [s] 0.042 [trace] [gc, tlab] ThreadLocalAllocBuffer: : compute_size (2) returns 65536 are calling the corresponding compute_size initial tlab size calculation, The 2 passed in is the required size (MarkWordSize) for the object allocated by the current thread, which computs an initial size of 65536, since MarkWordSize = 8 so 65536*8=524288 bytes, or 512 KB. [0.042s][trace][GC, TLAB] TLAB: fill thread: 0x000002a66a471710 [ID: 12916] 810KB slow allocs: 0 refill waste: 8192B alloc: 1.00000 1024KB refills: 1 waste 0.0% GC: 0B slow: 0B fast: 0B, the information of this TLAB includes:

  • The thread number0x000002a66a471710 [id: 12916]
  • The expected size, as just calculated, is 512KB:desired_size: 512KB
  • The number of slow assignments is the number of assignments that are not directly allocated by the current TLAB:slow allocs: 0
  • Current waste space limit, namely, the size limit of waste caused by the TLAB reapplication, refill waste: 8192B, that is, the maximum of 8192 bytes can be wasted
  • For information about current _allocation_fraction,Alloc: 1.00000 1024 KB, represents that the current _allocation_fraction is 1.00000, and TLAB has a total of 1024 KB
  • Refills number of times a TLAB reapplication occurs:refills: 1
  • Waste ratio:The term "0.0%
  • Waste size caused by GC collection:gc: 0B
  • slowrefillWaste caused:slow: 0B
  • fastrefillWaste caused:fast: 0B

Let’s calculate why the current wasted space is 8192 bytes, or 8KB. We have not modified the TLABRefillWasteFraction, which is the default 64, so the initial maximum wasted space = TLAB size/TLABRefillWasteFraction, which is 512KB / 64 = 8KB

After forcing FullGC for the first time, we see the following related logs:

//首先输出了每一个线程的当前 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
Copy the code

The first is to output the current TLAB information for each thread. It is similar to the TLAB distribution when refill occurs. Totally: Total: THRDS: totally: Total: total: total: total: total: total: total: total: total: total: total: total: total: total: total: total: total 7 refills: 21 Max: 15 slow allocs: 0 Max 0 Waste: 38.0% GC: 2974616B Max: 524008B Slow: 13880B Max: 13880B fast: 0 b Max: 0 b:

  • There are 7 threads using TLAB:thrds: 7That’s the front bandGC(0)In the TLAB information log, only 7 threads have refills greater than 0.
  • Number of refills for all threads in this GCrefills: 21
  • Maximum number of refills in a GCmax: 15
  • The number of times that all GC threads were allocated slowlyslow allocs: 0
  • The maximum number of slow allocations in a GCmax: 0
  • TLAB memory waste ratio of all GC threadsTerm: 38.0%
  • Various wasted memory size: ‘GC: 2974616B Max: 524008B Slow: 13880B Max: 13880B fast: 0B Max: 0B’

[trace][gc, TLAB] GC(0) TLAB new Size: thread: 0x000002a66a471710 [ID: 12916] refills 50 alloc: 1.000000 desired_size: 65536 -> 65536 Finally, the GC information of this time: [info][GC] gc (0) Pause Full (Initiated FullGC) 7M->0M(512M) 65.162ms The heap memory usage was reclaimed from 7M to 0M, the total heap memory size was 512M, and the total pause time was 65.162ms.

Our program then applied for 512 objects of size 1KB. New byte[OBJECT_SIZE – BYTE_ARRAY_OVERHEAD] is 1KB. Since the array object header defaults to 16 bytes, adding 1012 bytes is 1KB. When the loop ends, the following two lines of the log are output:

[s] 0.989 [trace] [gc, tlab] ThreadLocalAllocBuffer: : compute_size returns 65536 (128) [s] 0.989 [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: 0 b [s] 0.989 [trace] [gc, tlab] ThreadLocalAllocBuffer: : compute_size returns 65536 (128) [s] 0.989 [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: 0BCopy the code

It can be seen that there are two refill. The first refill is applied when the thread creates the object for the first time. The second refill is applied when the 512th object is applied. We know that because we need to fill dummy objects we need to keep the size of an array object header, so there is actually less than 1KB left to allocate, so we need the refill. Also, the wasted space (1KB) is less than the current wasted space limit (8KB), so a new TLAB can be reapplied for allocation.

Our program then went on to request 200 large objects of size 100KB after FullGC. We ignore the GC-related logs here and only look at the logs generated when the object is allocated.

[s] 3036.734 [trace] [gc, tlab] ThreadLocalAllocBuffer: : compute_size returns 65536 (12800) [s] 3036.734 [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 [TRACE][GC, Tlab] Tlab: Slow thread: 0x000002A66A471710 [ID: 12916] OBj: 12800 free: 1464 waste: 1452 [TRACE][GC, Tlab] Tlab: Slow thread: 0x000002a66A471710 [ID: 12916] OBj: 12800 free: 1464 waste: 1456 [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 [s] 3047.279 [trace] [gc, tlab] ThreadLocalAllocBuffer: : compute_size returns 65536 (12800) [s] 3047.279 [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 [TRACE][GC, TLAB] Tlab: Slow thread: 0x000002a66A471710 [ID: 12916] OBj: 12800 free: 1464 waste: 1340Copy the code

For a 100KB object, convert to MarkWordSize 12800, which corresponds to the log: [s] 3036.734 [trace] [gc, tlab] ThreadLocalAllocBuffer: : compute_size returns 65536 (12800), The TLAB size in this calculation is still 65536 MarkWordSize, which is 512KB. By the time the fifth object is allocated, the remaining memory in TLAB is insufficient. However, the initial maximum wasted space is 8KB, so we can only allocate the maximum wasted space directly in the Eden zone, and increment the maximum wasted space according to the value set by TLABWasteIncrement (default is 4), which is 4 * MarkWordSize each time, which is 32 bytes. Reflected in the log:

[TRACE][GC,tlab] Tlab: Slow thread: 0x000002A66A471710 [ID: 12916] OBj: 12800 free: 1464 waste: 1028 [TRACE][GC,tlab] Tlab: Slow thread: 0x000002a66A471710 [ID: 12916] OBj: 12800 free: 1464 waste: 1032 [TRACE][GC,tlab] Tlab: Slow thread: 0x000002a66A471710 [ID: 12916] OBj: 12800 free: 1464 waste: 1036 [GC, Tlab] Tlab: slow thread: 0x000002a66A471710 [ID: 12916] OBj: 12800 free: 1464 waste: 1040Copy the code

It can be seen that each allocation out of TLAB increases the maximum wasted space limit by 4. When the free space is less than the maximum wasted space limit, the thread refill applies for a new TLAB for allocation:

[TRACE][GC, Tlab] Tlab: Slow thread: 0x000002A66A471710 [ID: 12916] OBj: 12800 free: 1464 waste: 1456 [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 [s] 3047.279 [trace] [gc, tlab] ThreadLocalAllocBuffer: : compute_size returns 65536 (12800) [s] 3047.279 [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: 0BCopy the code

At this point, we have analyzed almost all the TLAB-related logs.