[JAVA] Examiner le comportement du délai d'expiration des transactions JPA

Aperçu

Il s'agit d'un enregistrement d'enquête sur le comportement du délai d'expiration des transactions dans JPA. Nous l'avons vérifié avec plusieurs modèles et résumé les résultats et les raisons. La première moitié de cet article est une description du code de vérification et la seconde moitié décrit les résultats et le résumé du code de vérification.

environnement

référence

Code de vérification et environnement

Vue

Pour la base de données, j'ai utilisé MySQL 5.6.25 fonctionnant sur le PC local. Créez une vue à l'aide de la fonction de veille MySQL pour créer un état pseudo-retardé lors de l'accès à la base de données. La recherche des vues ci-dessous prendra au moins 3 secondes pour renvoyer les résultats.

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)

Implémentation côté application

L'application utilisée pour la vérification a été implémentée avec Spring Boot et Spring Data JPA (ORM est Hibernate). La vérification réelle du délai d'expiration de la transaction a été effectuée avec le code de test unitaire.

entité

Une implémentation de l'entité qui accède à la vue ci-dessus.

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 omis

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

Implémentation du référentiel

J'ai utilisé la fonction Repository de 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> {
}

Mise en œuvre du service

Il s'agit d'une implémentation du processus permettant d'accéder à la base de données à l'aide du référentiel. Immédiatement après le début de la transaction, immédiatement avant la fin, et se met en veille pendant le nombre de secondes spécifié à trois endroits dans la boucle de traitement d'accès à la base de données. Ce sommeil est destiné à être une pseudo représentation de traitements chronophages autres que l'accès à la base de données (par exemple, appel d'un service Web externe, opération de fichier, traitement d'un grand nombre de collections).

package com.example.service;

public interface TransactionTestService {
    /**
     * <p>Vérifier le délai d'expiration de la transaction</p>
     *
     * @param beforeSleep Nombre de secondes pour dormir immédiatement après le début de la transaction
     * @param loopNums Nombre de boucles qui effectuent le traitement d'accès à la base de données
     * @param loopInSleep Nombre de secondes pour dormir dans une boucle
     * @param afterSleep Nombre de secondes de sommeil juste avant la fin de la 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);

            //Traitement d'accès à la base de données qui prend 3 secondes pour renvoyer le résultat
            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);
    }

}

Test de service unitaire

Le délai d'expiration est vérifié par ce test unitaire. Le délai a été fixé à 10 secondes pour tous les modèles de vérification et la validation a été effectuée tout en modifiant les paramètres transmis à la méthode de vérification.

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

Vérification du délai d'expiration de la transaction

À l'aide de l'environnement et du code de vérification ci-dessus, nous avons vérifié l'occurrence du délai d'expiration selon plusieurs modèles. Pour résumer brièvement au début, il y avait des niveaux de framework et JDBC pour les délais d'attente.

modèle 1

Exécutez l'accès à la base de données (3 secondes) après la mise en veille (11 secondes) immédiatement après le démarrage de la transaction. Le délai de 10 secondes se met en veille (11 secondes).

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

Expiration du délai

Une TransactionTimedOutException est levée.

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.

Le délai d'expiration se produit au moment de l'accès à la base de données, et non 10 secondes après le début de la transaction. En d'autres termes, il s'agit d'un timeout causé par le framework lorsque l'accès à la base de données est tenté de dépasser le délai géré par le framework.

Si vous vérifiez avec les métriques de session de JPA, vous pouvez voir qu'aucun SQL n'a été émis.

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

Les métriques de session peuvent être générées en définissant les paramètres suivants dans application.yml.

spring:
  jpa:
    properties:
      hibernate:
        generate_statistics: true

Motif 2

Boucle deux fois pour le sommeil (8 secondes) après l'accès à la base de données (3 secondes). Le délai d'expiration de 10 secondes se produira pendant le sommeil de la première boucle.

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

Expiration du délai

Une TransactionTimedOutException est levée. La raison de l'occurrence est la même que celle du modèle 1.

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

Si vous vérifiez les métriques de session, vous pouvez voir que l'accès à la base de données n'est effectué qu'une seule fois.

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

Modèle 3

Exécutez l'accès à la base de données (3 secondes) après la mise en veille (8 secondes) immédiatement après le démarrage de la transaction. Le délai d'expiration de 10 secondes se produira pendant le traitement d'accès à la base de données.

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

Expiration du délai

JpaSystemException <-Generic JDBCException est levée.

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.

Ce modèle est un délai d'expiration causé par un délai de requête de niveau JDBC. Dans cet exemple, l'accès à la base de données est effectué 8 secondes après le début de la transaction, de sorte que le délai d'expiration de la requête est défini sur les 2 secondes restantes. Étant donné que l'accès à la base de données (jusqu'à ce que le résultat soit renvoyé) prend 3 secondes, QueryTime out se produit pendant l'accès à la base de données. Lorsque j'ai vérifié le fichier journal MySQL, la commande "KILL QUERY" a été lancée.

Paramètres QueryTimeout

QueryTimeout est [EntityManagerFactoryUtils.applyTransactionTimeout](https://docs.spring.io/spring/docs/current/javadoc-api/org/springframework/orm/jpa/EntityManagerFactoryUtils.html#applyTransactionTimeout-avery.javery. Cela se fait dans 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.

Si vous vérifiez avec les métriques de session, le temps d'exécution du sql exécuté est d'environ 2 secondes, vous pouvez donc voir qu'il a été annulé au milieu de l'exécution.

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

Modèle 4

Boucle deux fois pour se mettre en veille (5 secondes) après l'exécution de l'accès à la base de données (3 secondes). Le délai d'expiration de 10 secondes se produira pendant le traitement d'accès à la base de données de la deuxième boucle.

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

Expiration du délai

JpaSystemException <-Generic JDBCException est levée. La raison de l'occurrence est la même que celle du modèle 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)
}

Modèle 5

Exécutez l'accès à la base de données (3 secondes) après la mise en veille (5 secondes) immédiatement après le début de la transaction et la mise en veille (5 secondes) juste avant la fin de la transaction. Le délai d'expiration de 10 secondes se produira pendant le sommeil (5 secondes) juste avant la fin de la 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");
}

Aucun délai d'attente ne se produit

Le temps de traitement de la méthode de vérification elle-même prend environ 13 secondes et dépasse les 10 secondes spécifiées dans timeout. Cependant, il n'y a pas de délai d'expiration et la méthode de vérification se termine normalement. En effet, le processus de vérification du délai (niveau JDBC, niveau ORM) n'est pas exécuté.

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

Modèle 6

Boucle deux fois pour se mettre en veille (6 secondes) après l'exécution de l'accès à la base de données (3 secondes). Le délai d'expiration de 10 secondes se produira pendant le traitement d'accès à la base de données de la deuxième boucle.

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

Expiration du délai

JpaSystemException <-PersistenceException est levée.

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

Des délais d'attente se produisent, mais je ne sais pas pourquoi. Un délai d'expiration de niveau JDBC doit se produire au moment indiqué dans la figure, mais aucune instruction SQL n'a été réellement émise. De plus, je pense que l'exception qui est levée si le délai d'expiration est au niveau du cadre est TransactionTimedOutException, mais en réalité JpaSystemException est levée.

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

Examiner le comportement du délai d'expiration des transactions JPA
Voir le comportement des mises à jour d'entités avec Spring Boot + Spring Data JPA
[Java] [Spring] Tester le comportement de l'enregistreur
Comportement de ThreadPoolTaskExecutor
Vérifiez le comportement de getOne, findById et des méthodes de requête avec Spring Boot + Spring Data JPA
Vérifiez le comportement de Java Intrinsic Locks avec bpftrace
Jusqu'à l'utilisation de Spring Data et JPA Part 2
Jusqu'à l'utilisation de Spring Data et JPA Part 1
Vérifiez le comportement de include, exclude et ExhaustedRetryException de Spring Retry
Le monde de Clara-Rules (2)
Jugement du calendrier
Le monde de Clara-Rules (4)
Le monde de Clara-Rules (1)
Le monde de Clara-Rules (3)
Le monde de Clara-Rules (5)
L'idée du tri rapide
L'idée de jQuery
Je n'ai pas vraiment compris le comportement de Java Scanner et .nextLine ()
Les débutants en Java ont brièvement résumé le comportement de Array et ArrayList
À propos du comportement par défaut de l'arrondi des fractions à l'aide de java.text.NumberFormat
Comportement de Files.copy (pathA, pathB) au moment de l'erreur