Java中用Flight Recorder監控Hibernate事件

banq發表於2024-06-12

在本教程中,我們將研究使用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
        ## Enable jdbc batch inserts
        jdbc.batch_size: 4
        order_inserts: true
        javax.cache.provider: org.ehcache.jsr107.EhcacheCachingProvider
        ## Enable L2 cache
        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 查詢。

相關文章