Java-JFR-民间指南---事件详解---jdk-ThreadAllocationStatistics

定时线程分配统计事件：jdk.ThreadAllocationStatistics
引入版本：Java 11

相关 ISSUES：

1.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 修复。

2.Per thread IO statistics in JFR ，这是一个新特性，期望和 ThreadAllocationStatistics 事件类似，提供每个线程的 IO 数据统计，这个特性还没有通过讨论。

各版本配置：
从 Java 11 引入之后没有改变过：

采样配置（ 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 ）:

为何需要这个事件？
Java 中业务线程都会分配对象，对于以下关键的业务，对象的分配可能更加频繁。有时候我们可能会遇到以下两个情况：

1.线上应用频繁 GC，可能是先开始 Young GC（New GC，Light GC，不同 GC 叫法不一样），之后伴随着 Old GC 或者 Full GC，可以观察到线上应用占用 CPU 高的线程也是 GC 线程。 这个很可能是某个业务 BUG 拉取了大量的数据 ，例如查询数据库没加条件导致查询整个表，三方接口没限制 limit 返回了超级多的数据。想要直观快速的定位这个问题，可以通 过观察那些线程突然分配了很多内存 ，然后查看这些线程的堆栈进一步确认。 jdk.ThreadAllocationStatistics 就是用来查看这个的 。

2.线上 GC 变多，想要减少 GC，光看 jmap 对象统计太多抽象，并不直观知道是那些代码创建的这些对象。堆 dump 太重，对于大内存进程分析成本也很大。可以通过 jdk.ThreadAllocationStatistics 查看是那些线程分配对象比较多，采集这些线程的堆栈可以定位相关代码。

事件包含属性

使用代码测试这个事件

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 =