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

冷不防 2022-10-27 12:19 142阅读 0赞

> 今天，又是干货满满的一天。这是全网最硬核 JVM 系列的开篇，首先从 TLAB 开始。由于文章很长，每个人阅读习惯不同，所以特此拆成单篇版和多篇版

*  [全网最硬核 JVM TLAB 分析（单篇版不包含额外加菜）][JVM TLAB]
 *  [全网最硬核 JVM TLAB 分析 1. 内存分配思想引入][JVM TLAB _ 1.]
 *  [全网最硬核 JVM TLAB 分析 2. TLAB生命周期与带来的问题思考][JVM TLAB _ 2. TLAB]
 *  [全网最硬核 JVM TLAB 分析 3. JVM EMA期望算法与TLAB相关JVM启动参数][JVM TLAB _ 3. JVM EMA_TLAB_JVM]
 *  [全网最硬核 JVM TLAB 分析 4. TLAB 基本流程全分析][JVM TLAB _ 4. TLAB]
 *  [全网最硬核 JVM TLAB 分析 5. TLAB 源代码全解析][JVM TLAB _ 5. TLAB]
 *  [全网最硬核 JVM TLAB 分析 6. TLAB 相关热门Q&A汇总][JVM TLAB _ 6. TLAB _Q_A]
 *  [全网最硬核 JVM TLAB 分析(额外加菜) 7. TLAB 相关 JVM 日志解析][JVM TLAB _ 7. TLAB _ JVM]
 *  [全网最硬核 JVM TLAB 分析(额外加菜) 8. 通过 JFR 监控 TLAB][JVM TLAB _ 8. _ JFR _ TLAB]

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

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

`jdk.ObjectAllocationOutsideTLAB` 和 `jdk.ObjectAllocationInNewTLAB` 这两个事件在[`default.jfc`][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 全解][JFR]

[JVM TLAB]: https://zhanghaoxin.blog.csdn.net/article/details/113625536
[JVM TLAB _ 1.]: https://zhanghaoxin.blog.csdn.net/article/details/113625581
[JVM TLAB _ 2. TLAB]: https://zhanghaoxin.blog.csdn.net/article/details/113625597
[JVM TLAB _ 3. JVM EMA_TLAB_JVM]: https://zhanghaoxin.blog.csdn.net/article/details/113625614
[JVM TLAB _ 4. TLAB]: https://zhanghaoxin.blog.csdn.net/article/details/113625627
[JVM TLAB _ 5. TLAB]: https://zhanghaoxin.blog.csdn.net/article/details/113625645
[JVM TLAB _ 6. TLAB _Q_A]: https://zhanghaoxin.blog.csdn.net/article/details/113625667
[JVM TLAB _ 7. TLAB _ JVM]: https://zhanghaoxin.blog.csdn.net/article/details/113625714
[JVM TLAB _ 8. _ JFR _ TLAB]: https://zhanghaoxin.blog.csdn.net/article/details/113625743
[default.jfc]: https://github.com/openjdk/jdk/blob/master/src/jdk.jfr/share/conf/jfr/default.jfc
[JFR]: https://blog.csdn.net/zhxdick/category_9860048.html