JPAのトランザクションタイムアウトの挙動について調査

概要

JPAでのトランザクションタイムアウトの挙動を調査した記録です。いくつかのパターンで検証しその結果と理由をまとめました。
この記事の前半は検証コードの説明で、後半にその検証コードでの結果とまとめを記載しています。

環境

• Windows10 Professional
• Java 1.8.0_144
• Spring Boot 1.5.6
  • Spring Data JPA 1.11.6
  • Hibernate 5.0.1
• MySQL 5.6.25

参考

• [Understanding JDBC Internals & Timeout Configuration] (http://www.cubrid.org/blog/understanding-jdbc-internals-and-timeout-configuration)
• [Spring Bootとmybatisでトランザクションタイムアウトが効かない] (http://qiita.com/yoshidan/items/7ce240ead835d48ce2a1)

検証コードおよび環境

ビュー

データベースにはローカルPC上で稼働するMySQL 5.6.25を使用しました。
DBアクセス時に疑似的に遅延状態を発生させるために、MySQLのsleep関数を使用したビューを作成します。
下記のビューを検索すると結果が返るまで少なくとも3秒かかります。

CREATE OR REPLACE VIEW pseudo_delay_view (
      id
    , sleep
    , create_at ) AS
SELECT UUID() AS id
    , SLEEP(3) AS sleep
    , NOW() AS create_at
;

select now(); select * from pseudo_delay_view; select now();

+---------------------+
| now()               |
+---------------------+
| 2017-09-08 19:23:18 |
+---------------------+
1 row in set (0.00 sec)

+--------------------------------------+-------+---------------------+
| id                                   | sleep | create_at           |
+--------------------------------------+-------+---------------------+
| bb5fe3d9-947f-11e7-b914-1c6f65331b46 |     0 | 2017-09-08 19:23:18 |
+--------------------------------------+-------+---------------------+
1 row in set (3.00 sec)

+---------------------+
| now()               |
+---------------------+
| 2017-09-08 19:23:21 |
+---------------------+
1 row in set (0.00 sec)

アプリケーション側の実装

検証に使用するアプリケーションはSpring BootとSpring Data JPA(ORMはHibernate)で実装しました。
トランザクションタイムアウトの実際の検証はUnitテストコードで行いました。

エンティティ

上記のビューにアクセスするエンティティの実装です。

package com.example.domain.entity;

import javax.persistence.Column;
import javax.persistence.Entity;
import javax.persistence.Id;
import javax.persistence.Table;
import java.io.Serializable;
import java.time.LocalDateTime;

@Entity
@Table(name="pseudo_delay_view")
public class PseudoDelay implements Serializable {

    private static final long serialVersionUID = -7295335149208136304L;

    @Id
    private String id;
    @Column(name="sleep")
    private Integer sleep;
    @Column(name="create_at")
    private LocalDateTime createAt;

    // getter/setterは省略

    @Override
    public String toString() {
        return "PseudoDelay{" +
                "id='" + id + '\'' +
                ", sleep=" + sleep +
                ", createAt=" + createAt +
                '}';
    }
}

リポジトリの実装

Spring Data JPAのRepository機能を使用しました。

package com.example.domain.repository;

import com.example.domain.entity.PseudoDelay;
import org.springframework.data.jpa.repository.JpaRepository;

public interface PseudoDelayRepository extends JpaRepository<PseudoDelay, String> {
}

サービスの実装

repositoryを使ってDBアクセスを行う処理の実装です。トランザクション開始直後、終了直前、DBアクセス処理のループ内の3箇所で指定する秒数sleepします。このsleepはDBアクセス以外で時間のかかる処理（たとえば外部Webサービスの呼び出し、File操作、大量のコレクションの処理）を疑似的に表現しているつもりです。

package com.example.service;

public interface TransactionTestService {
    /**
     * <p>トランザクションタイムアウトの検証を行う</p>
     *
     * @param beforeSleep トランザクション開始直後にsleepする秒数
     * @param loopNums DBアクセス処理を行うループ数
     * @param loopInSleep ループ内でsleepする秒数
     * @param afterSleep トランザクション終了直前にsleepする秒数
     */
    void check(long beforeSleep, int loopNums, long loopInSleep, long afterSleep);
}

package com.example.service.impl;

import com.example.domain.entity.PseudoDelay;
import com.example.domain.repository.PseudoDelayRepository;
import com.example.service.TransactionTestService;
import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Service;
import org.springframework.transaction.annotation.Transactional;

import java.util.concurrent.TimeUnit;

@Service
@Slf4j
public class TransactionTestServiceImpl implements TransactionTestService {

    @Autowired
    private PseudoDelayRepository repository;

    @Transactional(readOnly = true)
    @Override
    public void check(long beforeSleep, int loopNums, long loopInSleep, long afterSleep) {

        if (beforeSleep > 0L) {
            sleepAs(beforeSleep, "before");
        }

        for (int i=0; i<loopNums; i++) {
            log.debug("loop({}) start", i);

            // 結果が返るまで3秒かかるDBアクセス処理
            PseudoDelay result = repository.findAll().get(0);
            log.debug("result=[{}]", result);

            if (loopInSleep > 0L) {
                sleepAs(loopInSleep, "in loop");
            }

            log.debug("loop end");
        }

        if (afterSleep > 0L) {
            sleepAs(afterSleep, "after");
        }

    }

    private void sleepAs(long sec, String mes) {
        log.debug("sleep start : {}", mes);
        try {
            TimeUnit.SECONDS.sleep(sec);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
        log.debug("sleep end : {}", mes);
    }

}

サービスのUnitテスト

タイムアウトの検証はこのUnitテストで行います。タイムアウトはすべての検証パターンで10秒固定とし、checkメソッドに渡すパラメータを変えながら検証しました。

@RunWith(SpringRunner.class)
@SpringBootTest
@ContextConfiguration(classes = {
        TestApplication.class, DataSourceConfigure.class})
@Slf4j
public class TransactionTestServiceTest {

    @Autowired
    private TransactionTestService service;

    @Transactional(readOnly = true, timeout = 10)
    @Test
    public void check() {
        log.debug("transaction timeout test start >>>");
        service.check(0L, 2, 6L, 0L);
        log.debug("<<< end");
    }

}

package com.example.service;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;

@SpringBootApplication(scanBasePackages = {
        "com.example.service",
        "com.example.domain"
})
public class TestApplication {
    public static void main(String... args) {
        SpringApplication.run(TestApplication.class, args);
    }
}

トランザクションタイムアウトの検証

上記の環境および検証コードを用いて、いくつかのパターンでタイムアウトの発生を検証しました。
最初に簡単にまとめるとタイムアウトの発生にはフレームワークレベルとJDBCレベルがありました。

パターン1

トランザクション開始直後にsleep(11秒)した後にDBアクセス(3秒)を実行します。タイムアウトの10秒はsleep(11秒)中にむかえます。

• 補足：図の1マスは1秒を表現

@Transactional(readOnly = true, timeout = 10)
@Test
public void check() {
    log.debug("transaction timeout test start >>>");
    service.check(11L, 1, 0L, 0L);
    log.debug("<<< end");
}

タイムアウトは発生する

TransactionTimedOutExceptionがスローされます。

org.springframework.transaction.TransactionTimedOutException: Transaction timed out: deadline was Fri Sep 08 19:32:26 JST 2017

[org.springframework.transaction.TransactionTimedOutException] (https://docs.spring.io/spring-framework/docs/current/javadoc-api/org/springframework/transaction/TransactionTimedOutException.html)

Exception to be thrown when a transaction has timed out.

Thrown by Spring's local transaction strategies if the deadline for a transaction has been reached when an operation is attempted, according to the timeout specified for the given transaction.

タイムアウトはトランザクション開始から10秒たってからではなく、DBアクセスを行うタイミングで発生します。
つまりフレームワークが管理するタイムアウトを超えてDBアクセスが行われようとした場合に、フレームワークによっておこるタイムアウトです。

JPAのSession Metricsで確認するとSQLは発行されていないことがわかります。

Session Metrics {
    1667866 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    0 nanoseconds spent preparing 0 JDBC statements;
    0 nanoseconds spent executing 0 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}

Session Metricsはapplication.ymlで下記の設定を行うことで出力できます。

spring:
  jpa:
    properties:
      hibernate:
        generate_statistics: true

パターン2

DBアクセス(3秒)を行った後にsleep(8秒)する処理を2回ループします。タイムアウトの10秒は1回目ループのsleep中にむかえます。

@Transactional(readOnly = true, timeout = 10)
@Test
public void check() {
    log.debug("transaction timeout test start >>>");
    service.check(0L, 2, 8L, 0L);
    log.debug("<<< end");
}

タイムアウトは発生する

TransactionTimedOutExceptionがスローされます。
発生理由はパターン1と同様です。

org.springframework.transaction.TransactionTimedOutException: Transaction timed out: deadline was Fri Sep 08 19:54:57 JST 2017

Session Metricsを確認するとDBアクセスは1回しか行われていないことがわかります。

Session Metrics {
    1154803 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    30234062 nanoseconds spent preparing 1 JDBC statements;
    3002660666 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    34314 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}

パターン3

トランザクション開始直後にsleep(8秒)した後にDBアクセス(3秒)を実行します。タイムアウトの10秒はDBアクセス処理中にむかえます。

@Transactional(readOnly = true, timeout = 10)
@Test
public void check() {
    log.debug("transaction timeout test start >>>");
    service.check(8L, 1, 0L, 0L);
    log.debug("<<< end");
}

タイムアウトは発生する

JpaSystemException <- GenericJDBCExceptionがスローされます。

org.springframework.orm.jpa.JpaSystemException: could not extract ResultSet; nested exception is org.hibernate.exception.GenericJDBCException: could not extract ResultSet

[org.springframework.orm.jpa.JpaSystemException] (https://docs.spring.io/spring-framework/docs/current/javadoc-api/org/springframework/orm/jpa/JpaSystemException.html)

JPA-specific subclass of UncategorizedDataAccessException, for JPA system errors that do not match any concrete org.springframework.dao exceptions.

このパターンはJDBCレベルのQueryTimeアウトが起きたために発生するタイムアウトです。
この例では、トランザクション開始から8秒経過後にDBアクセスが行われるので、QueryTimeアウトには残りの2秒が設定されます。DBアクセス（の結果が返るまで）は3秒かかるようになっているので、DBアクセス途中でQueryTimeアウトが起きます。
MySQLのログファイルを確認すると"KILL QUERY"コマンドが発行されていました。

QueryTimeoutの設定

QueryTimeoutは[EntityManagerFactoryUtils.applyTransactionTimeout] (https://docs.spring.io/spring/docs/current/javadoc-api/org/springframework/orm/jpa/EntityManagerFactoryUtils.html#applyTransactionTimeout-javax.persistence.Query-javax.persistence.EntityManagerFactory-)で行われています。

Apply the current transaction timeout, if any, to the given JPA Query object.
This method sets the JPA 2.0 query hint "javax.persistence.query.timeout" accordingly.

Session Metricsで確認すると実行したsqlの実行時間が約2秒となっているので、実行途中でキャンセルされたことがわかります。

Session Metrics {
    1115870 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    23817317 nanoseconds spent preparing 1 JDBC statements;
    2027322968 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    34315 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}

パターン4

DBアクセス(3秒)を実行した後にsleep(5秒)する処理を2回ループします。タイムアウトの10秒は2回目ループのDBアクセス処理中にむかえます。

@Transactional(readOnly = true, timeout = 10)
@Test
public void check() {
    log.debug("transaction timeout test start >>>");
    service.check(0L, 2, 5L, 0L);
    log.debug("<<< end");
}

タイムアウトは発生する

JpaSystemException <- GenericJDBCExceptionがスローされます。
発生理由はパターン3と同様です。

Session Metrics {
    1412820 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    24558371 nanoseconds spent preparing 2 JDBC statements;
    5027844939 nanoseconds spent executing 2 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    26395 nanoseconds spent executing 2 partial-flushes (flushing a total of 0 entities and 0 collections)
}

パターン5

トランザクション開始直後にsleep(5秒)した後にDBアクセス(3秒)を実行し、トランザクション終了直前にsleep(5秒)します。タイムアウトの10秒はトランザクション終了直前のsleep(5秒)中にむかえます。

@Transactional(readOnly = true, timeout = 10)
@Test
public void check() {
    log.debug("transaction timeout test start >>>");
    service.check(5L, 1, 0L, 5L);
    log.debug("<<< end");
}

タイムアウトは発生しない

checkメソッド自体の処理時間が約13秒かかりtimeoutで指定した10秒を超えます。しかしタイムアウトはおきずcheckメソッドは正常終了します。
これはタイムアウトをチェックする処理(JDBCレベル、ORMレベル)が実行されないためです。

Session Metrics {
    1117190 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    27877934 nanoseconds spent preparing 1 JDBC statements;
    3003194515 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    50152 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}

パターン6

DBアクセス(3秒)を実行した後にsleep(6秒)する処理を2回ループします。タイムアウトの10秒は2回目ループのDBアクセス処理中にむかえます。

@Transactional(readOnly = true, timeout = 10)
@Test
public void check() {
    log.debug("transaction timeout test start >>>");
    service.check(0L, 2, 6L, 0L);
    log.debug("<<< end");
}

タイムアウトは発生する

JpaSystemException <- PersistenceExceptionがスローされます。

org.springframework.orm.jpa.JpaSystemException: nested exception is javax.persistence.PersistenceException

タイムアウトは発生するのでが、その理由についてはいまいちよくわかっていません。図のタイミングではJDBCレベルのタイムアウトが発生するはずですが実際にはSQL文は発行されていません。またフレームワークレベルでのタイムアウトであればスローされる例外はTransactionTimedOutExceptionだと思うのですが、実際にはJpaSystemExceptionがスローされています。

Session Metrics {
    1785986 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    26327198 nanoseconds spent preparing 2 JDBC statements;
    3002153213 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    46192 nanoseconds spent executing 2 partial-flushes (flushing a total of 0 entities and 0 collections)
}