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的主要内容,如果未能解决你的问题,请参考以下文章

JDK14的新特性:JFR,JMC和JFR事件流

JDK14的新特性:JFR,JMC和JFR事件流

内置 JFR(Java Flight Recorder)事件记录在哪里?

如何创建可重用的即时(持续时间)Java Flight Recorder JFR 事件?

如何识别 JFR 事件类型

为啥 JFR 会跳过事件字段