Java JFR 民间指南 - 事件详解 - jdk.ThreadAllocationStatistics
Posted Java_Pluto
tags:
篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了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 = 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 = 以上是关于Java JFR 民间指南 - 事件详解 - jdk.ThreadAllocationStatistics的主要内容,如果未能解决你的问题,请参考以下文章
内置 JFR(Java Flight Recorder)事件记录在哪里?