LoginSignup
11
14

More than 5 years have passed since last update.

@rubytomato@github(渡邉 真)

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

Last updated at Posted at 2017-09-10

概要

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

参考

検証コードおよび環境

ビュー

データベースにはローカル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秒)中にむかえます。

p1b.png
* 補足：図の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

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中にむかえます。

p2b.png

@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アクセス処理中にむかえます。

p3b.png

@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

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で行われています。

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アクセス処理中にむかえます。

p4b.png

@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秒)中にむかえます。

p5b.png

@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アクセス処理中にむかえます。

p6b.png

@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)
}
11
14
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
11
14