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

本文主要是介绍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 引入之后没有改变过:

默认配置(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):

配置描述
enabledfalse默认不启用
periodeveryChunk在生成每个新 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):

配置描述
enabledtrue默认启用
periodeveryChunk在生成每个新 Chunk 文件的时候采集一次

为何需要这个事件?

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 查看是那些线程分配对象比较多,采集这些线程的堆栈可以定位相关代码。

事件包含属性

属性说明举例
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;//我们要测试的对象大小是1kbprivate 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;}@Overridepublic void run() {for (int batches = 0; batches < 100; batches++) {for (int i = 0; i < 1024; i++) {buffer = new byte[allocationSize];}try {//期望每个采集周期之间的分配次数为 5Thread.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.915allocated = 1.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:29.915allocated = 2.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:29.915allocated = 3.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:29.915allocated = 4.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:29.965allocated = 6.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:29.965allocated = 12.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:29.965allocated = 15.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:29.965allocated = 20.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.015allocated = 10.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.015allocated = 20.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.015allocated = 27.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.015allocated = 36.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.066allocated = 15.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.066allocated = 28.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.066allocated = 39.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.066allocated = 50.3 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.116allocated = 19.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.116allocated = 36.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.116allocated = 51.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.116allocated = 64.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.167allocated = 24.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.167allocated = 44.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.167allocated = 63.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.167allocated = 80.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.217allocated = 28.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.217allocated = 52.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.217allocated = 75.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.217allocated = 96.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.268allocated = 32.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.268allocated = 61.3 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.268allocated = 87.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.268allocated = 109.5 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.319allocated = 37.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.319allocated = 68.3 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.319allocated = 99.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.319allocated = 124.3 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.370allocated = 41.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.370allocated = 78.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.370allocated = 111.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.370allocated = 144.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.420allocated = 45.4 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.420allocated = 86.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.420allocated = 126.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.420allocated = 160.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.470allocated = 50.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.470allocated = 96.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.470allocated = 138.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.470allocated = 180.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.520allocated = 54.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.520allocated = 104.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.520allocated = 150.4 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.520allocated = 196.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.571allocated = 58.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.571allocated = 112.3 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.571allocated = 165.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.571allocated = 212.5 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.621allocated = 63.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.621allocated = 122.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.621allocated = 180.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.621allocated = 232.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.671allocated = 67.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.671allocated = 130.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.671allocated = 192.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.671allocated = 248.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.722allocated = 72.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.722allocated = 140.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.722allocated = 207.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.722allocated = 268.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.772allocated = 76.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.772allocated = 148.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.772allocated = 219.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.772allocated = 284.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.581allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.581allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.581allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.581allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.631allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.631allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.631allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.631allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.682allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.682allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.682allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.682allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.732allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.732allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.732allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.732allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.823allocated = 81.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.823allocated = 158.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.823allocated = 234.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.823allocated = 304.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.874allocated = 85.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.874allocated = 166.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.874allocated = 246.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.874allocated = 320.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.925allocated = 90.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.925allocated = 176.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.925allocated = 258.5 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.925allocated = 340.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.975allocated = 94.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.975allocated = 184.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.975allocated = 273.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:30.975allocated = 356.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.024allocated = 99.0 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.024allocated = 194.0 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.024allocated = 285.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.024allocated = 372.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.075allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.075allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.075allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.075allocated = 392.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.126allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.126allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.126allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.126allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.177allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.177allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.177allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.177allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.228allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.228allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.228allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.228allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.278allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.278allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.278allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.278allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.329allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.329allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.329allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.329allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.379allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.379allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.379allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.379allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.429allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.429allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.429allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.429allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.479allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.479allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.479allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.479allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.530allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.530allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.530allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.530allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.791allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.791allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.791allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.791allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.842allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.842allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.842allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.842allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.892allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.892allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.892allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.892allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.943allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.943allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.943allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.943allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.993allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.993allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.993allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:31.993allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:32.043allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:32.043allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:32.043allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:32.043allocated = 400.0 MBthread = "Thread-3" (javaThreadId = 30)
}jdk.ThreadAllocationStatistics {startTime = 12:41:32.093allocated = 100.3 MBthread = "Thread-0" (javaThreadId = 27)
}jdk.ThreadAllocationStatistics {startTime = 12:41:32.093allocated = 200.1 MBthread = "Thread-1" (javaThreadId = 28)
}jdk.ThreadAllocationStatistics {startTime = 12:41:32.093allocated = 300.0 MBthread = "Thread-2" (javaThreadId = 29)
}jdk.ThreadAllocationStatistics {startTime = 12:41:32.093allocated = 400.0 MBthread = "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) 方法采集每一个线程的分配信息:

jfrPeriodic.cpp

#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_bytesjlong 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 对应源码:

memAllocator.cpp

//如果是 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)
{//实际实现方法是 GetOneThreadAllocatedMemoryreturn jmm_interface->GetOneThreadAllocatedMemory(env, tid);
}

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);}//获取当前线程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 这个事件并不太消耗性能。原因有二:

  1. 统计线程分配大小是近似统计,并不需要进入全局安全点统计。同时也代表,jdk.ThreadAllocationStatistics 同一时间的不同线程事件的分配大小实际并不是同一时间点的,因为没有进入安全点暂停所有线程
  2. 统计仅仅是原子读取每个线程的分配对象大小这个变量,之后加上每个线程当前 TLAB 分配对象大小(这个大小是通过读取两个指针地址获取的),可以看出操作是很轻量级的。即使有很多线程,也不会增加多少性能负担

然后,默认配置的采集周期,并不能满足我们的需求。默认的采集周期是 everyChunk,默认的 chunk 大小(maxchunksize)是 12M,也就是每采集 12M 的 JFR 事件之后,采集一次 jdk.ThreadAllocationStatistics。这是不太可控的,我一般配置为每过 5s 采集一次。这样对于我们上面提到的那两个需要这个事件的场景也是很适合的。

微信搜索“我的编程喵”关注公众号,加作者微信,每日一刷,轻松提升技术,斩获各种offer

image

这篇关于Java JFR 民间指南 - 事件详解 - jdk.ThreadAllocationStatistics的文章就介绍到这儿,希望我们推荐的文章对编程师们有所帮助!



http://www.chinasem.cn/article/375145

相关文章

Linux线程同步/互斥过程详解

《Linux线程同步/互斥过程详解》文章讲解多线程并发访问导致竞态条件,需通过互斥锁、原子操作和条件变量实现线程安全与同步,分析死锁条件及避免方法,并介绍RAII封装技术提升资源管理效率... 目录01. 资源共享问题1.1 多线程并发访问1.2 临界区与临界资源1.3 锁的引入02. 多线程案例2.1 为

分布式锁在Spring Boot应用中的实现过程

《分布式锁在SpringBoot应用中的实现过程》文章介绍在SpringBoot中通过自定义Lock注解、LockAspect切面和RedisLockUtils工具类实现分布式锁,确保多实例并发操作... 目录Lock注解LockASPect切面RedisLockUtils工具类总结在现代微服务架构中,分布

Java使用Thumbnailator库实现图片处理与压缩功能

《Java使用Thumbnailator库实现图片处理与压缩功能》Thumbnailator是高性能Java图像处理库,支持缩放、旋转、水印添加、裁剪及格式转换,提供易用API和性能优化,适合Web应... 目录1. 图片处理库Thumbnailator介绍2. 基本和指定大小图片缩放功能2.1 图片缩放的

Spring Boot集成/输出/日志级别控制/持久化开发实践

《SpringBoot集成/输出/日志级别控制/持久化开发实践》SpringBoot默认集成Logback,支持灵活日志级别配置(INFO/DEBUG等),输出包含时间戳、级别、类名等信息,并可通过... 目录一、日志概述1.1、Spring Boot日志简介1.2、日志框架与默认配置1.3、日志的核心作用

Python使用Tenacity一行代码实现自动重试详解

《Python使用Tenacity一行代码实现自动重试详解》tenacity是一个专为Python设计的通用重试库,它的核心理念就是用简单、清晰的方式,为任何可能失败的操作添加重试能力,下面我们就来看... 目录一切始于一个简单的 API 调用Tenacity 入门:一行代码实现优雅重试精细控制:让重试按我

破茧 JDBC:MyBatis 在 Spring Boot 中的轻量实践指南

《破茧JDBC:MyBatis在SpringBoot中的轻量实践指南》MyBatis是持久层框架,简化JDBC开发,通过接口+XML/注解实现数据访问,动态代理生成实现类,支持增删改查及参数... 目录一、什么是 MyBATis二、 MyBatis 入门2.1、创建项目2.2、配置数据库连接字符串2.3、入

Springboot项目启动失败提示找不到dao类的解决

《Springboot项目启动失败提示找不到dao类的解决》SpringBoot启动失败,因ProductServiceImpl未正确注入ProductDao,原因:Dao未注册为Bean,解决:在启... 目录错误描述原因解决方法总结***************************APPLICA编

深度解析Spring Security 中的 SecurityFilterChain核心功能

《深度解析SpringSecurity中的SecurityFilterChain核心功能》SecurityFilterChain通过组件化配置、类型安全路径匹配、多链协同三大特性,重构了Spri... 目录Spring Security 中的SecurityFilterChain深度解析一、Security

SpringBoot多环境配置数据读取方式

《SpringBoot多环境配置数据读取方式》SpringBoot通过环境隔离机制,支持properties/yaml/yml多格式配置,结合@Value、Environment和@Configura... 目录一、多环境配置的核心思路二、3种配置文件格式详解2.1 properties格式(传统格式)1.

Apache Ignite 与 Spring Boot 集成详细指南

《ApacheIgnite与SpringBoot集成详细指南》ApacheIgnite官方指南详解如何通过SpringBootStarter扩展实现自动配置,支持厚/轻客户端模式,简化Ign... 目录 一、背景:为什么需要这个集成? 二、两种集成方式(对应两种客户端模型) 三、方式一:自动配置 Thick