Timing thread distribution statistics event: the JDK. ThreadAllocationStatistics

Introduced version: Java 11

Related ISSUES:

1. Test the JDK/JFR/event/runtime/TestThreadAllocationEvent Java fails with null thread: . In some cases, the JDK ThreadAllocationStatistics not collected JFR related threads, cause the null pointer. The Bug and the JDK/JFR/event/compiler/TestCompilerCompile. Java failed due to “RuntimeException: No thread in the event” repeat. This BUG has no significant impact on usage and was fixed in Java 16.
2. Per thread IO statistics in JFR, this is a new feature, expectations and ThreadAllocationStatistics similar events, provide each thread IO data statistics, this feature has not yet been through discussion.

Configuration of each version:

This hasn’t changed since Java 11 was introduced:

Default configuration (default.jfc of Java 11, default.jfc of Java 12, default.jfc of Java 13, default.jfc of Java 14, default.jfc of Java 15, default. Default. JFC of Java 16, default. JFC of Java 17) :

configuration	value	describe
enabled	false	Disable by default
period	everyChunk	It is collected once each new Chunk file is generated

Sample configuration (profile.jfc of Java 11, profile.jfc of Java 12, profile.jfc of Java 13, profile.jfc of Java 14, profile.jfc of Java 15, Profile.jfc of Java 16, profile.jfc of Java 17) :

configuration	value	describe
enabled	true	Enabled by default
period	everyChunk	It is collected once each new Chunk file is generated

Why is this event needed?

All business threads in Java allocate objects, which can be more frequent for the following critical businesses. Sometimes we may encounter the following two situations:

1. The thread that consumes the most CPU in an online application is also a GC thread. The thread that consumes the most CPU in an online application is also a GC thread. This is probably due to a business BUG that pulls a large amount of data, such as querying the entire table without adding conditions to the database, or the three-party interface returns a large amount of data without limiting the limit. To locate the problem visually and quickly, observe which threads suddenly allocate a lot of memory, and then look at the stack of those threads to confirm. The JDK. ThreadAllocationStatistics is used to check this.
2. With more GC on line, trying to reduce GC is too abstract to look at jMap objects and not intuitively know which code created those objects. Heap dump is too heavy and expensive to analyze for large memory processes. By the JDK ThreadAllocationStatistics view is the thread object is more, gathering the thread’s stack can locate the relevant code.

Event inclusion property

attribute	instructions	For example,
startTime	Event start time	10:16:27. 718
allocated	The amount of space allocated	10.0 MB
thread	Thread information	“Thread-0” (javaThreadId = 27)

Test this event with code

package com.github.hashjang.jfr.test; import com.sun.management.ThreadMXBean; import jdk.jfr.Recording; import jdk.jfr.consumer.RecordedEvent; import jdk.jfr.consumer.RecordedThread; import jdk.jfr.consumer.RecordingFile; import sun.hotspot.WhiteBox; import java.io.File; import java.io.IOException; import java.lang.management.ManagementFactory; import java.nio.file.Path; import java.time.Duration; import java.util.Arrays; import java.util.HashMap; import java.util.Map; import java.util.Random; import java.util.concurrent.CountDownLatch; import java.util.concurrent.TimeUnit; import java.util.stream.Collectors; public class TestThreadAllocationStatistics { private static String EVENT_NAME = "jdk.ThreadAllocationStatistics"; Private Static Long eventPeriodMillis = 50; Private static final int BYTE_ARRAY_OVERHEAD = 16; Private static final int OBJECT_SIZE = 1024; private static final int OBJECT_SIZE = 1024; public static void main(String[] args) throws IOException { Recording recording = new Recording(); recording.enable(EVENT_NAME).withPeriod(Duration.ofMillis(eventPeriodMillis)); recording.start(); // Execute FullGC with WhiteBox to clear interference WhiteBox WhiteBox = whitebox.getwhitebox (); whiteBox.fullGC(); Allocator allocators[] = new Allocator[4]; CountDownLatch allocationsDoneLatch = new CountDownLatch(allocators.length); for (int i = 0; i < allocators.length; i++) { allocators[i] = new Allocator(allocationsDoneLatch, OBJECT_SIZE * (i + 1) - BYTE_ARRAY_OVERHEAD); allocators[i].setDaemon(true); allocators[i].start(); } Map<Long, Allocator> map = Arrays.stream(allocators).collect(Collectors.toMap(Thread::getId, v -> v)); Map<Long, Long> threadAllocatedMap = new HashMap<>(); try { allocationsDoneLatch.await(); / / wait for a period of time to get timing acquisition JDK. ThreadAllocationStatistics collected the latest TimeUnit. SECONDS. Sleep (1); } catch (InterruptedException e) { e.printStackTrace(); } recording.stop(); Path path = new File(new File(".").getAbsolutePath(), "recording-" + recording.getId() + "-pid" + ProcessHandle.current().pid() + ".jfr").toPath(); recording.dump(path); for (RecordedEvent event : RecordingFile.readAllEvents(path)) { if (! EVENT_NAME.equals(event.getEventType().getName())) { continue; } long javaThreadId = ((RecordedThread) event.getValue("thread")).getJavaThreadId(); If (map.containsKey(javaThreadId)) {// The event is timed (the collection time is short), Allocated thread. Put (javaThreadId, Event.getLong (" Allocated ")). System.out.println(event); } } map.forEach((id, thread) -> { System.out.println("Thread " + id + " allocated(from JMX): " + thread.totalAllocated + "; allocated(from jdk.ThreadAllocationStatistics): " + threadAllocatedMap.get(id)); }); } public static class Allocator extends Thread { private volatile long totalAllocated = -1; private final int allocationSize; public byte[] buffer; private final CountDownLatch allocationsDoneLatch; public Allocator(CountDownLatch allocationsDoneLatch, int allocationSize) { this.allocationsDoneLatch = allocationsDoneLatch; this.allocationSize = allocationSize; } @Override public void run() { for (int batches = 0; batches < 100; batches++) { for (int i = 0; i < 1024; i++) { buffer = new byte[allocationSize]; } Try {// It is expected that the number of times allocated between each periodperiodis 5 thread. sleep(eventPeriodMillis / 5); } catch (InterruptedException e) { e.printStackTrace(); TotalAllocated = getThreadAllocatedBytes(); allocationsDoneLatch.countDown(); / / set the Thread as a daemon Thread, wait for after the end of the main Thread will automatically end / / into the infinite loop here because to prevent timing acquisition JDK. ThreadAllocationStatistics events when the acquisition is less than the while (true) {Thread. The yield (); } } private long getThreadAllocatedBytes() { ThreadMXBean bean = (ThreadMXBean) ManagementFactory.getThreadMXBean(); return bean.getThreadAllocatedBytes(Thread.currentThread().getId()); }}}Copy the code

Start with the following JVM parameters:

Xbootclasspath/a: D: \ lot \ JFR - spring - all \ JDK - white - box \ target \ JDK - white - box - 17.0 - the SNAPSHOT. The jar - Xms512m - Xmx512m -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xlog:gcCopy the code

Output result:

[0.016s][info][gc] Using G1
[0.679s][info][gc] GC(0) Pause Full (WhiteBox Initiated Full GC) 19M->2M(512M) 8.804ms
[0.714s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 27M->2M(512M) 1.309ms
[1.099s][info][gc] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 308M->2M(512M) 0.943ms
[1.445s][info][gc] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 308M->2M(512M) 1.141ms
[1.788s][info][gc] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 308M->2M(512M) 1.117ms
jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.915
  allocated = 1.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.915
  allocated = 2.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.915
  allocated = 3.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.915
  allocated = 4.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.965
  allocated = 6.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.965
  allocated = 12.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.965
  allocated = 15.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:29.965
  allocated = 20.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.015
  allocated = 10.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.015
  allocated = 20.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.015
  allocated = 27.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.015
  allocated = 36.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.066
  allocated = 15.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.066
  allocated = 28.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.066
  allocated = 39.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.066
  allocated = 50.3 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.116
  allocated = 19.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.116
  allocated = 36.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.116
  allocated = 51.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.116
  allocated = 64.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.167
  allocated = 24.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.167
  allocated = 44.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.167
  allocated = 63.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.167
  allocated = 80.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.217
  allocated = 28.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.217
  allocated = 52.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.217
  allocated = 75.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.217
  allocated = 96.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.268
  allocated = 32.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.268
  allocated = 61.3 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.268
  allocated = 87.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.268
  allocated = 109.5 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.319
  allocated = 37.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.319
  allocated = 68.3 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.319
  allocated = 99.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.319
  allocated = 124.3 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.370
  allocated = 41.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.370
  allocated = 78.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.370
  allocated = 111.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.370
  allocated = 144.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.420
  allocated = 45.4 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.420
  allocated = 86.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.420
  allocated = 126.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.420
  allocated = 160.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.470
  allocated = 50.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.470
  allocated = 96.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.470
  allocated = 138.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.470
  allocated = 180.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.520
  allocated = 54.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.520
  allocated = 104.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.520
  allocated = 150.4 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.520
  allocated = 196.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.571
  allocated = 58.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.571
  allocated = 112.3 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.571
  allocated = 165.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.571
  allocated = 212.5 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.621
  allocated = 63.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.621
  allocated = 122.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.621
  allocated = 180.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.621
  allocated = 232.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.671
  allocated = 67.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.671
  allocated = 130.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.671
  allocated = 192.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.671
  allocated = 248.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.722
  allocated = 72.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.722
  allocated = 140.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.722
  allocated = 207.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.722
  allocated = 268.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.772
  allocated = 76.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.772
  allocated = 148.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.772
  allocated = 219.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.772
  allocated = 284.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.581
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.581
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.581
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.581
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.631
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.631
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.631
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.631
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.682
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.682
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.682
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.682
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.732
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.732
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.732
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.732
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.823
  allocated = 81.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.823
  allocated = 158.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.823
  allocated = 234.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.823
  allocated = 304.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.874
  allocated = 85.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.874
  allocated = 166.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.874
  allocated = 246.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.874
  allocated = 320.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.925
  allocated = 90.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.925
  allocated = 176.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.925
  allocated = 258.5 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.925
  allocated = 340.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.975
  allocated = 94.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.975
  allocated = 184.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.975
  allocated = 273.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:30.975
  allocated = 356.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.024
  allocated = 99.0 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.024
  allocated = 194.0 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.024
  allocated = 285.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.024
  allocated = 372.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.075
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.075
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.075
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.075
  allocated = 392.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.126
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.126
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.126
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.126
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.177
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.177
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.177
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.177
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.228
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.228
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.228
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.228
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.278
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.278
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.278
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.278
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.329
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.329
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.329
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.329
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.379
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.379
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.379
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.379
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.429
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.429
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.429
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.429
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.479
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.479
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.479
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.479
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.530
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.530
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.530
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.530
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.791
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.791
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.791
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.791
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.842
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.842
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.842
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.842
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.892
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.892
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.892
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.892
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.943
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.943
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.943
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.943
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.993
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.993
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.993
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:31.993
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.043
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.043
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.043
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.043
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.093
  allocated = 100.3 MB
  thread = "Thread-0" (javaThreadId = 27)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.093
  allocated = 200.1 MB
  thread = "Thread-1" (javaThreadId = 28)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.093
  allocated = 300.0 MB
  thread = "Thread-2" (javaThreadId = 29)
}


jdk.ThreadAllocationStatistics {
  startTime = 12:41:32.093
  allocated = 400.0 MB
  thread = "Thread-3" (javaThreadId = 30)
}


Thread 27 allocated(from JMX): 105179160; allocated(from jdk.ThreadAllocationStatistics): 105179160
Thread 28 allocated(from JMX): 209780040; allocated(from jdk.ThreadAllocationStatistics): 209780040
Thread 29 allocated(from JMX): 314573616; allocated(from jdk.ThreadAllocationStatistics): 314573616
Thread 30 allocated(from JMX): 419431216; allocated(from jdk.ThreadAllocationStatistics): 419431216
Copy the code

Underlying principles and related JVM source code

The interval of every configuration, is called requestThreadAllocationStatistics (void) method to collect the allocation of each thread information:

jfrPeriodic.cpp

# define TRACE_REQUEST_FUNC (id) void JfrPeriodicEventSet: : request# # id (void) / / using the macro definition function, The actual function is requestThreadAllocationStatistics (void) TRACE_REQUEST_FUNC (ThreadAllocationStatistics) {ResourceMark rm; Int initial_size = Threads::number_of_threads(); int initial_size = Threads::number_of_threads(); Allocated tokens GrowableArray< jLong > Allocated (Initial_size); GrowableArray<traceid> thread_ids(initial_size); JfrTicks time_stamp = JfrTicks::now(); // Create a new JfrJavaThreadIterator to iterate over each thread. while (iter.has_next()) { JavaThread* const jt = iter.next(); assert(jt ! = NULL, "invariant"); / / read each thread's cooked_allocated_bytes () allocated. Append (jt - > cooked_allocated_bytes ()); Thread_ids. append(JFR_THREAD_ID(jt)); } for(int I = 0; i < thread_ids.length(); i++) { EventThreadAllocationStatistics event(UNTIMED); // Set the current thread allocated size event.set_allocated(tokens. At (I)); Event.set_thread (thread_ids.at(I)); Event.set_endtime (time_stamp); event.commit(); }}Copy the code

The source code for the cooked_allocated_bytes() method is thread.inline-hpp

Inline jlong Thread::cooked_allocated_bytes() {// atoms read _allocated_bytes jlong allocated_bytes = Atomic::load_acquire(&_allocated_bytes); // If TLAB is enabled (by default), If (UseTLAB) {size_t used_bytes = TLAB ().used_bytes(); // If the current TLAB is being initialized, or the global TLAB is being initialized, used_bytes > max_size will occur, which will be ignored. If (used_bytes < = ThreadLocalAllocBuffer: : max_size_in_bytes ()) {/ / statistics could actually have a little question, namely happen TLAB retire, _allocated_bytes adds used_bytes to request a new TLAB. Calling this method may add used_bytes twice. } } return allocated_bytes; }Copy the code

So where does the _allocated_bytes variable change? There are two places, one is when the out-of-TLAB allocation happens, and the other is when TLAB Retire happens. TLAB Retire is when GC occurs and TLAB is full and the remaining space is less than the current maximum waste space limit will be re-applied for a new TLAB for allocation, the current TLAB Retire needs to be applied before the new. _allocated_bytes (TLAB) assignment changed

memAllocator.cpp

// If TLAB is assigned, HeapWord* MemAllocator::allocate_outside_tlab(Allocation& Allocation) const {// marks the current Allocation as an out-of-TLAB Allocation allocation._allocated_outside_tlab = true; HeapWord* mem = Universe::heap()->mem_allocate(_word_size, &allocation._overhead_limit_exceeded);  if (mem == NULL) { return mem; } NOT_PRODUCT(Universe::heap()->check_for_non_bad_heap_word_value(mem, _word_size)); Size_t size_in_bytes = _word_size * HeapWordSize; _thread-> incr_allocATED_bytes (size_in_bytes); return mem; }Copy the code

TLAB retire corresponding source: threadLocalAllocBuffer. CPP

void ThreadLocalAllocBuffer::retire(ThreadLocalAllocStats* stats) { if (stats ! = NULL) { accumulate_and_reset_statistics(stats); } if (end() ! = NULL) { invariants(); // Add the number of bytes currently used by TLAB to _allocated_bytes // From this, it can be seen that if this method is called with cooked_allocated_bytes(), used_bytes may be added twice. thread()->incr_allocated_bytes(used_bytes()); insert_filler(); initialize(NULL, NULL, NULL); }}Copy the code

Let’s take a look at the implementation of looking at thread-allocated memory size in JMX. The first corresponding JMX code is:

Protected Long getThreadAllocatedBytes(Long ID) {Boolean verified = verifyThreadAllocatedMemory(id); If (verified) {/ / call getThreadAllocatedMemory0 allocated memory size using the return getThreadAllocatedMemory0 ( Thread.currentThread().getId() == id ? 0 : id); } return -1; } / / getThreadAllocatedMemory0 is a native method private static native long getThreadAllocatedMemory0 (id);Copy the code

The JVM source code for this native method is threadimpl.c

JNIEXPORT jlong JNICALL Java_sun_management_ThreadImpl_getThreadAllocatedMemory0 (JNIEnv *env, jclass cls, Jlong dar) {/ / actual implementation method is GetOneThreadAllocatedMemory return jmm_interface - > GetOneThreadAllocatedMemory (env, tid); }Copy the code

management.cpp

JVM_ENTRY(jlong, jmm_GetOneThreadAllocatedMemory(JNIEnv *env, jlong thread_id)) if (thread_id < 0) { THROW_MSG_(vmSymbols::java_lang_IllegalArgumentException(), "Invalid thread ID", - 1); } // get the current thread if (thread_id == 0) {// call cooked_allocated_bytes, And gathering the JDK. ThreadAllocationStatistics calls the underlying methods return the thread - > cooked_allocated_bytes (); } ThreadsListHandle TLH; JavaThread* java_thread = tlh.list()->find_JavaThread_from_java_tid(thread_id); if (java_thread ! // call cooked_allocated_bytes, And gathering the JDK. ThreadAllocationStatistics calls the underlying methods return java_thread - > cooked_allocated_bytes (); } return -1; JVM_ENDCopy the code

As you can see, in fact, the underlying calls and JFR acquisition JDK. ThreadAllocationStatistics event, is the Thread cooked_allocated_bytes () method.

Some thoughts on this JFR event

First of all, the paper puts forward a point of view, the JDK. ThreadAllocationStatistics this event is not too cost performance. There are two reasons:

1. Statistical thread allocation size is approximate statistics, do not need to enter the global safety point statistics. . At the same time also on behalf of, the JDK ThreadAllocationStatistics different thread size distribution of the actual events at the same time is not the same point in time, all threads into safe point because there is no pause.
2. The statistics are simply a variable of the size of each thread’s allocated object read atomically, followed by the current TLAB size of each thread (which is obtained by reading two pointer addresses), and you can see that the operation is quite lightweight. Even if there are many threads, it does not add much performance burden.

However, the collection cycle configured by default does not meet our requirements. Default is everyChunk collection period, the default chunk size (maxchunksize) is 12 m, namely each collection after 12 m JFR event, collect a JDK. ThreadAllocationStatistics. This is not very controllable and I normally configure it to collect once every 5s. This is also appropriate for the two scenarios we mentioned above that require this event.

Wechat search “my programming meow” public account, add the author’s wechat, a daily brush, easy to improve skills, won a variety of offers