こんにちは、平田です。

QuarkusでHibernateの統計情報を出力できるようなので、試してみました。

JPAを使う場合、気をつけないといつの間にかN+1 SELECTの罠を踏み抜くことがあります。そこで、発行されているSQLをログ出力して、意図しないSQLが発行されていないか確認するのが一般的かと思いますが、Hibernateには統計情報なるものがあるようで、これでも発行回数や処理時間を確認できるようです。

この統計情報をQuarkusアプリで出力してみます。Quarkusのサンプル集から、hibernate-orm-quickstartを使用します。

quarkus-quickstartsリポジトリをgit cloneして、hibernate-orm-quickstartのREADMEを元にPostgreSQLを起動します。

docker run --ulimit memlock=-1:-1 -it --rm=true --memory-swappiness=0 --name quarkus_test \
 -e POSTGRES_USER=quarkus_test \
 -e POSTGRES_PASSWORD=quarkus_test \
 -e POSTGRES_DB=quarkus_test \
 -p 5432:5432 postgres:10.5

次に、src/main/resources/application.properties に以下の設定を追加します。

quarkus.hibernate-orm.statistics=true

この状態で mvn quarkus:dev で起動し、更新のAPIをキックします。

curl -s -H 'Content-Type: application/json' \
  -X PUT localhost:8080/fruits/3 \
  -d '{"name": "Banana2"}'

更新処理では、idで更新対象のエンティティをSELECTしてから更新するため、都合2回のSQLが実行されるはずです。統計情報はログに出力されます。

2021-01-04 15:41:43,732 INFO  [org.hib.eng.int.StatisticalLoggingSessionEventListener] (executor-thread-1) Session Metrics {
    15371006 nanoseconds spent acquiring 2 JDBC connections;
    24062 nanoseconds spent releasing 2 JDBC connections;
    20085980 nanoseconds spent preparing 2 JDBC statements;
    12173381 nanoseconds spent executing 2 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    3607178 nanoseconds spent performing 3 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    830126 nanoseconds spent performing 1 L2C misses;
    11098762 nanoseconds spent executing 2 flushes (flushing a total of 2 entities and 0 collections);
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}

12173381 nanoseconds spent executing 2 JDBC statements; と出ている行が、SQLの実行回数（と処理時間）になります。他にもコネクションの使用数やキャッシュの統計が出力されています（コネクションを2件使っているのは謎…）。

HibernateのSession (≒EntityManager)をクローズしたときに統計情報を出力しているようです（SessionEventListener#endで出力）。