全网最硬核 JVM TLAB 分析(额外加菜) 8. 通过 JFR 监控 TLAB

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介: 全网最硬核 JVM TLAB 分析(额外加菜) 8. 通过 JFR 监控 TLAB
今天,又是干货满满的一天。这是全网最硬核 JVM 系列的开篇,首先从 TLAB 开始。由于文章很长,每个人阅读习惯不同,所以特此拆成单篇版和多篇版


12. 监控 TLAB 慢分配与 TLAB 外分配 - JFR 相关事件解析


我们可以通过 JFR 来监控 TLAB 慢分配或者 TLAB 外分配事件。也就是jdk.ObjectAllocationOutsideTLABjdk.ObjectAllocationInNewTLAB这两个事件。

jdk.ObjectAllocationOutsideTLABjdk.ObjectAllocationInNewTLAB 这两个事件在default.jfc中( JFR 默认事件采集配置)是没有开启采集的:

<event name="jdk.ObjectAllocationInNewTLAB">
  <setting name="enabled">false</setting>
  <setting name="stackTrace">true</setting>
</event>
<event name="jdk.ObjectAllocationOutsideTLAB">
  <setting name="enabled">false</setting>
  <setting name="stackTrace">true</setting>
</event>

一般的,采集这两个事件,是需要连着堆栈一起采集,但是无法通过持续时间(因为这个事件没有持续时间这一概念)限制采集哪些,也就是只要开启就是全部采集,所以不建议长期开启这个采集。而是通过一些其他的监控项,按照需要,动态开启这个采集一段时间,之后关闭并 dump 出 JFR 文件用于分析。

那么一般根据什么指标判断呢?一般的,当 Young GC 过于频繁时,我们就要考虑是不是由于 TLAB 造成很多空间被浪费导致 GC 频繁了。至于如果采集 Young GC 频率从而动态开启,这个会在后面的动态监控章节详细说明。

我们还用上面的程序,根据之前的日志,对于 1KB 的对象,应该有两次 jdk.ObjectAllocationInNewTLAB 事件,第一次是线程第一次申请 TLAB,第二次是在分配第 512 个对象的时候,TLAB 剩余空间不足,同时剩余空间小于最大浪费空间限制,所以申请新的 TLAB 分配。对于 1KB 的分配,没有发生 jdk.ObjectAllocationOutsideTLAB。对于 100KB 的对象分配,在第五次分配时,TLAB 剩余空间不足,但是剩余空间大于最大浪费空间限制,直接在 Eden 区分配,同时将最大浪费空间限制增加 4。在第 114 次对象分配时,最大浪费空间限制达到了剩余空间,所以申请新的 TLAB 分配。所以对于 100KB 对象的 200 次分配里面,jdk.ObjectAllocationInNewTLAB也只有两次。

同时由于开启了 JFR,导致 TLAB 可能会被占用一部分,所以上面说的这些次数可能不太准确,不过没关系,大体上应该是对的。

//对于字节数组对象头占用16字节
private static final int BYTE_ARRAY_OVERHEAD = 16;
//我们要测试的对象大小是100kb
private static final int OBJECT_SIZE = 100 * 1024;
//需要使用静态field,而不是方法内本地变量,否则编译后循环内的new byte[]全部会被省略,只剩最后一次的
public static byte[] tmp;
public static void main(String[] args) throws Exception {
    WhiteBox whiteBox = WhiteBox.getWhiteBox();
    //初始化 JFR 记录
    Recording recording = new Recording();
    //启用 jdk.ObjectAllocationOutsideTLAB 事件监控
    recording.enable("jdk.ObjectAllocationOutsideTLAB");
    recording.enable("jdk.ObjectAllocationInNewTLAB");
    // JFR 记录启动
    recording.start();
    //强制 fullGC 防止接下来程序发生 GC
    //同时可以区分出初始化带来的其他线程的TLAB相关的日志
    whiteBox.fullGC();
    //分配对象,大小1KB
    for (int i = 0; i < 512; ++i) {
        tmp = new byte[OBJECT_SIZE - BYTE_ARRAY_OVERHEAD];
    }
    //强制 fullGC,回收所有 TLAB
    whiteBox.fullGC();
    //分配对象,大小100KB
    for (int i = 0; i < 200; ++i) {
        tmp = new byte[OBJECT_SIZE * 100 - BYTE_ARRAY_OVERHEAD];
    }
    whiteBox.fullGC();
    //将 JFR 记录 dump 到一个文件
    Path path = new File(new File(".").getAbsolutePath(), "recording-" + recording.getId() + "-pid" + ProcessHandle.current().pid() + ".jfr").toPath();
    recording.dump(path);
    int countOf1KBObjectAllocationInNewTLAB = 0;
    int countOf100KBObjectAllocationInNewTLAB = 0;
    int countOf1KBObjectAllocationOutsideTLAB = 0;
    int countOf100KBObjectAllocationOutsideTLAB = 0;
    //读取文件中的所有 JFR 事件
    for (RecordedEvent event : RecordingFile.readAllEvents(path)) {
        //获取分配的对象的类型
        String className = event.getString("objectClass.name");
        if (
            //确保分配类型是 byte[]
                BYTE_ARRAY_CLASS_NAME.equalsIgnoreCase(className)
        ) {
            RecordedFrame recordedFrame = event.getStackTrace().getFrames().get(0);
            //同时必须是咱们这里的main方法分配的对象,并且是Java堆栈中的main方法
            if (recordedFrame.isJavaFrame()
                    && "main".equalsIgnoreCase(recordedFrame.getMethod().getName())
            ) {
                //获取分配对象大小
                long allocationSize = event.getLong("allocationSize");
                //统计各种事件个数
                if ("jdk.ObjectAllocationOutsideTLAB".equalsIgnoreCase(event.getEventType().getName())) {
                    if (allocationSize == 102400) {
                        countOf100KBObjectAllocationOutsideTLAB++;
                    } else if (allocationSize == 1024) {
                        countOf1KBObjectAllocationOutsideTLAB++;
                    }
                } else if ("jdk.ObjectAllocationInNewTLAB".equalsIgnoreCase(event.getEventType().getName())) {
                    if (allocationSize == 102400) {
                        countOf100KBObjectAllocationInNewTLAB++;
                    } else if (allocationSize == 1024) {
                        countOf1KBObjectAllocationInNewTLAB++;
                    }
                } else {
                    throw new Exception("unexpected size of TLAB event");
                }
                System.out.println(event);
            }
        }
    }
    System.out.println("countOf1KBObjectAllocationInNewTLAB: " + countOf1KBObjectAllocationInNewTLAB);
    System.out.println("countOf100KBObjectAllocationInNewTLAB: " + countOf100KBObjectAllocationInNewTLAB);
    System.out.println("countOf1KBObjectAllocationOutsideTLAB: " + countOf1KBObjectAllocationOutsideTLAB);
    System.out.println("countOf100KBObjectAllocationOutsideTLAB: " + countOf100KBObjectAllocationOutsideTLAB);
    //阻塞程序,保证所有日志输出完
    Thread.currentThread().join();
}

输出应该近似于:

//省略其他事件的详细信息,这里每种挑一个展示
jdk.ObjectAllocationInNewTLAB {
  startTime = 13:07:51.681
  objectClass = byte[] (classLoader = bootstrap)
  allocationSize = 1.0 kB
  tlabSize = 478.2 kB
  eventThread = "main" (javaThreadId = 1)
  stackTrace = [
    com.github.hashjang.jfr.test.TestAllocOutsideTLAB.main(String[]) line: 96
  ]
}
jdk.ObjectAllocationInNewTLAB {
  startTime = 13:07:51.777
  objectClass = byte[] (classLoader = bootstrap)
  allocationSize = 100.0 kB
  tlabSize = 512.0 kB
  eventThread = "main" (javaThreadId = 1)
  stackTrace = [
    com.github.hashjang.jfr.test.TestAllocOutsideTLAB.main(String[]) line: 102
  ]
}
jdk.ObjectAllocationOutsideTLAB {
  startTime = 13:07:51.784
  objectClass = byte[] (classLoader = bootstrap)
  allocationSize = 100.0 kB
  eventThread = "main" (javaThreadId = 1)
  stackTrace = [
    com.github.hashjang.jfr.test.TestAllocOutsideTLAB.main(String[]) line: 102
  ]
}
//省略其他事件的详细信息,这里每种挑一个展示
countOf1KBObjectAllocationInNewTLAB: 2
countOf100KBObjectAllocationInNewTLAB: 2
countOf1KBObjectAllocationOutsideTLAB: 0
countOf100KBObjectAllocationOutsideTLAB: 190

可以看出jdk.ObjectAllocationInNewTLAB包含:

  • 开始时间:startTime = 13:07:51.784
  • 分配对象类型:objectClass = byte[] (classLoader = bootstrap)
  • 分配大小:allocationSize = 100.0 kB
  • 新的 TLAB 大小:tlabSize = 512.0 kB
  • 线程:eventThread = "main" (javaThreadId = 1)
  • 堆栈

jdk.ObjectAllocationOutsideTLAB包含:

  • 开始时间:startTime = 13:07:51.784
  • 分配对象类型:objectClass = byte[] (classLoader = bootstrap)
  • 分配大小:allocationSize = 100.0 kB
  • 线程:eventThread = "main" (javaThreadId = 1)
  • 堆栈

我们一般通过 JMC 查看 JFR 监控的文件,通过事件查看器就可以查看其中的事件,可以参考我的另一系列:JFR 全解

相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
相关文章
|
2月前
|
监控 算法 Java
jvm-48-java 变更导致压测应用性能下降,如何分析定位原因?
【11月更文挑战第17天】当JVM相关变更导致压测应用性能下降时,可通过检查变更内容(如JVM参数、Java版本、代码变更)、收集性能监控数据(使用JVM监控工具、应用性能监控工具、系统资源监控)、分析垃圾回收情况(GC日志分析、内存泄漏检查)、分析线程和锁(线程状态分析、锁竞争分析)及分析代码执行路径(使用代码性能分析工具、代码审查)等步骤来定位和解决问题。
|
2月前
|
Arthas Prometheus 监控
监控堆外使用JVM工具
监控堆外使用JVM工具
49 7
|
2月前
|
监控 Java Spring
JVM如何监控某个方法的入参和相应结果?
JVM如何监控某个方法的入参和相应结果?
40 0
|
3月前
|
Arthas 监控 数据可视化
JVM进阶调优系列(7)JVM调优监控必备命令、工具集合|实用干货
本文介绍了JVM调优监控命令及其应用,包括JDK自带工具如jps、jinfo、jstat、jstack、jmap、jhat等,以及第三方工具如Arthas、GCeasy、MAT、GCViewer等。通过这些工具,可以有效监控和优化JVM性能,解决内存泄漏、线程死锁等问题,提高系统稳定性。文章还提供了详细的命令示例和应用场景,帮助读者更好地理解和使用这些工具。
|
3月前
|
小程序 Oracle Java
JVM知识体系学习一:JVM了解基础、java编译后class文件的类结构详解,class分析工具 javap 和 jclasslib 的使用
这篇文章是关于JVM基础知识的介绍,包括JVM的跨平台和跨语言特性、Class文件格式的详细解析,以及如何使用javap和jclasslib工具来分析Class文件。
63 0
JVM知识体系学习一:JVM了解基础、java编译后class文件的类结构详解,class分析工具 javap 和 jclasslib 的使用
|
3月前
|
存储 Java PHP
【JVM】垃圾回收机制(GC)之引用计数和可达性分析
【JVM】垃圾回收机制(GC)之引用计数和可达性分析
90 0
|
6月前
|
Java
jmap 查看jvm内存大小并进行dump文件内存分析
jmap 查看jvm内存大小并进行dump文件内存分析
144 3
|
6月前
|
运维 监控 Java
(十)JVM成神路之线上故障排查、性能监控工具分析及各线上问题排错实战
经过前述九章的JVM知识学习后,咱们对于JVM的整体知识体系已经有了全面的认知。但前面的章节中,更多的是停留在理论上进行阐述,而本章节中则更多的会分析JVM的实战操作。
147 1
|
6月前
|
Arthas 监控 Java
JVM内存问题之使用gperftools分析JNI Memory泄漏的具体步骤是什么
JVM内存问题之使用gperftools分析JNI Memory泄漏的具体步骤是什么
147 2
|
6月前
|
存储 消息中间件 监控
JVM内存问题之ARMS监控显示堆内存和我设置的不同如何解决
JVM内存问题之ARMS监控显示堆内存和我设置的不同如何解决