Investigate the behavior of JPA transaction timeout

Overview

This is a record of investigating the behavior of transaction timeout in JPA. We verified it with several patterns and summarized the results and reasons. The first half of this article is a description of the verification code, and the second half describes the results and summary of the verification code.

environment

reference

Verification code and environment

View

For the database, I used MySQL 5.6.25 running on the local PC. Create a view using MySQL's sleep function to generate a pseudo delay state when accessing the DB. Searching the views below will take at least 3 seconds to return results.

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)

Application side implementation

The application used for verification was implemented with Spring Boot and Spring Data JPA (ORM is Hibernate). The actual verification of the transaction timeout was done with Unit test code.

entity

An implementation of the entity that accesses the above view.

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 omitted

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

Repository implementation

I used the Repository function of Spring Data JPA.

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

Service implementation

It is an implementation of the process to access DB using repository. Immediately after the transaction starts, immediately before the end, and sleeps for the number of seconds specified in three places in the DB access processing loop. This sleep is intended to be a pseudo representation of time-consuming processing other than DB access (for example, calling an external Web service, File operation, processing a large number of collections).

package com.example.service;

public interface TransactionTestService {
    /**
     * <p>Verify transaction timeout</p>
     *
     * @param beforeSleep Number of seconds to sleep immediately after the start of a transaction
     * @param loopNums Number of loops that perform DB access processing
     * @param loopInSleep Number of seconds to sleep in a loop
     * @param afterSleep Number of seconds to sleep just before the end of a transaction
     */
    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);

            //DB access process that takes 3 seconds to return the result
            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 test of service

This Unit test is used to verify the timeout. The timeout was fixed at 10 seconds for all verification patterns, and validation was performed while changing the parameters passed to the check method.

@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);
    }
}

Transaction timeout validation

Using the above environment and verification code, we verified the occurrence of timeouts in several patterns. To summarize briefly at the beginning, there were framework level and JDBC level for timeout occurrence.

pattern 1

Execute DB access (3 seconds) after sleeping (11 seconds) immediately after the transaction starts. The timeout of 10 seconds goes to sleep (11 seconds).

p1b.png

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

Timeout occurs

A TransactionTimedOutException is thrown.

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.

The timeout occurs at the timing of DB access, not 10 seconds after the transaction starts. In other words, it is a timeout caused by the framework when DB access is attempted to exceed the timeout managed by the framework.

If you check with JPA's Session Metrics, you can see that no SQL has been issued.

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 can be output by making the following settings in application.yml.

spring:
  jpa:
    properties:
      hibernate:
        generate_statistics: true

Pattern 2

It loops twice the process of sleeping (8 seconds) after DB access (3 seconds). The 10 second timeout will occur during the sleep of the first loop.

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");
}

Timeout occurs

A TransactionTimedOutException is thrown. The reason for the occurrence is the same as pattern 1.

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

If you check Session Metrics, you can see that the DB access is done only once.

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)
}

Pattern 3

Execute DB access (3 seconds) after sleeping (8 seconds) immediately after the transaction starts. The timeout of 10 seconds will occur during DB access processing.

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");
}

Timeout occurs

JpaSystemException <-Generic JDBCException is thrown.

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.

This pattern is a timeout caused by a JDBC level Query Time out. In this example, the DB access is performed 8 seconds after the transaction starts, so the Query Time out is set to the remaining 2 seconds. Since DB access (until the result is returned) takes 3 seconds, Query Time out occurs during DB access. When I checked the MySQL log file, the "KILL QUERY" command was issued.

QueryTimeout settings

QueryTimeout is [EntityManagerFactoryUtils.applyTransactionTimeout](https://docs.spring.io/spring/docs/current/javadoc-api/org/springframework/orm/jpa/EntityManagerFactoryUtils.html#applyTransactionTimeout-javax.persistence.Query-javax. It is done in 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.

If you check with Session Metrics, the execution time of the executed sql is about 2 seconds, so you can see that it was canceled in the middle of execution.

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)
}

Pattern 4

It loops twice the process of sleeping (5 seconds) after executing DB access (3 seconds). The timeout of 10 seconds will occur during the DB access processing of the second loop.

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");
}

Timeout occurs

JpaSystemException <-Generic JDBCException is thrown. The reason for the occurrence is the same as pattern 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)
}

Pattern 5

Execute DB access (3 seconds) after sleeping (5 seconds) immediately after the start of the transaction, and sleep (5 seconds) just before the end of the transaction. The timeout of 10 seconds is reached during sleep (5 seconds) just before the end of the transaction.

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");
}

No timeout occurs

The processing time of the check method itself takes about 13 seconds and exceeds the 10 seconds specified by timeout. However, there is no timeout and the check method ends normally. This is because the process of checking the timeout (JDBC level, ORM level) is not executed.

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)
}

Pattern 6

It loops twice the process of sleeping (6 seconds) after executing DB access (3 seconds). The timeout of 10 seconds will occur during the DB access processing of the second loop.

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");
}

Timeout occurs

JpaSystemException <-PersistenceException is thrown.

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

Time-outs occur, but I'm not sure why. A JDBC level timeout should occur at the timing shown in the figure, but no SQL statement was actually issued. Also, I think the exception that is thrown if there is a timeout at the framework level is TransactionTimedOutException, but in reality JpaSystemException is thrown.

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)
}

Recommended Posts

Investigate the behavior of JPA transaction timeout
See the behavior of entity update with Spring Boot + Spring Data JPA
[Java] [Spring] Test the behavior of the logger
Behavior of ThreadPoolTaskExecutor
Check the behavior of getOne, findById, and query methods in Spring Boot + Spring Data JPA
Check the behavior of Java Intrinsic Locks with bpftrace
Until the use of Spring Data and JPA Part 2
Until the use of Spring Data and JPA Part 1
Check the behavior of include, exclude, ExhaustedRetryException of Spring Retry
The world of clara-rules (2)
Judgment of the calendar
The world of clara-rules (4)
The world of clara-rules (1)
The world of clara-rules (3)
The world of clara-rules (5)
The idea of quicksort
The idea of jQuery
I didn't understand the behavior of Java Scanner and .nextLine ().
Java beginners briefly summarized the behavior of Array and ArrayList
About the default behavior of decimal point rounding using java.text.NumberFormat
About the behavior at the time of error of Files.copy (pathA, pathB)