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