深度探索JFR - JFR详细介绍与生产问题定位落地 - 1.

本文基于 OpenJDK 11 并涉及一些之后版本的特性，非 OpenJDK 11 的特性会被特殊标记出来

什么是 JFR？

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

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

如果是利用默认配置启动这个记录，性能非常高效，对于业务影响很小，因为这个框架本来就是用来长期在线上部署的框架。这个记录可以输出成二进制文件，用户可以指定最大记录时间，或者最大记录大小，供用户在需要的时候输出成文件进行事后分析。

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，这一版本就是我们今天要详细讨论说明。

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

• JEP 328: Flight Recorder（Release in JDK 11）： https://openjdk.java.net/jeps/328
• hotspot虚拟机JFR相关bug：https://bugs.openjdk.java.net/browse/JDK-8240430?jql=project%20in%20(JDK)%20AND%20component%20in%20(hotspot)%20AND%20Subcomponent%20in%20(jfr)
• JEP 349: JFR Event Streaming（Release in JDK 14）：https://openjdk.java.net/jeps/349

为什么用 JFR？

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

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

image

可以看出，在19:40开启后基本无影响。

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

image

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

JFR，具有以下关键的特性：

• 低开销（在配置正确的情况下），可在生产环境核心业务进程中始终在线运行。当然，也可以随时开启与关闭。
• 可以查看出问题时间段内进行分析，可以分析 Java 应用程序，JVM 内部以及当前Java进程运行环境等多因素。
• JFR基于事件采集，可以分析非常底层的信息，例如对象分配，方法采样与热点方法定位与调用堆栈，安全点分析与锁占用时长与堆栈分析，GC 相关分析以及 JIT 编译器相关分析（例如 CodeCache ）
• 完善的 API 定义，用户可以自定义事件生产与消费。

JFR 的核心 - 事件 Event 说明

在 JFR中，一切皆为 Event：

• 任意JVM行为都是一个Event，例如类加载也是一个 Event，对应 Class Load Event
• 开启 JFR 记录的原因也是一个Event，对应的就是 Recording Reason Event
• 就算是有 Event 丢失，他也是一个 Event，对应 Data Loss Event

这些 Event 在某些特定的时间点产生，每个事件都有名称，产生时间戳还有 Event 数据体组成。Event 数据体不同的 Event 数据不同，例如 CP U负载，Event 发生之前还有之后的 Java 堆大小， 获取锁的线程 ID 等等。还有一点比较有意思的是，大部分的 Event，都有 Event 是在哪个线程发生的，Event 发生的时候这个线程的调用栈，Event 的持续时间。这就非常有用了，利用这些信息，我们可以回溯 Event 发生当时的情况。

Event 按照采集方式可以分为三种：

1. Instant Event：顾名思义，这种 Event 在发生时就立刻采集。例如：Throw Exception Event 还有 Thread Start Event，类似于这种在某一时刻发生的 Event
2. Duration Event：这种 Event 需要耗费一些时间，在完成的时候会记录。对于这种类型的 Event，可以设置一个时间限制，超过这个时间限制的才会记录。例如 GC Event，Thread Sleep Event。
3. Sample Event（或者是Requestable Event）：按照一定的频率采集，这个频率是可以配置的。例如 Thread Dump Event，Method Sampling Event

由于 JFR 会采集很多很多的数据，为了效率，最好配置自己感兴趣的事件采集，并且对于 Duration Event 设置时间限制，一般我们对于时间短的事件并不关心。

Event 会被写入 .jfr 的二进制文件（二进制文件对于应用来说读写效率最高）中，以 little endian base 128 的形式编码，这里我们用一个 Event 举个例子：

Class Load Event

0000FC10 : 98 80 80 00 87 02 95 ae e4 b2 92 03 a2 f7 ae 9a 94 02 02 01 8d 11 00 00

• 0000FC10: 文件位置
• 98 80 80 00: Event 大小
• 87 02: Event ID
• 95 ae e4 b2 92 03: 时间戳
• a2 f7 ae 9a 94 02: 持续时间
• 02: 线程 ID
• 01: 堆栈 ID
• PayLoad（每种 Event 的 field 不同）：
  • 8d 11: 加载的类
  • 00 : 定义类的 ClassLoader
  • 00 : 初始化类的 ClassLoader

这里仅仅是举个例子，实际使用中，我们肯定不会去这么看每个 Event 的，而是通过可视化工具 JMC 去看，这个我们后面会讲到。至于 Event 有哪些种类，也会在后面的章节涉及到。

那么这些Event是如何产生，如何记录保持高效的呢？

JFR如何实现的低延迟与低性能损耗

首先，Event肯定是多线程产生的，这点显而易见。如果 Event 记录要保证全局有序，那么肯定需要多线程向一个指定队列或者缓存输出，那么不可避免的会涉及到锁争用，这样是很低效的。 Event本身带时间戳，那么可不可以在最后读取的时候进行排序？在一个线程内，生成的 Event 肯定是有序的；那么多线程产生的 Event， 就可以看成一个又一个的有序集合。最后，针对这些有序集合的每个元素进行整体排序，算法上快很多。所以我们没有必要在 Event 产生的时候就进行整体排序。

在 JFR 中，所有的 Event （包括通过JFR API产生的 Event 还有 JVM 产生的 EVENT），会先存储到每个线程自己的 Thread Buffer 中；在这个 Buffer 满了之后，会将 Buffer 的内容刷入 Global Buffer 中；Global Buffer 是一个环形 Buffer，保存着所有线程发送来的 Thread Buffer 中的内容。当这个环形 Buffer 存储到达上限之后，根据配置，会选择丢弃或者刷入文件。

可以看出，不同的 Buffer 之间的数据不会有任何重叠。并且某一块数据，要么就是在内存中，要么就是在磁盘上，不会两个地方都存在，那么这样会带来数据丢失的问题：

• 首先，在断电的时候或者操作系统强制重启的时候，还未写入磁盘的 Event 会丢失。
• 如果只是强制 kill -9掉了Java 进程，那么刷入文件写入高速缓冲的 Event 不会丢失，但是 Global Buffer 中还有 Thread Buffer 中的数据会丢失。同样的，如果JVM崩溃了，这些内存Buffer中的数据也会丢失。正常退出，或者应用异常但是JVM正常退出的，数据不会丢失。
• 采集的数据在可见之前可能会有很小的延迟。例如数据在从 Thread Buffer 刷入 Global Bufeer 的时候， 你如果去 dump JFR 的数据，可能这部分数据会被忽略而导致看不到。
• 最后一点，任何情况下导致在从 Global Buffer 刷入磁盘不够快的时候，这时候要刷入磁盘的数据可能被丢弃。当发生这种情况是，就会记录下数据丢失事件，这个事件包括是那块时间的数据丢掉了。通过 JFR 的日志也能看到这个信息。

image

开启JFR记录

可以通过启动参数配置并且启用 JFR，也可以通过启动参数在 JVM 进程启动的时候就启动 JFR，或者是利用 jcmd 工具，动态启用或者关闭 JFR。

通过 JVM 启动参数启用以及 JVM 参数说明

在 OpenJDK 11 版本之后，启动参数被简化了很多很多；目前JFR涉及的参数仅仅只有两个，一个负责启动（-XX:StartFlightRecording），一个负责配置（-XX:FlightRecorderOptions）。JDK 8中的-XX:+FlightRecorder打开 FlightRecorder 状态位在 OpenJDK 11 中不再需要了，目前仅需一个参数就能启动 JFR。 这里我们举一个例子：

java -XX:StartFlightRecording=disk=true,dumponexit=true,filename=recording.jfr,maxsize=1024m,maxage=1d,settings=profile,path-to-gc-roots=true test.Main

核心就是 -XX:StartFlightRecording，有了这个参数就会启用 JFR 记录。其中的涉及配置有：

配置key	默认值	说明
delay	0	延迟多久后启动 JFR 记录，支持带单位配置， 例如 delay=60s（秒）， delay=20m（分钟）， delay=1h（小时）， delay=1d（天），不带单位就是秒， 0就是没有延迟直接开始记录。一般为了避免框架初始化等影响，我们会延迟 1 分钟开始记录（例如Spring cloud应用，可以看下日志中应用启动耗时，来决定下这个时间）。
disk	true	是否写入磁盘，这个就是上文提到的， global buffer 满了之后，是直接丢弃还是写入磁盘文件。
dumponexit	false	程序退出时，是否要dump出 .jfr文件
duration	0	JFR 记录持续时间，同样支持单位配置，不带单位就是秒，0代表不限制持续时间，一直记录。
filename	启动目录/hotspot-pid-26732-id-1-2020_03_12_10_07_22.jfr，pid 后面就是 pid， id 后面是第几个 JFR 记录，可以启动多个 JFR 记录。最后就是时间。	dump的输出文件
name	无	记录名称，由于可以启动多个 JFR 记录，这个名称用于区分，否则只能看到一个记录 id，不好区分。
maxage	0	这个参数只有在 disk 为 true 的情况下才有效。最大文件记录保存时间，就是 global buffer 满了需要刷入本地临时目录下保存，这些文件最多保留多久的。也可以通过单位配置，没有单位就是秒，默认是0，就是不限制
maxsize	250MB	这个参数只有在 disk 为 true 的情况下才有效。最大文件大小，支持单位配置， 不带单位是字节，m或者M代表MB，g或者G代表GB。设置为0代表不限制大小。虽然官网说默认就是0，但是实际用的时候，不设置会有提示： No limit specified, using maxsize=250MB as default. 注意，这个配置不能小于后面将会提到的 maxchunksize 这个参数。
path-to-gc-roots	false	是否记录GC根节点到活动对象的路径，一般不打开这个，首先这个在我个人定位问题的时候，很难用到，只要你的编程习惯好。还有就是打开这个，性能损耗比较大，会导致FullGC一般是在怀疑有内存泄漏的时候热启动这种采集，并且通过产生对象堆栈无法定位的时候，动态打开即可。一般通过产生这个对象的堆栈就能定位，如果定位不到，怀疑有其他引用，例如 ThreadLocal 没有释放这样的，可以在 dump 的时候采集 gc roots
settings	默认是 default.jfc，这个位于 $JAVA_HOME/lib/jfr/default.jfc	采集 Event 的详细配置，采集的每个 Event 都有自己的详细配置。另一个 JDK 自带的配置是 profile.jfc，位于 $JAVA_HOME/lib/jfr/profile.jfc。这个配置文件里面的配置是怎么回事，我们后面会涉及。

至于前面章节中提到的那些 Buffer 的大小，是在另一个配置参数中配置，一般我们不改这些配置，用默认的就能满足我们的需求了，这里列出下：

-XX:FlightRecorderOptions 相关的参数

配置key	默认值	说明
allow_threadbuffers_to_disk	false	是否允许 在 thread buffer 线程阻塞的时候，直接将 thread buffer 的内容写入文件。默认不启用，一般没必要开启这个参数，只要你设置的参数让 global buffer 大小合理不至于刷盘很慢，就行了。
globalbuffersize	如果不设置，根据设置的 memorysize 自动计算得出	单个 global buffer 的大小，一般通过 memorysize 设置，不建议自己设置
maxchunksize	12M	存入磁盘的每个临时文件的大小。默认为12MB，不能小于1M。可以用单位配置，不带单位是字节，m或者M代表MB，g或者G代表GB。注意这个大小最好不要比 memorySize 小，更不能比 globalbuffersize 小，否则会导致性能下降
memorysize	10M	JFR的 global buffer 占用的整体内存大小，一般通过设置这个参数，numglobalbuffers 还有 globalbuffersize 会被自动计算出。可以用单位配置，不带单位是字节，m或者M代表MB，g或者G代表GB。
numglobalbuffers	如果不设置，根据设置的 memorysize 自动计算得出	global buffer的个数，一般通过 memorysize 设置，不建议自己设置
old-object-queue-size	256	对于Profiling中的 Old Object Sample 事件，记录多少个 Old Object，这个配置并不是越大越好。记录是怎么记录的，会在后面的各种 Event 介绍里面详细介绍。我的建议是，一般应用256就够，时间跨度大的，例如 maxage 保存了一周以上的，可以翻倍
repository	等同于 -Djava.io.tmpdir 指定的目录	JFR 保存到磁盘的临时记录的位置
retransform	true	是否通过 JVMTI 转换 JFR 相关 Event 类，如果设置为 false，则只在 Event 类加载的时候添加相应的 Java Instrumentation，这个一般不用改，这点内存 metaspace 还是足够的
samplethreads	true	这个是是否开启线程采集的状态位配置，只有这个配置为 true，并且在 Event 配置中开启线程相关的采集（这个后面会提到），才会采集这些事件。
stackdepth	64	采集事件堆栈深度，有些 Event 会采集堆栈，这个堆栈采集的深度，统一由这个配置指定。注意这个值不能设置过大，如果你采集的 Event种类很多，堆栈深度大很影响性能。比如你用的是 default.jfc 配置的采集，堆栈深度64基本上就是不影响性能的极限了。你可以自定义采集某些事件，增加堆栈深度。
threadbuffersize	8KB	threadBuffer 大小，最好不要修改这个，如果增大，那么随着你的线程数增多，内存占用会增大。过小的话，刷入 global buffer 的次数就会变多。8KB 就是经验中最合适的。

配置与 JFR 的架构联系:

image

注意这些配置的联系与区别

1.disk=true 与 dumponexit=true， 这两个配置完全不是一回事。disk=true，仅仅代表如果 global buffer 满了，将这个写入文件并不是用户可以看到的，只会写入 repository 配置的目录，默认是临时目录，这个临时目录地址是-Djava.io.tmpdir指定的，默认为：

• linux： /tmp 目录
• windows: C:\Users\你的用户\AppData\Temp

配置了 disk=true 之后，就会在临时目录产生一个文件夹，命名格式是：时间_pid，例如：2020_03_12_08_04_45_10916；里面的文件就是一个又一个的 Data trunk，表现为一个又一个的 .jfr 文件。最新的文件 会跟随一个 .part ：

--/2020_03_12_08_04_45_10916
|----2020_03_12_08_04_45.jfr
|----2020_03_12_08_05_12.jfr
|----2020_03_12_08_05_55.jfr
|----2020_03_12_08_06_08.jfr
|----2020_03_12_08_06_08.part

每个 .jfr 文件的大小， 就是 Data Chunk 的大小，这个大小如何配置，会在后面的 jcmd 启动并配置 JFR 中提到。
dumponexit=true 代表在程序退出的时候，强制dump一次将数据存入 filename 配置的输出文件。只有用户手动 dump， 或者是 dumponexit 触发的 dump， 用户才能正常看到 .jfr 文件。输出这个文件其实很快， 就是将内存中所有 beffer 以及临时文件夹 中的 .jfr文件的内容，输出到用户指定的 .jfr 文件中。一般内存中的 buffer 很小，是MB级别的，这个是可以配置的，注意不要配置很大，否则可能会内存不足，最重要的是可能会使老年代增大导致FullGC。

2.JFR相关的内存占用到底有多大？主要是两部分，一部分是 global buffer，另一部分是 thread local buffer。 global buffer 总大小由上面提到的 memorysize 自动计算得出，总大小就是 memorysize。所以， JFR 相关的占用内存大小为： thread 数量 * thread buffer 大小 + memory size

通过 jcmd 命令启用

jcmd 命令相关的参数与 JVM 参数涉及的配置参数，其实是一样的，我们来看。

1. jcmd <pid> JFR.start。启动 JFR 记录，参数和-XX:StartFlightRecording一模一样，请参考上面的表格。但是注意这里不再是逗号分割，而是空格
   示例：

jcmd 21 JFR.start name=profile_online maxage=1d maxsize=1g

这个就代表启动一个名称为 profile_online, 最多保留一天，最大保留 1G 的本地文件记录

2. jcmd <pid> JFR.stop. 停止 JFR 记录，需要传入名称，例如如果要停止上面打开的，则执行：

jcmd 21 JFR.stop name=profile_online

参数：

参数	默认值	描述
name	无	指定要停止的 JFR 记录名称
copy_to_file	无	停止时同时复制到文件，指定文件输出位置

3. jcmd <pid> JFR.check，查看当前正在执行的 JFR 记录。

示例：

jcmd 21 JFR.check

输出：

21:
Recording 1: name=profile_online maxsize=1.0GB maxage=1d (running)

参数：

参数	默认值	描述
name	无	指定要查看的 JFR 记录名称
verbose	false	是否查看每种 Event 采集详细配置

4. jcmd <pid> JFR.configure，如果不传入参数，则是查看当前配置，传入参数就是修改配置。配置与-XX:FlightRecorderOptions的一模一样。请参考上面的表格
   示例：

./jcmd 21 JFR.configure

输出：

Repository path: /tmp/2020_03_18_08_41_44_21

Stack depth: 64
Global buffer count: 20
Global buffer size: 512.0 kB
Thread buffer size: 8.0 kB
Memory size: 10.0 MB
Max chunk size: 12.0 MB
Sample threads: true

示例：

./jcmd 21 JFR.configure stackdepth=65

输出：

21:
Stack depth: 65

5. jcmd <pid> JFR.dump

参数：

参数	默认值	描述
name	无	指定要查看的 JFR 记录名称
filename	无	指定文件输出位置
maxage	0	dump最多的时间范围的文件，可以通过单位配置，没有单位就是秒，默认是0，就是不限制
maxsize	0	dump最大文件大小，支持单位配置， 不带单位是字节，m或者M代表MB，g或者G代表GB。设置为0代表不限制大小
begin	无	dump开始位置， 可以这么配置：09:00, 21:35:00, 2018-06-03T18:12:56.827Z, 2018-06-03T20:13:46.832, -10m, -3h, or -1d
end :	无	dump结束位置，可以这么配置： 09:00, 21:35:00, 2018-06-03T18:12:56.827Z, 2018-06-03T20:13:46.832, -10m, -3h, or -1d (STRING, no default value)
path-to-gc-roots	false	是否记录GC根节点到活动对象的路径，一般不记录，dump 的时候打开这个肯定会触发一次 fullGC，对线上应用有影响。最好参考之前对于 JFR 启动记录参数的这个参数的描述，考虑是否有必要