JVM 的 JFR 事件追踪：精确记录 I/O、锁竞争、GC 暂停的底层细节
大家好，今天我们来深入探讨 JVM 的 Java Flight Recorder (JFR)，一个强大的性能分析和诊断工具。我们将重点关注如何利用 JFR 精确地记录 I/O 操作、锁竞争以及 GC 暂停等关键底层细节，从而帮助我们更好地理解和优化 Java 应用程序的性能。
1. JFR 简介与工作原理
JFR 是 JVM 内置的性能监控和诊断工具，从 JDK 11 开始成为 OpenJDK 的一部分，无需额外安装。它以低开销的方式持续收集 JVM 运行时的数据，并将其存储在二进制文件中，供事后分析。
JFR 的工作原理可以概括为以下几个步骤：
- 事件生成： JVM 内部以及 Java 应用代码中的关键事件发生时，例如方法调用、对象分配、锁竞争、I/O 操作等，都会生成相应的事件数据。
- 数据缓冲： 这些事件数据会被暂时存储在 JVM 的缓冲区中。
- 周期性 Flush： JFR 会定期（例如每秒）将缓冲区中的数据刷新到磁盘上的
.jfr文件中。 - 事后分析： 我们可以使用 JDK 自带的
JDK Mission Control (JMC)工具或者其他 JFR 分析工具（例如jfr-dump命令行工具）来打开.jfr文件，并对收集到的数据进行分析，找出性能瓶颈。
2. JFR 的启动方式与配置
启动 JFR 有两种主要方式：
- 命令行方式： 在启动 JVM 时，通过
-XX:StartFlightRecording参数来启用 JFR。 - 运行时方式： 使用
jcmd工具在 JVM 运行时动态启动和停止 JFR 录制。
2.1 命令行方式
最简单的启动方式如下：
java -XX:StartFlightRecording=filename=myrecording.jfr MyApp这个命令会启动 JFR，并将录制的数据保存到 myrecording.jfr 文件中。
更详细的配置可以使用以下参数：
java -XX:StartFlightRecording=filename=myrecording.jfr,duration=60s,frequency=1000ms,settings=profile MyAppfilename: 指定录制文件的名称。duration: 指定录制时长，例如60s表示 60 秒。frequency: 指定采样频率，例如1000ms表示每秒采样一次。settings: 指定 JFR 的配置模板，常用的有profile和default。profile模板收集更详细的数据，但开销也更高。default模板开销较低，适合长期监控。
2.2 运行时方式
可以使用 jcmd 命令来动态启动和停止 JFR 录制。首先需要找到 JVM 进程的 ID：
jcmd假设找到的进程 ID 是 1234，可以使用以下命令启动 JFR：
jcmd 1234 JFR.start filename=myrecording.jfr duration=60s停止 JFR 录制：
jcmd 1234 JFR.stop filename=myrecording.jfr还可以使用 JFR.dump 命令将当前录制的数据导出到文件：
jcmd 1234 JFR.dump filename=myrecording.jfr2.3 自定义 JFR 配置
JFR 允许自定义配置文件，以精确控制需要收集哪些事件以及它们的采样频率和阈值。配置文件是 XML 格式，可以指定哪些事件启用或禁用，以及设置事件的阈值。
以下是一个简单的自定义 JFR 配置文件 myconfig.jfr：
<?xml version="1.0" encoding="UTF-8"?>
<configuration version="2.0">
<control>
<event name="jdk.SocketRead">
<setting name="enabled">true</setting>
<setting name="threshold">10 ms</setting>
</event>
<event name="jdk.SocketWrite">
<setting name="enabled">true</setting>
<setting name="threshold">10 ms</setting>
</event>
<event name="jdk.ThreadLockContention">
<setting name="enabled">true</setting>
<setting name="threshold">10 ms</setting>
</event>
<event name="jdk.GarbageCollection">
<setting name="enabled">true</setting>
<setting name="threshold">10 ms</setting>
</event>
</control>
</configuration>这个配置文件启用了 jdk.SocketRead、jdk.SocketWrite、jdk.ThreadLockContention 和 jdk.GarbageCollection 事件，并设置了 10 毫秒的阈值。只有耗时超过 10 毫秒的事件才会被记录。
使用自定义配置文件启动 JFR：
java -XX:StartFlightRecording=filename=myrecording.jfr,settings=myconfig.jfr MyApp3. JFR 事件类型与底层细节
JFR 提供了大量的事件类型，涵盖了 JVM 运行时的各个方面。下面我们重点关注与 I/O、锁竞争和 GC 相关的事件。
3.1 I/O 事件
JFR 提供了多种 I/O 相关的事件，可以帮助我们分析 I/O 性能瓶颈。
| 事件名称 | 描述 |
|---|---|
jdk.SocketRead |
记录 Socket 读取操作的耗时、读取的字节数等信息。 |
jdk.SocketWrite |
记录 Socket 写入操作的耗时、写入的字节数等信息。 |
jdk.FileRead |
记录文件读取操作的耗时、读取的字节数等信息。 |
jdk.FileWrite |
记录文件写入操作的耗时、写入的字节数等信息。 |
jdk.NioMark |
记录 NIO 缓冲区的标记操作。 |
jdk.NioPosition |
记录 NIO 缓冲区的定位操作。 |
jdk.NioRead |
记录 NIO 缓冲区的读取操作。 |
jdk.NioWrite |
记录 NIO 缓冲区的写入操作。 |
通过分析这些事件，我们可以了解应用程序的 I/O 行为，例如：
- 哪些 Socket 连接的读取/写入操作耗时较长？
- 哪些文件的读取/写入操作频率较高？
- NIO 缓冲区的操作是否高效？
代码示例:
假设我们有一个简单的 Socket 服务器，如下所示：
import java.io.*;
import java.net.ServerSocket;
import java.net.Socket;
public class SocketServer {
public static void main(String[] args) throws IOException {
ServerSocket serverSocket = new ServerSocket(8080);
System.out.println("Server started on port 8080");
while (true) {
Socket clientSocket = serverSocket.accept();
System.out.println("Client connected: " + clientSocket.getInetAddress());
new Thread(() -> {
try (BufferedReader reader = new BufferedReader(new InputStreamReader(clientSocket.getInputStream()));
PrintWriter writer = new PrintWriter(clientSocket.getOutputStream(), true)) {
String line;
while ((line = reader.readLine()) != null) {
System.out.println("Received: " + line);
writer.println("Server received: " + line);
}
} catch (IOException e) {
e.printStackTrace();
} finally {
try {
clientSocket.close();
System.out.println("Client disconnected: " + clientSocket.getInetAddress());
} catch (IOException e) {
e.printStackTrace();
}
}
}).start();
}
}
}我们可以使用以下命令启动 JFR 并监控 jdk.SocketRead 和 jdk.SocketWrite 事件：
java -XX:StartFlightRecording=filename=socket.jfr,duration=60s,settings=profile SocketServer然后，使用 JMC 打开 socket.jfr 文件，可以查看 SocketRead 和 SocketWrite 事件的详细信息，包括耗时、读取/写入的字节数等。
3.2 锁竞争事件
锁竞争是多线程程序中常见的性能瓶颈。JFR 提供了以下事件来帮助我们分析锁竞争：
| 事件名称 | 描述 |
|---|---|
jdk.ThreadLockContention |
记录线程在尝试获取锁时发生竞争的事件。 |
jdk.JavaMonitorEnter |
记录线程成功获取 Java Monitor 的事件。 |
jdk.JavaMonitorWait |
记录线程在 Java Monitor 上等待的事件。 |
jdk.ThreadPark |
记录线程被 Park 的事件，通常发生在 java.util.concurrent 包下的同步工具类中，例如 LockSupport.park()。 |
通过分析这些事件，我们可以了解：
- 哪些锁的竞争最激烈？
- 哪些线程在等待锁？
- 线程在 Park 状态的时间有多长？
代码示例:
import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReentrantLock;
public class LockExample {
private static final Lock lock = new ReentrantLock();
private static int counter = 0;
public static void main(String[] args) throws InterruptedException {
for (int i = 0; i < 10; i++) {
new Thread(() -> {
for (int j = 0; j < 100000; j++) {
lock.lock();
try {
counter++;
} finally {
lock.unlock();
}
}
}).start();
}
Thread.sleep(5000);
System.out.println("Counter: " + counter);
}
}我们可以使用以下命令启动 JFR 并监控 jdk.ThreadLockContention 事件：
java -XX:StartFlightRecording=filename=lock.jfr,duration=60s,settings=profile LockExample然后，使用 JMC 打开 lock.jfr 文件，可以查看 ThreadLockContention 事件的详细信息，包括发生竞争的锁对象、竞争的线程等。
3.3 GC 事件
GC 暂停是影响 Java 应用程序性能的重要因素之一。JFR 提供了丰富的 GC 事件，可以帮助我们分析 GC 的行为。
| 事件名称 | 描述 |
|---|---|
jdk.GarbageCollection |
记录 GC 暂停的事件，包括 GC 的类型、耗时、回收的内存大小等信息。 |
jdk.YoungGarbageCollection |
记录 Young GC 的事件。 |
jdk.OldGarbageCollection |
记录 Full GC 的事件。 |
jdk.GCHeapSummary |
记录 GC 堆的概要信息，包括堆的大小、已使用的内存大小等。 |
jdk.GCLockerInitiated |
记录由于 System.gc() 调用而触发 GC 的事件。 |
通过分析这些事件，我们可以了解：
- GC 暂停的频率和时长？
- GC 的类型（Young GC 还是 Full GC）？
- GC 回收了多少内存？
- 是否存在频繁的
System.gc()调用？
代码示例:
以下代码会不断创建对象，触发 GC：
import java.util.ArrayList;
import java.util.List;
public class GcExample {
public static void main(String[] args) throws InterruptedException {
List<Object> list = new ArrayList<>();
while (true) {
for (int i = 0; i < 1000; i++) {
list.add(new Object());
}
Thread.sleep(1);
}
}
}我们可以使用以下命令启动 JFR 并监控 jdk.GarbageCollection 事件：
java -XX:StartFlightRecording=filename=gc.jfr,duration=60s,settings=profile GcExample然后，使用 JMC 打开 gc.jfr 文件，可以查看 GarbageCollection 事件的详细信息，包括 GC 的类型、耗时、回收的内存大小等。
4. 使用 JMC 进行 JFR 数据分析
JDK Mission Control (JMC) 是 Oracle 提供的免费的 JFR 分析工具。它可以打开 .jfr 文件，并以图形化的方式展示 JFR 数据。
JMC 提供了多种视图来分析 JFR 数据，包括：
- Overview: 展示 JFR 录制的总体情况，例如 CPU 使用率、内存使用率、GC 情况等。
- Memory: 展示内存分配、GC、堆使用情况等信息。
- Threads: 展示线程活动、锁竞争、阻塞等信息。
- I/O: 展示 I/O 操作的耗时、读取/写入的字节数等信息。
- Method Profiling: 展示方法的调用栈、耗时等信息。
通过 JMC 的各种视图，我们可以深入分析 JFR 数据，找出性能瓶颈。
5. 案例分析：优化 I/O 密集型应用
假设我们有一个 I/O 密集型的应用程序，需要读取大量的文件。我们发现应用程序的性能很差，需要进行优化。
首先，我们使用 JFR 录制一段时间的数据，并使用 JMC 打开 .jfr 文件。
在 JMC 的 I/O 视图中，我们发现 jdk.FileRead 事件的耗时很长，而且读取的文件数量很多。这表明 I/O 操作是性能瓶颈。
进一步分析，我们发现读取文件的方式是每次读取一个字节。这种方式效率很低。
我们可以将读取文件的方式改为使用缓冲区，一次读取多个字节。
修改后的代码如下：
import java.io.*;
public class FileReadExample {
public static void main(String[] args) throws IOException {
try (BufferedInputStream bis = new BufferedInputStream(new FileInputStream("large_file.txt"))) {
byte[] buffer = new byte[8192];
int bytesRead;
while ((bytesRead = bis.read(buffer)) != -1) {
// Process the data
}
}
}
}修改代码后，再次使用 JFR 录制数据，并使用 JMC 分析。我们发现 jdk.FileRead 事件的耗时大大降低，应用程序的性能也得到了显著提升。
6. 总结
JFR 是一个强大的性能分析和诊断工具，可以帮助我们深入了解 JVM 运行时的行为，找出性能瓶颈。通过 JFR 提供的 I/O 事件、锁竞争事件和 GC 事件，我们可以精确地记录 I/O 操作、锁竞争和 GC 暂停等底层细节，从而更好地优化 Java 应用程序的性能。
利用 JMC 等工具分析 JFR 文件，能够直观地了解程序运行时的各种指标。
7. 展望
JFR 作为一个不断发展的工具，未来将会提供更多的事件类型和更强大的分析功能，帮助我们更好地理解和优化 Java 应用程序的性能。不断学习和掌握 JFR 的使用，将有助于我们成为更优秀的 Java 开发者。