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

H2入門の第4回です。Spring BootアプリでSpring Data JPAによって実行されるSQLログの出力設定をします。DBはH2を使用。実際にエンティティクラスやリポジトリによって実行されたSQLログの確認をします。Spring Bootを学習している初心者・入門者の方は、参考にしてください。

動作環境と今回の目的

最終更新日:2021/5/19

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

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

・動作環境やバージョン情報です。
OS:macOS Catalina(バージョン10.15.5)
開発環境:Eclipse(Pleiades All in One、4.16(2020-06)、Java Full Edition版)、(*2020/8/28時点の最新安定版です)
Spring Boot:バージョン2.3.3
Java:11
データベース:H2

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

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

application.propertiesファイルを以下のように編集します。

spring.datasource.driver-class-name=org.h2.Driver
spring.datasource.url=jdbc:h2:mem:hogedb
#今回追加、SQLログ出力
spring.jpa.show-sql=true

今回追加したのは「spring.jpa.show-sql=true」の1行です。これでSQLのロギングを有効になり、Spring Data JPAによって実行されたSQLがコンソールビューに出力されます。

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

〜
2020-10-12 03:16:14.205  INFO 96112 --- [  restartedMain] com.example.demo.TestH2Application       : Started TestH2Application in 1.882 seconds (JVM running for 2.541)
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))
2020-10-12 03:16:14.460  INFO 96112 --- [         task-1] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
〜

アプリの起動時にdiaryというテーブルを作成している事がわかります。これは、前回までにJavaの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を新規に作成します。

$ 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 {
}

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

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

◾️Spring Data JPAのCrudRepository、JpaRepositoryについて
CrudRepositoryを継承しただけのDiaryRepositoryインタフェースを使用してできるCRUD操作には限界があります。
例えば、条件でテーブルのフィールドを指定してデータ取得をしたい場合はDiaryRepositoryインタフェースにメソッドを追加する必要がありますし、メソッドを追加して@Queryを付ければSQLを使用する事もできます。

Spring Data JPAのCrudRepository、JpaRepositoryについてはまた別の機会でちゃんと書きたいと思います。

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

//import文などはここでは省略
@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に紐づくレコードを取得したり削除するメソッドを実行しています。

[広告] Kindle Unlimitedなら対象の本が定額で読み放題
対象本には、プログラミングなどのIT関連本、マンガ、雑誌、ビジネス書などがたくさんあります!

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

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

〜
2020-10-12 19:14:55.790  INFO 2700 --- [  restartedMain] DeferredRepositoryInitializationListener : Triggering deferred initialization of Spring Data repositories…
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))
2020-10-12 19:14:56.094  INFO 2700 --- [         task-1] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2020-10-12 19:14:56.100  INFO 2700 --- [         task-1] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2020-10-12 19:14:56.228  INFO 2700 --- [  restartedMain] DeferredRepositoryInitializationListener : Spring Data repositories initialized!
2020-10-12 19:14:56.239  INFO 2700 --- [  restartedMain] com.example.demo.TestH2Application       : Started TestH2Application in 2.632 seconds (JVM running for 3.543)
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ファイルに1行追加します。

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

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

spring.jpa.properties.hibernate.format_sql=true

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

〜
2020-10-13 02:43:23.059  INFO 7723 --- [  restartedMain] DeferredRepositoryInitializationListener : Triggering deferred initialization of Spring Data repositories…
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)
    )
2020-10-13 02:43:23.393  INFO 7723 --- [         task-1] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2020-10-13 02:43:23.398  INFO 7723 --- [         task-1] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2020-10-13 02:43:23.524  INFO 7723 --- [  restartedMain] DeferredRepositoryInitializationListener : Spring Data repositories initialized!
2020-10-13 02:43:23.534  INFO 7723 --- [  restartedMain] com.example.demo.TestH2Application       : Started TestH2Application in 2.56 seconds (JVM running for 3.375)
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=?
2020-10-13 02:43:23.650 TRACE 7723 --- [  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=?
2020-10-13 02:43:23.655 TRACE 7723 --- [  restartedMain] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [2]
Hibernate: 
    delete 
    from
        diary 
    where
        id=?
2020-10-13 02:43:23.668 TRACE 7723 --- [  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 Boot2.3,2.4でシンプルな日記投稿ウェブアプリの開発しながら、入門者・初心者にもわかりやすいように説明しています。DBを使用して、新規投稿、編集、削除、一覧表示という基本的なCRUD機能を備えたアプリです。