Java中用Flight Recorder监控Hibernate事件

banq
在本教程中，我们将研究使用Java Flight Recorder记录Hibernate生命周期执行期间事件的过程。之后，我们将使用Oracle 的JDK Mission Control工具检查记录的事件并深入了解 Hibernate 的内部执行。

Java Flight Recorder 和 JDK Mission Control 简介
Java Flight Recorder (JFR) 是 Oracle、OpenJDK 和 Oracle JDK 的 Hotspot 虚拟机提供的低级代理。它对于监控 Java 应用程序非常有用。

Java Flight Recorder 代理在应用程序执行期间记录 Java 虚拟机和受支持的框架（如 Hibernate）生成的事件。JFR 将生成的事件记录到文件中，可以使用 Oracle 的 JDK Mission Control 工具对其进行分析和可视化。

配置应用程序以发出 Hibernate-JFR 事件
Hibernate ORM 不会立即发出任何 Java Flight Recorder 事件。为了能够从 Hibernate 生成事件，我们必须在pom.xml文件中添加hibernate-jfr依赖项：

<dependency>
    <groupId>org.hibernate.orm</groupId>
    <artifactId>hibernate-jfr</artifactId>
    <version>6.4.4.Final</version>
</dependency>

值得注意的是，hibernate-jfr jar 仅从 Hibernate 6.4 开始可用。

1. 配置示例 Spring Boot 应用程序
现在让我们创建一个示例 Spring Boot 应用程序，使用spring-data-jpa和ehcache作为 Hibernate L2 缓存来演示 Hibernate JFR 事件。我们在本例中使用的 Spring Boot 版本是 3.1.5。

示例应用程序使用 H2 数据库。我们可以使用下面的 Spring 配置来为此类用例配置 Hibernate：

spring:
  h2:
    console.enabled: true
  datasource:
    url: jdbc:h2:mem:hibernatejfr
    username: sa
    password: password
    driverClassName: org.h2.Driver
  jpa:
    database-platform: org.hibernate.dialect.H2Dialect
    defer-datasource-initialization: true
    show-sql: true # Print SQL statements
    properties:
      hibernate:
        format_sql: true
        generate_statistics: true
        <strong>Enable jdbc batch inserts</strong>
        jdbc.batch_size: 4
        order_inserts: true
        javax.cache.provider: org.ehcache.jsr107.EhcacheCachingProvider
        <strong>Enable L2 cache</strong>
        cache:
          region.factory_class: org.hibernate.cache.jcache.JCacheRegionFactory
          use_second_level_cache: true
          use_query_cache: true
      jakarta.persistence.sharedCache.mode: ENABLE_SELECTIVE

我们将使用 Spring JPA 和 Hibernate 6 作为 ORM 层创建一个简单的 Spring Boot 应用程序来演示 JFR 事件。为简洁起见，我们仅提供演示应用程序的类图：
 

配置好应用程序后，让我们通过在启动应用程序时传递-XX:StartFlightRecording 作为 VM 参数来以飞行记录模式启动应用程序：

java -XX:StartFlightRecording=filename=myrecordingL2Cache.jfr -jar hibernatejfr-0.0.1-SNAPSHOT.jar

如果我们使用IntelliJ Idea 启动应用程序，我们可以通过 IDE运行/调试配置添加-XX:StartFlightRecording VM 参数：

在 Intellij Idea 中添加 VM 参数
现在应用程序已准备好运行。首先，我们将启动演示应用程序并使用cURL或PostMan访问几个 REST 端点。然后，我们将停止应用程序并验证录音是否保存在指定的文件中。

或者，如果我们想在运行单元测试用例时捕获事件，可以使用maven-surefire-plugin应用 VM 参数以在测试用例执行期间启动飞行记录。

2. 配置日志
我们可以启用 Hibernate 配置属性hibernate.generate_statistics来生成日志，打印 L2C 缓存命中和 JDBC 连接等操作的统计信息。我们可以使用这些日志来验证 L2 缓存是否设置正确。

启用记录后，Flight Recorder 会在应用程序启动时打印日志。因此，我们应该留意确认 JFR 记录正在运行的日志行：

[0.444s][info][jfr,startup] Started recording 1. No limit specified, using maxsize=250MB as default.
[0.444s][info][jfr,startup] 
[0.444s][info][jfr,startup] Use jcmd 27465 JFR.dump name=1 to copy recording data to file.

Hibernate JFR 事件的类型
hibernate-jfr jar定义了 Hibernate 在飞行记录期间产生的事件，它遵循 SPI 机制将自身插入到 Hibernate 生命周期中。Java中的服务提供者接口(SPI) 架构提供了一种很好的方式来促进可扩展性、松散耦合、模块化和插件架构。

hibernate -core jar 声明了服务提供程序接口 (SPI) org.hibernate.event.spi.EventManager，JFR jar 实现了该接口。因此，当 Hibernate 检测到类路径中存在hibernate-jfr jar 时，Hibernate 会注册它并在执行期间发出 JFR 事件。

hibernate-jfr jar中定义了以下事件：

  • 缓存获取事件
  • CachePut事件
  • 脏计算事件
  • 刷新事件
  • JdbcBatchExecution事件
  • JdbcConnectionAcquisitionEvent事件
  • JdbcPreparedStatementCreation事件
  • JdbcPreparedStatementExecution事件
  • 部分刷新事件
  • 会话关闭事件
  • 会话打开事件
我们可以看到，这些事件的名称是不言自明的。但是，某些事件（例如CacheGetEvent和CachePutEvent ）仅在配置了2 级缓存时才会发布。同样，JdbcBatchExecutionEvent是在以批处理模式执行 JDBC 查询时发布的。

此外，上述每个 Hibernate JFR 事件都具有属性来描述所发出事件的详细信息。例如，SessionOpenEvent具有以下属性：

会话打开事件中的属性
Hibernate 针对不同类型的事件收集不同的属性。一些对分析至关重要的重要属性是开始时间、持续时间、结束时间和事件线程。会话标识符是另一个重要属性，但 Hibernate 不会针对所有事件类型收集它。

使用 JDK Mission Control 分析 JFR 事件
现在我们已经准备好分析 JFR 文件，让我们深入研究 JDK Mission Control 来分析 JFR 文件。

1. 在 Java Mission Control 中查找 Hibernate ORM 事件
让我们启动 Java Mission Control 并通过导航到文件>打开文件菜单项来打开 JFR 文件。

加载文件后，我们会看到一个包含自动分析结果的登录页面。此页面提供了应用程序行为的窗口，并允许快速查看。但是，要查看 Hibernate 引发的事件，我们导航到“大纲”窗格中的“事件浏览器” ，并在事件类型树部分下查找“ Hibernate ORM”


2. 在 JDK Mission Control 中对相关的 Hibernate ORM 事件进行分组
现在，让我们右键单击“事件类型树”下的Hibernate ORM标题，然后单击“根据所选事件类型创建新页面”上下文菜单。此操作将在大纲侧栏上创建一个名为“已过滤事件”的新页面，其中显示所有 Hibernate 事件。我们可以根据需要重命名“已过滤事件”页面。

现在，我们可以打开新的“过滤事件”页面，右键单击表上的任意行，然后选择“分组依据”>“事件线程”。此操作根据“事件线程”属性对表中的所有事件进行分组。按事件线程分组是在命令式编程范式中聚合相关事件的一种非常有效的方法。

在反应式或多线程范例中，我们在按事件线程分组之前应该小心，因为这可能会产生不一致的结果，因为不同的线程可能已经计算了相关的应用程序逻辑。

3. JDK Mission Control 中 Hibernate ORM 事件的基本分析
按事件线程对事件进行分组会在表格上方显示一个新部分，展示分组的事件。接下来，我们通过右键单击标题并选择“可见列”>“总持续时间”向此表添加另一列。“总持续时间”列有助于识别执行时间较长的线程.

Hibernate事件基本分析
现在，选择“总持续时间”最长的事件线程会显示所有导致该时间的事件。如果我们按“开始时间”对事件列表进行排序，我们可以直观地看到 Hibernate 中的事件顺序。

在上面的案例中，我们可以看到，在所有捕获的事件中，JDBC 语句的执行和创建占了“Total Duration总持续时间”的大部分，其次是“Cache Put Events缓存放置事件”。我们还可以看到执行的 JDBC 查询。