Java JFR 民间指南 - 事件详解 - jdk.ThreadAllocationStatist
定时线程分配统计事件:jdk.ThreadAllocationStatistics
引入版本:Java 11
相关 ISSUES:
- Test jdk/jfr/event/runtime/TestThreadAllocationEvent.java fails with null thread:在某些情况下,jdk.ThreadAllocationStatistics 没有采集到 JFR 相关线程,导致空指针。这个 Bug 和 jdk/jfr/event/compiler/TestCompilerCompile.java failed due to "RuntimeException: No thread in event" 重复.该 BUG 对于使用没有大影响,于 Java 16 修复。
- Per thread IO statistics in JFR,这是一个新特性,期望和 ThreadAllocationStatistics 事件类似,提供每个线程的 IO 数据统计,这个特性还没有通过讨论。
各版本配置:
从 Java 11 引入之后没有改变过:
默认配置(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.jfc of Java 16,default.jfc of Java 17):
配置 | 值 | 描述 |
---|---|---|
enabled | false | 默认不启用 |
period | everyChunk | 在生成每个新 Chunk 文件的时候采集一次 |
采样配置(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):
配置 | 值 | 描述 |
---|---|---|
enabled | true | 默认启用 |
period | everyChunk | 在生成每个新 Chunk 文件的时候采集一次 |
为何需要这个事件?
Java 中业务线程都会分配对象,对于以下关键的业务,对象的分配可能更加频繁。有时候我们可能会遇到以下两个情况:
- 线上应用频繁 GC,可能是先开始 Young GC(New GC,Light GC,不同 GC 叫法不一样),之后伴随着 Old GC 或者 Full GC,可以观察到线上应用占用 CPU 高的线程也是 GC 线程。这个很可能是某个业务 BUG 拉取了大量的数据,例如查询数据库没加条件导致查询整个表,三方接口没限制 limit 返回了超级多的数据。想要直观快速的定位这个问题,可以通过观察那些线程突然分配了很多内存,然后查看这些线程的堆栈进一步确认。jdk.ThreadAllocationStatistics 就是用来查看这个的。
- 线上 GC 变多,想要减少 GC,光看 jmap 对象统计太多抽象,并不直观知道是那些代码创建的这些对象。堆 dump 太重,对于大内存进程分析成本也很大。可以通过 jdk.ThreadAllocationStatistics 查看是那些线程分配对象比较多,采集这些线程的堆栈可以定位相关代码。
事件包含属性
属性 | 说明 | 举例 |
---|---|---|
startTime | 事件开始时间 | 10:16:27.718 |
allocated | 分配过的空间大小 | 10.0 MB |
thread | 线程信息 | "Thread-0" (javaThreadId = 27) |
使用代码测试这个事件
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"; //50ms采集一次 private static long eventPeriodMillis = 50; //对于字节数组对象头占用16字节 private static final int BYTE_ARRAY_OVERHEAD = 16; //我们要测试的对象大小是1kb 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(); //使用 WhiteBox 执行 FullGC,清除干扰 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(); //再等待一段时间让定时采集 jdk.ThreadAllocationStatistics 采集到最新的 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)) { //事件是时间有序的(采集时间比较短),所以放入的最后一个就是采集到的线程最终的分配大小 threadAllocatedMap.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 { //期望每个采集周期之间的分配次数为 5 Thread.sleep(eventPeriodMillis / 5); } catch (InterruptedException e) { e.printStackTrace(); } } //获取当前线程分配的对象大小 totalAllocated = getThreadAllocatedBytes(); allocationsDoneLatch.countDown(); //设置线程为守护线程,等待主线程结束之后会自动结束 //这里进入死循环是因为防止定时采集 jdk.ThreadAllocationStatistics 事件的时候采集不到 while (true) { Thread.yield(); } } private long getThreadAllocatedBytes() { ThreadMXBean bean = (ThreadMXBean) ManagementFactory.getThreadMXBean(); return bean.getThreadAllocatedBytes(Thread.currentThread().getId()); } } }
使用以下 JVM 参数启动:
-Xbootclasspath/a:D:\github\jfr-spring-all\jdk-white-box\target\jdk-white-box-17.0-SNAPSHOT.jar -Xms512m -Xmx512m -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xlog:gc
输出结果:
[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
底层原理以及相关 JVM 源码
每隔配置的间隔,就会调用
requestThreadAllocationStatistics(void)方法采集每一个线程的分配信息:
#define TRACE_REQUEST_FUNC(id) void JfrPeriodicEventSet::request##id(void) //使用了宏定义函数,实际函数就是 requestThreadAllocationStatistics(void) TRACE_REQUEST_FUNC(ThreadAllocationStatistics) { ResourceMark rm; //获取线程数量,虽然后面线程数量在采集过程中可能会改变,利用这个值初始化数组 int initial_size = Threads::number_of_threads(); //建立一个数组记录每个线程的分配大小 GrowableArray<jlong> allocated(initial_size); //建立一个数组记录线程号,和上面那个数组一一对应 GrowableArray<traceid> thread_ids(initial_size); //记录当前时间 JfrTicks time_stamp = JfrTicks::now(); //新建一个 JfrJavaThreadIterator 来遍历每个线程 JfrJavaThreadIterator iter; while (iter.has_next()) { JavaThread* const jt = iter.next(); assert(jt != NULL, "invariant"); //读取每个线程的 cooked_allocated_bytes() allocated.append(jt->cooked_allocated_bytes()); //记录线程号(包括系统线程号以及 Java 线程号) thread_ids.append(JFR_THREAD_ID(jt)); } //遍历数组,生成 JFR 事件并采集 for(int i = 0; i < thread_ids.length(); i++) { EventThreadAllocationStatistics event(UNTIMED); //设置当前线程已分配大小 event.set_allocated(allocated.at(i)); //设置线程信息 event.set_thread(thread_ids.at(i)); //设置结束时间 event.set_endtime(time_stamp); event.commit(); } }
统计线程的分配内存的大小方法即
cooked_allocated_bytes()方法的源码如下:
thread.inline.hpp
inline jlong Thread::cooked_allocated_bytes() { //原子读取 _allocated_bytes jlong allocated_bytes = Atomic::load_acquire(&_allocated_bytes); //如果开启了 TLAB(默认开启),则需要查看下当前线程的 TLAB 已经分配的对象大小 if (UseTLAB) { //统计当前线程的 TLAB 已经分配的大小 size_t used_bytes = tlab().used_bytes(); //如果当前 TLAB 在初始化,或者全局 TLAB 在初始化,会发生 used_bytes > max_size 的情况,忽略这种情况。 if (used_bytes <= ThreadLocalAllocBuffer::max_size_in_bytes()) { //这样统计其实有可能有点问题,即发生 TLAB retire 的时候,_allocated_bytes 会加上 used_bytes 之后申请一个新的 TLAB,这时候调用这个方法可能会把这个 used_bytes 加了两遍 return allocated_bytes + used_bytes; } } return allocated_bytes; }
那么哪里会修改
_allocated_bytes这个变量呢?有两个地方,一个是发生 TLAB 外分配的时候,另一个是发生 TLAB retire 的时候。 TLAB retire 是在发生 GC 以及 TLAB 满了并且剩余空间小于当前最大浪费空间限制的时候会重新申请一个新的 TLAB 进行分配,申请新的之前需要将当前 TLAB retire。
发生 TLAB 外分配修改
_allocated_bytes对应源码:
//如果是 TLAB 外分配,会调用这个方法 HeapWord* MemAllocator::allocate_outside_tlab(Allocation& allocation) const { //标记当前分配为 TLAB 外分配 allocation._allocated_outside_tlab = true; //执行 TLAB 外分配,不同 GC 不同 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; //增加 _allocated_bytes 当前分配的字节大小 _thread->incr_allocated_bytes(size_in_bytes); return mem; }
TLAB retire 对应源码:
threadLocalAllocBuffer.cpp
void ThreadLocalAllocBuffer::retire(ThreadLocalAllocStats* stats) { if (stats != NULL) { accumulate_and_reset_statistics(stats); } if (end() != NULL) { invariants(); //将当前 TLAB 使用的字节数加到 _allocated_bytes //从这里可以看出,如果这个方法和 cooked_allocated_bytes() 同时被调用,可能 used_bytes 被加了两遍。 thread()->incr_allocated_bytes(used_bytes()); insert_filler(); initialize(NULL, NULL, NULL); } }
我们再来看看 JMX 中查看线程分配内存大小的具体实现。首先对应的 JMX 的代码是:
//我们示例中底层调用的实际就是这个方法获取线程分配的内存大小 protected long getThreadAllocatedBytes(long id) { boolean verified = verifyThreadAllocatedMemory(id); if (verified) { //调用 getThreadAllocatedMemory0 获取分配的内存大小 return getThreadAllocatedMemory0( Thread.currentThread().getId() == id ? 0 : id); } return -1; } //getThreadAllocatedMemory0 是一个 native 方法 private static native long getThreadAllocatedMemory0(long id);
这个 native 方法对应的 JVM 源码是:ThreadImpl.c
JNIEXPORT jlong JNICALL Java_sun_management_ThreadImpl_getThreadAllocatedMemory0 (JNIEnv *env, jclass cls, jlong tid) { //实际实现方法是 GetOneThreadAllocatedMemory return jmm_interface->GetOneThreadAllocatedMemory(env, tid); }
JVM_ENTRY(jlong, jmm_GetOneThreadAllocatedMemory(JNIEnv *env, jlong thread_id)) if (thread_id < 0) { THROW_MSG_(vmSymbols::java_lang_IllegalArgumentException(), "Invalid thread ID", -1); } //获取当前线程 if (thread_id == 0) { // current thread //调用 cooked_allocated_bytes,和采集 jdk.ThreadAllocationStatistics 调用的底层方法一样 return thread->cooked_allocated_bytes(); } //根据线程号获取线程 ThreadsListHandle tlh; JavaThread* java_thread = tlh.list()->find_JavaThread_from_java_tid(thread_id); if (java_thread != NULL) { //调用 cooked_allocated_bytes,和采集 jdk.ThreadAllocationStatistics 调用的底层方法一样 return java_thread->cooked_allocated_bytes(); } return -1; JVM_END
可以看出,其实底层调用的和 JFR 采集 jdk.ThreadAllocationStatistics 事件一样,都是调用 Thread 的
cooked_allocated_bytes()方法。
针对这个 JFR 事件的一些思考
首先,提出一个观点,jdk.ThreadAllocationStatistics 这个事件并不太消耗性能。原因有二:
- 统计线程分配大小是近似统计,并不需要进入全局安全点统计。同时也代表,jdk.ThreadAllocationStatistics 同一时间的不同线程事件的分配大小实际并不是同一时间点的,因为没有进入安全点暂停所有线程。
- 统计仅仅是原子读取每个线程的分配对象大小这个变量,之后加上每个线程当前 TLAB 分配对象大小(这个大小是通过读取两个指针地址获取的),可以看出操作是很轻量级的。即使有很多线程,也不会增加多少性能负担。
然后,默认配置的采集周期,并不能满足我们的需求。默认的采集周期是 everyChunk,默认的 chunk 大小(maxchunksize)是 12M,也就是每采集 12M 的 JFR 事件之后,采集一次 jdk.ThreadAllocationStatistics。这是不太可控的,我一般配置为每过 5s 采集一次。这样对于我们上面提到的那两个需要这个事件的场景也是很适合的。
微信搜索“我的编程喵”关注公众号,加作者微信,每日一刷,轻松提升技术,斩获各种offer:
- 按照自己的思路去研究Spring AOP源码【1】
- 太顶了!爆肝3.5W字长文详解Java 集合!(建议收藏)
- 深入理解Java并发框架AQS系列(五):条件队列(Condition)
- dubbo学习实践(4)之Springboot整合Dubbo及Hystrix服务熔断降级
- Java 常用类总结(SE基础)
- Spring Boot 2从入门到入坟 | 底层注解篇:@Configuration详解
- Java多线程详解——一篇文章搞懂Java多线程
- 史上最全java范型讲解
- han_spring
- Java应用AES对称解密遭遇异常处理方法
- Java应用AES对称解密遭遇异常处理方法
- SpringBoot启动后直接退出 控制台显示Process finished with exit code 1
- hive-19994 bug java.sql.BatchUpdateException
- Java基础语法(七)——类和对象
- Spring Boot——我的第一个Spring Boot程序
- 知识点:Java HashMap 原理与源码分析(下)
- 【Azure Developer】使用Java SDK代码创建Azure VM (包含设置NSG,及添加数据磁盘SSD)
- Java JFR 民间指南 - 事件详解 - jdk.ObjectAllocationSample
- Java on Visual Studio Code的更新 – 2021年3月
- springcloud面试题【第二期】