通过 JFR 与日志深入探索 JVM - 1. JFR 简介与发展

一时失言乱红尘 2022-12-29 04:40 242阅读 0赞

> 全系列目录：[通过 JFR 与日志深入探索 JVM - 总览篇][JFR _ JVM -]

## 什么是 Java Flight Record ##

我们都知道，黑匣子是用于记录飞机飞行和性能参数的仪器。在飞机出问题后，用于定位问题原因。**JFR（Java Flight Record）** 就是 Java 的黑匣子。

JFR 是 Java Flight Record （Java飞行记录） 的缩写，是 **JVM 内置的基于事件的JDK监控记录框架**。这个起名就是参考了黑匣子对于飞机的作用，将 Java 进程比喻成飞机飞行。顾名思义，这个记录主要用于问题定位和持续监控。

在线上出问题时，我们一般首要任务是快速恢复，而不是保留现场等问题定位好解决好。而快速恢复一般需要重启，或者简单改一些代码之后发布重启，或者回滚到上一个版本的代码之后发布重启，这些都会破坏现场。持续采集的意义就在于事后定位分析问题，JFR 就是这样一种主要用于问题定位和持续监控的 Java 事件记录。

如果是利用默认配置启动这个记录，性能非常高效，对于业务影响很小（当然，对于**大部分应用是这样的**，对于**某些特殊的应用，例如线程密集有好几万线程的应用，或者是内存特别大达到几个 TB 级别的进程，默认的 JFR 配置可是不行的**），因为这个框架本来就是用来长期在线上部署的框架。这个记录可以输出成**二进制文件**，用户可以指定最大记录时间，或者最大记录大小，供用户在需要的时候输出成文件进行事后分析。

## JFR 的前世今生 ##

JFR 的前身也是 JFR，只不过这个 J 不是 Java 而是 **JRockit**。在 JRockit 虚拟机时代，就有这样一个工具用来记录 Java 虚拟机运行时各项数据。在 Oracle 收购 Sun 公司之后，**Hotspot 虚拟机时代，也一直延续了这个工具**：

*  JFR 0.9 版本对应 JDK 7 和JDK 8：JDK 7u40 之后，实现了和 JRockit Flight Recorder 一样的功能，并添加了各项数据配置，用来打开或者关闭一些统计数据功能。而且，在 JDK 8u40 之后，可以在运行时灵活地打开关闭 JFR。
 *  JFR 1.0 版本对应 JDK 9 和 JDK 10： 在这一版本之后，增加了 JFR 事件接口，用户可以生产或者消费某种事件。
 *  **JFR 2.0 版本对应 JDK 11，这一版本就是我们这个系列主要基于的版本**。
 *  JDK 14 推出了 JFR Event Streaming，让用户处理 JFR 事件更加灵活方便。

JFR 起源于 JVM 基于事件的监控（[JEP 167: Event-Based JVM Tracing][JEP 167_ Event-Based JVM Tracing]）,这个 JEP 中定义了一些基本的监控事件，JFR 在此基础上做了很多扩展与补充。同时这个 JEP 中只是简单地将这些监控事件输出到标准输出（stdout），JFR 则是更加完善。

这里我们先来列出一些些关于JFR更新与bug信息的链接：

*  [JEP 328: Flight Recorder（Release in JDK 11）][JEP 328_ Flight Recorder_Release in JDK 11]：
 *  [Jhotspot虚拟机JFR相关bug][Jhotspot_JFR_bug]
 *  [JEP 349: JFR Event Streaming（Release in JDK 14）][JEP 349_ JFR Event Streaming_Release in JDK 14]

## 为什么用 JFR？ ##

因为某些异常很难在开发测试阶段发现，需要在生产环境才会出这些问题。为了能在生产问题发生后，更好的定位生产问题，JDK 提供了这样一个可以长期开启，对应用影响很小的持续监控手段。官方说，目标是开启 JFR 监控（默认配置），对性能的影响在1%之内，对JVM Runtime 和 GC，OS 以及 Java 库进行全方位的监控。

这里放出一个本人开启**默认配置**的 JFR 监控后，性能对比，JFR 是在 19:40 开启的：

![image][]

可以看出，在 19:40 开启 default，之后请求数量回归峰值之前，CPU Load 基本和之前一样，可以视为无影响。

再放出一个本人在同一个微服务另一个实例同一时间开启 profile 配置的 JFR 监控后，性能对比，同样是在 19:40 开启：  
![image][image 1]

profile 的情况下，峰值 CPU Load 相较于 default 的峰值 CPU Load 高了很多。profile 配置官方说大概影响 2% 的性能，但是实际上，这个影响，尤其是频繁发生内存分配的微服务接口应用，影响**绝对不止 2%**，而且profile的确采集的东西要比默认配置的多很多(这个我们后面会详细说，为什么负载会高的原因也会在后面的系列详细分析说)，所以，**线上系统不推荐长期跑profile。**

## 你可以用 JFR 来做什么？ ##

### 1. 低开销的持续监控 JVM 的运行 ###

在配置正确的情况下，JFR 的整体开销是很低的（为啥低会在下一小节详细说明）。JFR 基于事件采集，JFR 提供很多类型的监控事件，**用户可以自由的启用或者关闭某些事件，并定义事件采集的条件，周期等等**，还可以采集这些事件发生的时候的线程堆栈，GC 根节点等等。这些事件包括如下几类（可能类型之间会有交叉）：

1.  **JVM 内存相关事件**  
    a. **元空间监控相关**，包括各种类加载，卸载，代码高速缓存，JIT 采集等等  
    b. **堆内存相关**，包括 TLAB 内存相关，线程内存分配，堆内存占用，大对象采样等等
2.  **GC 相关事件**  
    a. GC 公共类型事件：例如 GC 开始结束与类型等等  
    b. CMS GC 事件  
    c. G1 GC 事件  
    d. ZGC 事件  
    e. Shenandoah GC 事件
3.  **安全点相关监控事件**，例如安全点开始，安全点结束等等
4.  **IO 相关监控事件**，例如文件 IO，网络 IO 等等
5.  **Java 锁与同步相关事件**
6.  **JIT 编译相关事件**，包括 JIT 编译，代码缓存清理等等
7.  **JVM 配置事件**，就是各种 JVM flag 的配置采集，由于有些参数可以动态配置，JFR 会按一定周期采集这些配置记录变化
8.  **Java 线程相关事件**，包括线程开始，结束，阻塞，等待等等。
9.  **JVM 统计数据采集**，包括线程与线程分配内存统计，大对象统计，对象统计，线程 CPU 统计等等等等
10. **JVM 所处运行环境统计**，包括系统 CPU 统计，系统环境变量等等

可以根据自己的需要，针对 JVM 的这些事件进行持续的监控。

### 2. 持续监控 JVM 所处于的系统环境 ###

如上面所述，JFR 对于 JVM 所处运行环境也是有采集统计数据的事件的。

### 3. 定位性能瓶颈，优化性能 ###

对于一些**性能关键事件**，例如 Java 锁相关事件，IO 相关事件，GC 相关事件等等，这些和程序性能息息相关的事件，经过 JFR 的持续采集，为性能瓶颈定位提供了有力的参考。

### 4. 结合 JVM 日志，深入学习 JVM 原理 ###

想不浮于表面看 JVM 的各种概念以及设计原理，而是深入了解 JVM 的原理以及了解这些原理后如何运用于实践， JFR 会是一个不错的学习工具。你可以通过学习 JVM 原理，结合 JFR 事件与一些 JVM 日志，通过测试程序产生这些事件，了解这些事件产生的原因，时机以及影响，来更深入的理解 JVM 原理。**这也是本系列的一个主要目标**

### 5. 根据 JFR 持续采集某些指标动态采集 JFR 某些指标来更好的监控与定位系统问题 ###

JFR 有很多统计数据，这些是你的 JVM 程序可以解析的。在 Java 14 更是引入了 JFR Stream，这样就不用像之前那样想解析必须先 dump 到一个临时文件中进行解析，而是像流一样不断消费。利用这些统计数据，你可以动态的采集一些 JFR 事件。这些事件可能对于性能影响较大，不能线上一直持续采集，但是又是那种遇到线上问题非常需要的事件，这样动态开启的需求就很必要。**通过对于 JFR 一些性能影响小的持续采集事件的消费，可以在出现问题时，动态开启一些 JFR 事件的采集，这样能更好的维持线上稳定以及高效，并能保证事后定位解决问题时有据可依**。

[JFR _ JVM -]: https://zhanghaoxin.blog.csdn.net/article/details/111386635
[JEP 167_ Event-Based JVM Tracing]: http://openjdk.java.net/jeps/167
[JEP 328_ Flight Recorder_Release in JDK 11]: https://openjdk.java.net/jeps/328
[Jhotspot_JFR_bug]: https://bugs.openjdk.java.net/browse/JDK-8240430?jql=project%20in%20%28JDK%29%20AND%20component%20in%20%28hotspot%29%20AND%20Subcomponent%20in%20%28jfr%29
[JEP 349_ JFR Event Streaming_Release in JDK 14]: https://openjdk.java.net/jeps/349
[image]: /images/20221120/861dea76d59041ea8f60af62f67ef109.png
[image 1]: https://img-blog.csdnimg.cn/img_convert/3614a4aa8788bdda5e6a106897b106fc.png