(第4回) Spring Bootで実行されるSQLのログ出力の設定【H2, Spring Boot2】

動作環境と今回の目的

前回は、Spring Bootアプリの起動中に使える、H2のブラウザ管理ツール"H2 Console"の使い方について説明しました。
(第3回) H2のブラウザ管理ツール"H2 Console"の使い方【Spring Boot2】

H2 Consoleでは、実際にSQLを実行してH2データベースのデータが見れたり、データの編集や新規作成ができました。
今回は、Spring Bootアプリの起動時や起動中に実行されるSQLの実行ログを出力するように設定をします。

・動作環境やバージョン情報です。
OS：macOS Big Sur（バージョン11.7.1）
開発環境：Eclipse（Pleiades All in One、4.16(2020-06)、Java Full Edition版）
Spring Boot：バージョン2.7.6
Java：11
データベース：H2

SQLログの出力設定、application.properties

データベースを使用するウェブアプリやREST API(Web API)を開発する場合、実行されるDBのSQLログはプログラマなどの開発者にとって必須です。
という事で、Spring Bootアプリの起動中に実行されるSQLのログをEclipseのコンソールビューに出力されるようにします。

application.propertiesファイルに、spring.jpa.show-sqlプロパティの設定を１行追加します。

spring.jpa.show-sql=true

これでSQLのロギングを有効になり、Spring Data JPAによって実行されたSQLがコンソールビューに出力されます。

実際にSpring Bootアプリを起動した時のコンソールビューの一部を抜粋して表示します。

〜
2022-11-25 21:52:22.398  INFO 27715 --- [  restartedMain] org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.H2Dialect
Hibernate: drop table if exists diary CASCADE 
Hibernate: create table diary (id integer generated by default as identity, comment varchar(255), create_datetime timestamp not null, primary key (id))
2022-11-25 21:52:22.750  INFO 27715 --- [  restartedMain] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
〜

アプリの起動時にdiaryというテーブルを作成している事がわかります。これは、前回のページでDiaryというエンティティクラスを作りましたが、Spring Data JPAがエンティティクラスに対応したdiaryテーブルを作成しています。

ちなみに、SQLログの前に"Hibernate:"とあります。Spring Data JPAが内部でHibernateを使用している事がわかります。

CRUDのSQLログの確認、Repository(リポジトリ)作成

エンティティクラスからテーブルを作成するSQLログの出力を確認しましたが、selectなどのCRUDのSQLログも確認しておきたいところです。
そこで、Spring Data JPAを使った簡単なRepository（リポジトリ）を作成し、select SQLを実行するリポジトリのメソッドを実行して、SQLのログを確認してみます。

まずは、エンティティクラスDiary.java用のリポジトリDiaryRepository.javaを新規に作成します（DiaryRepository.javaは、クラスではなくインタフェースです）。

$ tree test-h2/src/main/java/
test-h2/src/main/java/
└── com
    └── example
        └── demo
            ├── Diary.java
            ├── DiaryRepository.java
            └── TestH2Application.java

そして、DiaryRepository.javaを編集します。

package com.example.demo;

import org.springframework.data.repository.CrudRepository;

public interface DiaryRepository extends CrudRepository<Diary, Integer> {
}

DiaryRepository.javaは、CrudRepositoryを継承しただけのインタフェースです。
ただのインタフェースですが、Spring Data JPAはこのインタフェースを実装したクラスを自動で作ってくれるため、プログラマはこのDiaryRepository.javaを使ってDiaryエンティティの簡単なCRUD操作ができます。

また、CrudRepositoryの代わりにJpaRepositoryを使用しても問題ありません。JpaRepositoryはCrudRepositoryを継承しています。

次に、DiaryRepository.javaの呼び出し側のコードを書きます。
Spring Bootがプロジェクト作成時に自動で生成してくれたTestH2Application.javaを編集します。
(*ファイル名がTestH2Application.javaなのは、プロジェクト名がtest-h2のためです)

package com.example.demo;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.CommandLineRunner;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.dao.EmptyResultDataAccessException;

@SpringBootApplication
public class TestH2Application implements CommandLineRunner{
	@Autowired
	DiaryRepository diaryRepository;

	public static void main(String[] args) {
		SpringApplication.run(TestH2Application.class, args);
	}

	@Override
	public void run(String... args) throws Exception {
		diaryRepository.findAll();	//全件取得
		diaryRepository.findById(1);	//id=1のレコード取得
		try {
			diaryRepository.deleteById(2);	//id=2のレコード削除
		}catch(EmptyResultDataAccessException e) {
			System.out.println("データは存在しないため、レコードを削除できません！");
		}
	}
}

TestH2Application.javaは、CommandLineRunnerを継承しrunメソッドをオーバーライドしています。そして、アプリ起動時にrunメソッドが実行されます。
runメソッドでは、先ほど作成したリポジトリDiaryRepositoryを使って、全件取得やidに紐づくレコードを取得したり削除するメソッドを実行しています。

アプリの実行とSQLログの確認

それでは実際にアプリを実行して、コンソールビューでSQLのログを確認してみます。

〜
Hibernate: drop table if exists diary CASCADE 
Hibernate: create table diary (id integer generated by default as identity, comment varchar(255), create_datetime timestamp not null, primary key (id))
2022-11-25 22:24:42.646  INFO 28450 --- [  restartedMain] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
〜
2022-11-25 22:24:43.373  INFO 28450 --- [  restartedMain] com.example.demo.TestH2Application       : Started TestH2Application in 4.135 seconds (JVM running for 5.371)
Hibernate: select diary0_.id as id1_0_, diary0_.comment as comment2_0_, diary0_.create_datetime as create_d3_0_ from diary diary0_
Hibernate: select diary0_.id as id1_0_0_, diary0_.comment as comment2_0_0_, diary0_.create_datetime as create_d3_0_0_ from diary diary0_ where diary0_.id=?
Hibernate: select diary0_.id as id1_0_0_, diary0_.comment as comment2_0_0_, diary0_.create_datetime as create_d3_0_0_ from diary diary0_ where diary0_.id=?
Hibernate: delete from diary where id=?
〜

行頭に「Hibernate:〜」とあるのが、SQLのロギング情報です。
最初の方でdiaryテーブルが作成され、最後の方でselectやdeleteのSQLが実行されている事がわかります。
これで、CRUDのSQLログも出力できている事を確認できました。

ただ、最後のselectとdeleteのSQLをよく見ると、「where id=?」というようになっていて、SQLの条件文がプレースホルダーのままになっているのが気になります。
プレースホルダーの値を表示するには、application.propertiesファイルに１行追加します。

logging.level.org.hibernate.type.descriptor.sql.BasicBinder=trace

また、SQLを整形して出力して見やすくしたい場合、application.propertiesファイルに１行追加します。

spring.jpa.properties.hibernate.format_sql=true

この設定で再度アプリを実行して、コンソールビューでSQLのログを確認してみます。

〜
2022-11-25 22:28:18.889  INFO 28610 --- [  restartedMain] org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.H2Dialect
Hibernate: 
    
    drop table if exists diary CASCADE 
Hibernate: 
    
    create table diary (
       id integer generated by default as identity,
        comment varchar(255),
        create_datetime timestamp not null,
        primary key (id)
    )
〜
2022-11-25 22:28:20.087  INFO 28610 --- [  restartedMain] com.example.demo.TestH2Application       : Started TestH2Application in 3.733 seconds (JVM running for 4.662)
Hibernate: 
    select
        diary0_.id as id1_0_,
        diary0_.comment as comment2_0_,
        diary0_.create_datetime as create_d3_0_ 
    from
        diary diary0_
Hibernate: 
    select
        diary0_.id as id1_0_0_,
        diary0_.comment as comment2_0_0_,
        diary0_.create_datetime as create_d3_0_0_ 
    from
        diary diary0_ 
    where
        diary0_.id=?
2022-11-25 22:28:20.252 TRACE 28610 --- [  restartedMain] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [1]
Hibernate: 
    select
        diary0_.id as id1_0_0_,
        diary0_.comment as comment2_0_0_,
        diary0_.create_datetime as create_d3_0_0_ 
    from
        diary diary0_ 
    where
        diary0_.id=?
2022-11-25 22:28:20.257 TRACE 28610 --- [  restartedMain] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [2]
Hibernate: 
    delete 
    from
        diary 
    where
        id=?
2022-11-25 22:28:20.275 TRACE 28610 --- [  restartedMain] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [2]

実行されるSQLログが複数行で表示されるようになり見やすくなりました。ただ、SQLログはいちいち改行しない方がいいという人もいるでしょうから、このへんは好みだと思います。
あと、「binding parameter [1] as [INTEGER] - [2]」という感じでプレースホルダーに入る値もログからわかるようになりました。

最後に、次回

今回は、Spring BootアプリでSpring Data JPAによって実行されたSQLのログを出力する設定をしました。

ただ現状は出力されるSQLログは、条件文が「where id=?」というプレースホルダーの形式になっていて、その後にプレースホルダにバインティングされる値が出力されている状態です。
できればここは、プレースホルダではなく、実行されるSQLのログをそのまま出力したいところです。
また、初期データ作成のために作ったdata.sqlファイルのSQLログも出力できていません。

ですので次回は、別の方法のlog4jdbc-log4j2を使って、JDBCドライバ経由のSQLログの出力を設定してみたいと思います。

(第5回) log4jdbc-log4j2でSQLログの出力設定【H2, Spring Boot2】
H2データベース入門【Spring Boot】トップに戻る

Spring Bootの記事

Spring Boot2で日記投稿ウェブアプリ開発入門トップページ
Spring Bootでシンプルな日記投稿ウェブアプリの開発しながら、入門者・初心者にもわかりやすいように説明しています。DBを使用して、新規投稿、編集、削除、一覧表示という基本的なCRUD機能を備えたアプリです。

参考サイト

Spring Data JPA - リファレンスドキュメント