🔍

JPAで実行されるSQLクエリを正しく把握する

mkamei

2025/11/05に公開

はじめに

Spring BootでJPA(Hibernate)を使っていると、意図しないDBアクセスを引き起こすことがあります。
こうした問題を早期発見するには、SQLのクエリや統計情報をログ出力する手法が有効です。
本記事では、よく使われるデバッグ情報をピックアップして、1つずつ意味を確認していきます。

バージョン

Spring Boot: 3.5.7
spring-boot-starter-data-jpa: 3.5.7
hibernate: 6.6.33
OpenJDK: 21.0.9
PostgreSQL: 17.6

検証用コード

今回検証として使うUserエンティティとapplication.propertiesです。
バルクインサートを実現するため、以下のポイントで設定しています：

ID生成：GenerationType.SEQUENCE(IDENTITYだとバッチ処理は無効化されます)
Hibernateのバッチ処理：batch_size=8で8件ずつにまとめる
JDBCドライバの最適化：reWriteBatchedInserts=trueで1つのINSERT文に書き換え

User.java

@Getter
@Setter
@Entity
@Table(name = "users")
public class User {
    @Id
    @GeneratedValue(strategy = GenerationType.SEQUENCE, generator = "users_id_seq")
    @SequenceGenerator(name = "users_id_seq", sequenceName = "users_id_seq", allocationSize = 8)
    @Column(name = "id")
    private Long id;

    @Column(name = "name")
    private String name;
}

application.properties

# PostgreSQLデータベース設定
spring.datasource.url=jdbc:postgresql://localhost:5432/demo?reWriteBatchedInserts=true
spring.datasource.username=postgres
spring.datasource.password=
spring.datasource.driver-class-name=org.postgresql.Driver
# JPA/Hibernate設定
spring.jpa.database-platform=org.hibernate.dialect.PostgreSQLDialect
spring.jpa.hibernate.ddl-auto=update
spring.jpa.properties.hibernate.jdbc.batch_size=8

今回実行するテストコードです。
このUserエンティティを10件作成してDB保存する処理のデバッグ情報を確認していきます。
(バッチサイズが8なので、SQLクエリの回数は、シーケンスからのID取得2回 + バルクインサート2回 = 計4回になります)

@Transactional
@Test
void saveAllTest() {
    List<User> users = new ArrayList<>();
    for (int i = 1; i <= 10; i++) {
        User user = new User();
        user.setName("test" + i);
        users.add(user);
    }
    userRepository.saveAll(users);
    entityManager.flush();
}

PostgreSQLでのSQLクエリの確認

まず、意図したSQLクエリが実行されていることを確認するため、PostgreSQL側で直接SQLのクエリログを確認します。
以下のログ設定をpostgresql.confに追加します。

postgresql.conf

logging_collector = on
log_directory = 'log'
log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log'
log_statement = 'all'
log_duration = on
log_min_duration_statement = 0

テストコードを実行してみると、シーケンスからのID取得が2回、バルクインサートが2回で、計4回のSQLログがあります。
意図した通りで、問題ありません。

postgresql-2025-11-03_151950.log

2025-11-03 15:34:13.533 JST [23753] LOG:  statement: BEGIN
2025-11-03 15:34:13.533 JST [23753] LOG:  duration: 0.113 ms
2025-11-03 15:34:13.533 JST [23753] LOG:  duration: 0.210 ms  parse <unnamed>: select nextval('users_id_seq')
2025-11-03 15:34:13.533 JST [23753] LOG:  duration: 0.115 ms  bind <unnamed>: select nextval('users_id_seq')
2025-11-03 15:34:13.533 JST [23753] LOG:  execute <unnamed>: select nextval('users_id_seq')
2025-11-03 15:34:13.533 JST [23753] LOG:  duration: 0.247 ms
2025-11-03 15:34:13.542 JST [23753] LOG:  duration: 0.073 ms  parse <unnamed>: select nextval('users_id_seq')
2025-11-03 15:34:13.542 JST [23753] LOG:  duration: 0.051 ms  bind <unnamed>: select nextval('users_id_seq')
2025-11-03 15:34:13.542 JST [23753] LOG:  execute <unnamed>: select nextval('users_id_seq')
2025-11-03 15:34:13.542 JST [23753] LOG:  duration: 0.029 ms
2025-11-03 15:34:13.551 JST [23753] LOG:  duration: 0.227 ms  parse S_1: insert into users (name,id) values ($1,$2),($3,$4),($5,$6),($7,$8),($9,$10),($11,$12),($13,$14),($15,$16)
2025-11-03 15:34:13.551 JST [23753] LOG:  duration: 0.092 ms  bind S_1: insert into users (name,id) values ($1,$2),($3,$4),($5,$6),($7,$8),($9,$10),($11,$12),($13,$14),($15,$16)
2025-11-03 15:34:13.551 JST [23753] DETAIL:  Parameters: $1 = 'test1', $2 = '34', $3 = 'test2', $4 = '35', $5 = 'test3', $6 = '36', $7 = 'test4', $8 = '37', $9 = 'test5', $10 = '38', $11 = 'test6', $12 = '39', $13 = 'test7', $14 = '40', $15 = 'test8', $16 = '41'
2025-11-03 15:34:13.551 JST [23753] LOG:  execute S_1: insert into users (name,id) values ($1,$2),($3,$4),($5,$6),($7,$8),($9,$10),($11,$12),($13,$14),($15,$16)
2025-11-03 15:34:13.551 JST [23753] DETAIL:  Parameters: $1 = 'test1', $2 = '34', $3 = 'test2', $4 = '35', $5 = 'test3', $6 = '36', $7 = 'test4', $8 = '37', $9 = 'test5', $10 = '38', $11 = 'test6', $12 = '39', $13 = 'test7', $14 = '40', $15 = 'test8', $16 = '41'
2025-11-03 15:34:13.551 JST [23753] LOG:  duration: 0.478 ms
2025-11-03 15:34:13.552 JST [23753] LOG:  duration: 0.061 ms  parse S_2: insert into users (name,id) values ($1,$2),($3,$4)
2025-11-03 15:34:13.552 JST [23753] LOG:  duration: 0.055 ms  bind S_2: insert into users (name,id) values ($1,$2),($3,$4)
2025-11-03 15:34:13.552 JST [23753] DETAIL:  Parameters: $1 = 'test9', $2 = '42', $3 = 'test10', $4 = '43'
2025-11-03 15:34:13.552 JST [23753] LOG:  execute S_2: insert into users (name,id) values ($1,$2),($3,$4)
2025-11-03 15:34:13.552 JST [23753] DETAIL:  Parameters: $1 = 'test9', $2 = '42', $3 = 'test10', $4 = '43'
2025-11-03 15:34:13.552 JST [23753] LOG:  duration: 0.058 ms
2025-11-03 15:34:13.555 JST [23753] LOG:  duration: 0.032 ms  parse S_3: ROLLBACK
2025-11-03 15:34:13.555 JST [23753] LOG:  duration: 0.009 ms  bind S_3: ROLLBACK
2025-11-03 15:34:13.555 JST [23753] LOG:  execute S_3: ROLLBACK

アプリケーションでのデバッグ情報

ここからが本題です。PostgreSQLで確認した実際のクエリを踏まえて、アプリケーション側で設定できるデバッグ情報を確認し、それぞれが出力するSQLクエリや統計情報を見ていきます。

spring.jpa.show-sql=true

まず、JPAのshow-sqlです。
application.propertiesに以下を追記します。

spring.jpa.show-sql=true

テストコードを実行すると、以下のログが出力されました。

app.log

Hibernate: select nextval('users_id_seq')
Hibernate: select nextval('users_id_seq')
Hibernate: insert into users (name,id) values (?,?)
Hibernate: insert into users (name,id) values (?,?)
Hibernate: insert into users (name,id) values (?,?)
Hibernate: insert into users (name,id) values (?,?)
Hibernate: insert into users (name,id) values (?,?)
Hibernate: insert into users (name,id) values (?,?)
Hibernate: insert into users (name,id) values (?,?)
Hibernate: insert into users (name,id) values (?,?)
Hibernate: insert into users (name,id) values (?,?)
Hibernate: insert into users (name,id) values (?,?)

実際に実行されるバルクインサートのクエリではなく、個別のINSERTクエリになっています。
これは、Hibernateの生成するINSERT文が、あくまで途中段階のSQL文であるためです。
生成されたINSERT文は、batch_sizeごとにバッチとしてまとめられ、その後、JDBCドライバーがreWriteBatchedInserts=trueにより、各バッチを1つのINSERT文に書き換えます。
つまり、このHibernateのログのクエリが、そのままDBで実行されているとは限らないことに注意が必要です。

spring.jpa.properties.hibernate.generate_statistics=true

次に、Hibernateの統計情報を出力してみます。
application.propertiesに以下を追記します。

spring.jpa.properties.hibernate.generate_statistics=true

そして、テストコードの前後に以下のコードを追加します。

SessionFactory sessionFactory = entityManagerFactory.unwrap(SessionFactory.class);
Statistics stats = sessionFactory.getStatistics();
stats.clear();
~ テストコード ~
System.out.println("===== Statistics =====");
System.out.println("Entity insert count: " + stats.getEntityInsertCount());
System.out.println("Prepared statements: " + stats.getPrepareStatementCount());
System.out.println("Query execution count: " + stats.getQueryExecutionCount());
System.out.println("===================================");

実行すると以下のような結果が得られました。

app.log

===== Statistics =====
Entity insert count: 10
Prepared statements: 3
Query execution count: 0
===================================
2025-11-03T21:15:53.001+09:00  INFO 32652 --- [demo] [           main] i.StatisticalLoggingSessionEventListener : Session Metrics {
    16792 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    627416 nanoseconds spent preparing 3 JDBC statements;
    1237584 nanoseconds spent executing 2 JDBC statements;
    1672708 nanoseconds spent executing 2 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    7513208 nanoseconds spent executing 1 flushes (flushing a total of 10 entities and 0 collections);
    0 nanoseconds spent executing 0 pre-partial-flushes;
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}

重要なポイントをピックアップします。

Prepared statements: 3, 627416 nanoseconds spent preparing 3 JDBC statements;
これは、事前準備されたSQL文の数で、シーケンスからのID取得で2個、バルクインサートはバッチ処理のため再利用され1個、計3個とカウントされています。
つまり、このカウント値は実際に実行されるクエリの回数とは一致しないので注意が必要です。
1237584 nanoseconds spent executing 2 JDBC statements;
これは、単一クエリ（非バッチ）の実行回数で、シーケンスからのID取得の2回分がカウントされています。
1672708 nanoseconds spent executing 2 JDBC batches;
これは、バッチ処理が実行された回数で、今回はバルクインサートで2回のバッチ実行が行われています。
ただし、バッチ処理の回数 = SQLクエリの回数ではない ので注意が必要です。
今回はreWriteBatchedInserts=trueなので、1バッチ = 1クエリですが、reWriteBatchedInserts=falseの場合は、個別のINSERT文がbatch_size個集まって1つのバッチとなります。
つまり、あくまでバッチ処理された塊の個数であって、実行されたSQLクエリの数ではありません。

logging.level.org.postgresql.core.v3.QueryExecutorImpl=TRACE

最後に、PostgreSQLに実際にSQLクエリを送信するQueryExecutorImplのログレベルをTRACEにしてみます。
application.propertiesに以下を追記します。

logging.level.org.postgresql.core.v3.QueryExecutorImpl=TRACE

テストコードを実行してみると、以下のログが出力されました。

app.log

2025-11-03T18:05:26.711+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :   simple execute, handler=org.postgresql.jdbc.PgStatement$StatementResultHandler@3e5ed0d4, maxRows=0, fetchSize=0, flags=1
2025-11-03T18:05:26.711+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> SimpleQuery(query="BEGIN")
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Parse(stmt=null,query="select nextval('users_id_seq')",oids={})
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Bind(stmt=null,portal=null)
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Describe(portal=null)
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Execute(portal=null,limit=0)
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Sync
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE CommandStatus(BEGIN)
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ReadyForQuery(T)
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ParseComplete [null]
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE BindComplete [unnamed]
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE RowDescription(1)
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :         Field(nextval,INT8,8,T)
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE DataRow(len=1)
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE CommandStatus(SELECT 1)
2025-11-03T18:05:26.712+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ReadyForQuery(T)
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :   simple execute, handler=org.postgresql.jdbc.PgStatement$StatementResultHandler@5ca006ac, maxRows=0, fetchSize=0, flags=1
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Parse(stmt=null,query="select nextval('users_id_seq')",oids={})
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Bind(stmt=null,portal=null)
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Describe(portal=null)
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Execute(portal=null,limit=0)
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Sync
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ParseComplete [null]
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE BindComplete [unnamed]
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE RowDescription(1)
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :         Field(nextval,INT8,8,T)
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE DataRow(len=1)
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE CommandStatus(SELECT 1)
2025-11-03T18:05:26.717+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ReadyForQuery(T)
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :   simple execute, handler=org.postgresql.jdbc.PgStatement$StatementResultHandler@34a99d8, maxRows=0, fetchSize=0, flags=1
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Parse(stmt=null,query="select nextval('users_id_seq')",oids={})
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Bind(stmt=null,portal=null)
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Describe(portal=null)
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Execute(portal=null,limit=0)
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Sync
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ParseComplete [null]
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE BindComplete [unnamed]
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE RowDescription(1)
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :         Field(nextval,INT8,8,T)
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE DataRow(len=2)
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE CommandStatus(SELECT 1)
2025-11-03T18:05:26.718+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ReadyForQuery(T)
2025-11-03T18:05:26.725+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :   batch execute 1 queries, handler=org.postgresql.jdbc.BatchResultHandler@54f62ac6, maxRows=0, fetchSize=0, flags=516
2025-11-03T18:05:26.725+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Parse(stmt=S_1,query="insert into users (name,id) values ($1,$2),($3,$4),($5,$6),($7,$8),($9,$10),($11,$12),($13,$14),($15,$16)",oids={1043,20,1043,20,1043,20,1043,20,1043,20,1043,20,1043,20,1043,20})
2025-11-03T18:05:26.725+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Bind(stmt=S_1,portal=null,$1=<('test1')>,type=VARCHAR,$2=<('1'::int8)>,type=INT8,$3=<('test2')>,type=VARCHAR,$4=<('2'::int8)>,type=INT8,$5=<('test3')>,type=VARCHAR,$6=<('3'::int8)>,type=INT8,$7=<('test4')>,type=VARCHAR,$8=<('4'::int8)>,type=INT8,$9=<('test5')>,type=VARCHAR,$10=<('5'::int8)>,type=INT8,$11=<('test6')>,type=VARCHAR,$12=<('6'::int8)>,type=INT8,$13=<('test7')>,type=VARCHAR,$14=<('7'::int8)>,type=INT8,$15=<('test8')>,type=VARCHAR,$16=<('8'::int8)>,type=INT8)
2025-11-03T18:05:26.725+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Describe(portal=null)
2025-11-03T18:05:26.725+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Execute(portal=null,limit=1)
2025-11-03T18:05:26.725+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Sync
2025-11-03T18:05:26.726+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ParseComplete [S_1]
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE BindComplete [unnamed]
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE NoData
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE CommandStatus(INSERT 0 8)
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ReadyForQuery(T)
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :   batch execute 1 queries, handler=org.postgresql.jdbc.BatchResultHandler@5fe4848, maxRows=0, fetchSize=0, flags=516
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Parse(stmt=S_2,query="insert into users (name,id) values ($1,$2),($3,$4)",oids={1043,20,1043,20})
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Bind(stmt=S_2,portal=null,$1=<('test9')>,type=VARCHAR,$2=<('9'::int8)>,type=INT8,$3=<('test10')>,type=VARCHAR,$4=<('10'::int8)>,type=INT8)
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Describe(portal=null)
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Execute(portal=null,limit=1)
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Sync
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ParseComplete [S_2]
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE BindComplete [unnamed]
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE NoData
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE CommandStatus(INSERT 0 2)
2025-11-03T18:05:26.727+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ReadyForQuery(T)
2025-11-03T18:05:26.730+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :   simple execute, handler=org.postgresql.jdbc.PgConnection$TransactionCommandHandler@c8ed958, maxRows=0, fetchSize=0, flags=22
2025-11-03T18:05:26.730+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Parse(stmt=S_3,query="ROLLBACK",oids={})
2025-11-03T18:05:26.730+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Bind(stmt=S_3,portal=null)
2025-11-03T18:05:26.730+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Execute(portal=null,limit=1)
2025-11-03T18:05:26.730+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  FE=> Sync
2025-11-03T18:05:26.730+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ParseComplete [S_3]
2025-11-03T18:05:26.730+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE BindComplete [unnamed]
2025-11-03T18:05:26.730+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE CommandStatus(ROLLBACK)
2025-11-03T18:05:26.730+09:00 TRACE 78491 --- [demo] [           main] o.postgresql.core.v3.QueryExecutorImpl   :  <=BE ReadyForQuery(I)

ログを見ると、実際にDBに投げられているSQLクエリの式や、INSERTされる値まで細かく確認できます。
少し見づらいですが、実行される完全なSQLクエリの内容が知りたければ、これを使うとよさそうです。

まとめ

今回は、JPA(Hibernate)でのSQLクエリや統計情報のログ出力をまとめてみました。
JPAは自動でやってくれることが多い分、実際に実行されるSQLクエリの把握が難しいです。
そういう時は今回紹介したようなデバッグ情報を有効にすることで、パフォーマンスの問題を早期に発見し、適切な対処が可能になります。

ただし、SQLクエリの回数がボトルネックになるほど大量のデータを扱う場合は、SQLを直接制御できるMyBatisなどを検討してみてください。

この記事が少しでも参考になれば幸いです。質問やフィードバックがあれば、コメントでお気軽にお聞かせください。

参考文献

Virtual Craft Tech Blog

株式会社バーチャルクラフトのテックブログです。バーチャルクラフトは、クラウドサービスのプラットフォーム基盤におけるインフラエンジニアリングの技術集団です。従来のインフラエンジニアの枠を超え、OPS分野のエキスパートを目指して日々技術研鑽に取り組んでいます。

はじめに

バージョン

検証用コード

PostgreSQLでのSQLクエリの確認

アプリケーションでのデバッグ情報

spring.jpa.show-sql=true

spring.jpa.properties.hibernate.generate_statistics=true

logging.level.org.postgresql.core.v3.QueryExecutorImpl=TRACE

まとめ

参考文献

Discussion