概要

Spring Boot + Spring Data JPA でエンティティを更新する際にどのように SQL 文を発行しているかログ出力して挙動を見る

環境

macOS Catalina
Java 11 (AdoptOpenJDK build 11.0.7+10)
Gradle 6.4
Spring Boot 2.2.6
H2 Database 1.4.200

サンプルコード

ファイル一覧

├── build.gradle
├── settings.gradle
└── src
    └── main
        ├── java
        │   └── com
        │       └── example
        │           ├── Counter.java
        │           ├── CounterController.java
        │           ├── CounterRepository.java
        │           └── CounterService.java
        └── resources
            ├── application.properties
            └── data.sql

build.gradle

plugins {
  id 'org.springframework.boot' version '2.2.6.RELEASE'
  id 'io.spring.dependency-management' version '1.0.9.RELEASE'
  id 'java'
}

group = 'com.example'
version = '0.0.1'
sourceCompatibility = '11'

repositories {
  mavenCentral()
}

dependencies {
  // Spring
  implementation 'org.springframework.boot:spring-boot-starter-web'
  implementation 'org.springframework.boot:spring-boot-starter-data-jpa'
  // Lombok
  compileOnly 'org.projectlombok:lombok'
  annotationProcessor 'org.projectlombok:lombok'
  // H2 Database
  runtimeOnly 'com.h2database:h2'
}

settings.gradle

rootProject.name = 'my-app'

src/main/resources/application.properties

application.properties

# H2 Database の設定
# 自動コミットをオフに AUTOCOMMIT=OFF
# ログを出力するために TRACE_LEVEL_SYSTEM_OUT=2 を指定
spring.datasource.url=jdbc:h2:mem:testdb;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=false;AUTOCOMMIT=OFF;TRACE_LEVEL_SYSTEM_OUT=2
# Spring Framework と Hibernate ORM 等のログを出力するように指定
logging.level.org.hibernate.SQL=DEBUG
logging.level.org.hibernate.type.descriptor.sql=TRACE
logging.level.org.springframework.orm.jpa=DEBUG
logging.level.com.example=DEBUG
# Open EntityManager in View パターンを使わない
spring.jpa.open-in-view=false

src/main/resources/data.sql

-- 初期データを DB に追加
INSERT INTO counter (name, count, updated_at) VALUES ('mycounter', 0, LOCALTIMESTAMP);

src/main/java/com/example/Counter.java

エンティティクラス。

package com.example;

import lombok.Data;

import javax.persistence.Entity;
import javax.persistence.Id;
import java.time.LocalDateTime;

/**
 * DB テーブルの1レコード分に相当。
 */
@Data // Lombok で getter setter など便利なメソッドを自動生成
@Entity // JPA エンティティとして扱う
public class Counter {

  // カウンター名
  @Id // JPA にこの変数をオブジェクトの ID だと認識させる
  private String name;

  // カウント数
  private int count;

  // 更新日時
  private LocalDateTime updatedAt;
}

src/main/java/com/example/CounterController.java

package com.example;

import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.PathVariable;
import org.springframework.web.bind.annotation.RestController;

import java.util.Map;

@SpringBootApplication
@RestController
@Slf4j // org.slf4j.Logger 型の static final 変数 log を自動生成
public class CounterController {

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

  @Autowired
  private CounterService service;

  @GetMapping("/counter/{name}")
  public Map counter(@PathVariable("name") String name) {

    // カウントアップする
    log.debug("Before: countup");
    Counter counter = service.countup(name);
    log.debug("After: countup");

    // JSON レスポンスを生成
    return Map.of(counter.getName(), counter.getCount());
  }
}

src/main/java/com/example/CounterService.java

package com.example;

import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Service;

import javax.transaction.Transactional;
import java.time.LocalDateTime;

@Service
@Slf4j // org.slf4j.Logger 型の static final 変数 log を自動生成
public class CounterService {

  @Autowired
  private CounterRepository repository;

  /**
   * カウンターをカウントアップする。
   *
   * @param name カウンター名
   * @return カウンターのリスト
   */
  @Transactional // メソッド開始時にトランザクションを開始、終了時にコミットする
  public Counter countup(String name) {

    // DB から1レコードを取得
    log.debug("Before: getOne");
    Counter counter = repository.getOne(name);
    log.debug("After: getOne");

    // カウント数を更新
    log.debug("Before: setCount");
    counter.setCount(counter.getCount() + 1);
    log.debug("After: setCount");

    // 更新日時を更新
    log.debug("Before: setUpdatedAt");
    counter.setUpdatedAt(LocalDateTime.now());
    log.debug("After: setUpdatedAt");

    // DB から1レコードを取得
    log.debug("Before: getOne");
    Counter result = repository.getOne(name);
    log.debug("After: getOne");

    return result;
  }
}

src/main/java/com/example/CounterRepository.java

package com.example;

import org.springframework.data.jpa.repository.JpaRepository;
import org.springframework.stereotype.Repository;

/**
 * DB アクセス用リポジトリ。
 * Spring Data JPA が標準で提供するメソッドが自動生成される。
 */
@Repository
public interface CounterRepository extends JpaRepository<Counter, String> { // エンティティと主キーの型を指定
}

実行結果

Spring Boot アプリケーションを起動

gradle の bootRun タスクで Spring Boot アプリケーションを起動。

$ gradle bootRun

> Task :bootRun

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.2.6.RELEASE)

Spring Boot のログを見ると Hibernate ORM 5.4.12.Final が使われているのがわかる。

org.hibernate.Version                    : HHH000412: Hibernate ORM core version 5.4.12.Final
o.hibernate.annotations.common.Version   : HCANN000001: Hibernate Commons Annotations {5.1.0.Final}
org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.H2Dialect

エンティティクラスの定義から DB のテーブルが自動生成される。

org.hibernate.SQL                        : drop table counter if exists
org.hibernate.SQL                        : create table counter (name varchar(255) not null, count integer not null, updated_at timestamp, primary key (name))
o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'

H2 Database のログ。
data.sql に記述した通り、insert 文が発行されている。

2020-05-09 23:21:10 jdbc[3]: 
/*SQL */drop table counter if exists;
2020-05-09 23:21:10 jdbc[3]: 
/*SQL t:6*/create table counter (name varchar(255) not null, count integer not null, updated_at timestamp, primary key (name));
2020-05-09 23:21:10 jdbc[3]: 
/*SQL #:1 t:16*/INSERT INTO counter (name, count, updated_at) VALUES ('mycounter', 0, LOCALTIMESTAMP);

CounterService#countup 時の挙動を確認

別のターミナルから curl コマンドでアクセスする。

$ curl http://localhost:8080/counter/mycounter
{"mycounter":1}

Spring Boot のログを確認する。
CounterService#countup コール時。

com.example.CounterController            : Before: countup
o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [com.example.CounterService.countup]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(1254645459<open>)] for JPA transaction
o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@4ef360f9]

CounterRepository#getOne コール時。

com.example.CounterService               : Before: getOne
o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(1254645459<open>)] for JPA transaction
o.s.orm.jpa.JpaTransactionManager        : Participating in existing transaction
com.example.CounterService               : After: getOne

Counter#setCount コール時。
ここでようやく select 文を発行しているように見える。

com.example.CounterService               : Before: setCount
org.hibernate.SQL                        : select counter0_.name as name1_0_0_, counter0_.count as count2_0_0_, counter0_.updated_at as updated_3_0_0_ from counter counter0_ where counter0_.name=?
o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [VARCHAR] - [mycounter]
o.h.type.descriptor.sql.BasicExtractor   : extracted value ([count2_0_0_] : [INTEGER]) - [0]
o.h.type.descriptor.sql.BasicExtractor   : extracted value ([updated_3_0_0_] : [TIMESTAMP]) - [2020-05-09T23:21:10.472636]
com.example.CounterService               : After: setCount

H2 Database のログ。

2020-05-09 23:21:19 jdbc[3]: 
/*SQL l:153 #:1*/select counter0_.name as name1_0_0_, counter0_.count as count2_0_0_, counter0_.updated_at as updated_3_0_0_ from counter counter0_ where counter0_.name=? {1: 'mycounter'};
2020-05-09 23:21:19 jdbc[3]: 
/*SQL l:58 #:1*/SELECT VALUE FROM INFORMATION_SCHEMA.SETTINGS WHERE NAME=? {1: 'QUERY_TIMEOUT'};

Counter#setUpdatedAt コール時。
特に処理をしていないように見える。

com.example.CounterService               : Before: setUpdatedAt
com.example.CounterService               : After: setUpdatedAt

エンティティの setter メソッドを複数コール (setCount と setUpdatedAt) してもこの時点では更新処理は実行されてない。

CounterRepository#getOne コール時。

com.example.CounterService               : Before: getOne
o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(1254645459<open>)] for JPA transaction
o.s.orm.jpa.JpaTransactionManager        : Participating in existing transaction
com.example.CounterService               : After: getOne

CounterService#countup 内のコードがすべて完了してから、update 文が発行され、commit される。

o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(1254645459<open>)]
org.hibernate.SQL                        : update counter set count=?, updated_at=? where name=?
o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [1]
o.h.type.descriptor.sql.BasicBinder      : binding parameter [2] as [TIMESTAMP] - [2020-05-09T23:21:19.247019]
o.h.type.descriptor.sql.BasicBinder      : binding parameter [3] as [VARCHAR] - [mycounter]

H2 Database のログ。

2020-05-09 23:21:19 jdbc[3]: 
/*SQL l:53 #:1 t:3*/update counter set count=?, updated_at=? where name=? {1: 1, 2: TIMESTAMP '2020-05-09 23:21:19.247019', 3: 'mycounter'};
2020-05-09 23:21:19 jdbc[3]: 
/*SQL */COMMIT;
2020-05-09 23:21:19 jdbc[3]: 
/*SQL */COMMIT;

トランザクション後。

o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(1254645459<open>)] after transaction

CounterService#countup コール完了。

com.example.CounterController            : After: countup

参考資料