[JAVA] Untersuchen Sie das Verhalten des JPA-Transaktionszeitlimits

Überblick

Dies ist eine Aufzeichnung zur Untersuchung des Verhaltens des Transaktionszeitlimits in JPA. Wir haben es mit verschiedenen Mustern überprüft und die Ergebnisse und Gründe zusammengefasst. Die erste Hälfte dieses Artikels enthält eine Beschreibung des Bestätigungscodes und die zweite Hälfte beschreibt die Ergebnisse und die Zusammenfassung des Bestätigungscodes.

Umgebung

Referenz

Bestätigungscode und Umgebung

Aussicht

Für die Datenbank habe ich MySQL 5.6.25 verwendet, das auf dem lokalen PC ausgeführt wird. Erstellen Sie eine Ansicht mit der MySQL-Sleep-Funktion, um beim Zugriff auf die Datenbank einen pseudo-verzögerten Status zu erstellen. Das Durchsuchen der folgenden Ansichten dauert mindestens 3 Sekunden, um die Ergebnisse zurückzugeben.

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)

Anwendungsseitige Implementierung

Die zur Überprüfung verwendete Anwendung wurde mit Spring Boot und Spring Data JPA (ORM ist Hibernate) implementiert. Die eigentliche Überprüfung des Transaktionszeitlimits erfolgte mit dem Unit-Testcode.

Entität

Eine Implementierung der Entität, die auf die obige Ansicht zugreift.

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 weggelassen

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

Repository-Implementierung

Ich habe die Repository-Funktion von Spring Data JPA verwendet.

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-Implementierung

Es ist eine Implementierung des Prozesses zum Ausführen des DB-Zugriffs mithilfe des Repositorys. Unmittelbar nach dem Start der Transaktion, unmittelbar vor dem Ende, und für die an drei Stellen in der DB-Zugriffsverarbeitungsschleife angegebene Anzahl von Sekunden. Dieser Ruhezustand soll eine Pseudodarstellung einer anderen zeitaufwändigen Verarbeitung als dem DB-Zugriff sein (z. B. Aufrufen eines externen Webdienstes, Dateivorgang, Verarbeiten einer großen Anzahl von Sammlungen).

package com.example.service;

public interface TransactionTestService {
    /**
     * <p>Überprüfen Sie das Transaktionszeitlimit</p>
     *
     * @param beforeSleep Anzahl der Sekunden, die unmittelbar nach dem Start der Transaktion in den Ruhezustand versetzt werden sollen
     * @param loopNums Anzahl der Schleifen, die die DB-Zugriffsverarbeitung ausführen
     * @param loopInSleep Anzahl der Sekunden, die in einer Schleife geschlafen werden sollen
     * @param afterSleep Anzahl der Sekunden, die kurz vor dem Ende der Transaktion in den Ruhezustand versetzt werden sollen
     */
    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-Zugriffsverarbeitung, die 3 Sekunden dauert, um das Ergebnis zurückzugeben
            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

Das Timeout wird durch diesen Unit-Test überprüft. Das Zeitlimit wurde für alle Überprüfungsmuster auf 10 Sekunden festgelegt, und die Validierung wurde durchgeführt, während die an die Überprüfungsmethode übergebenen Parameter geändert wurden.

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

Überprüfung des Transaktionszeitlimits

Unter Verwendung der obigen Umgebung und des Bestätigungscodes haben wir das Auftreten eines Timeouts in mehreren Mustern überprüft. Um es zu Beginn kurz zusammenzufassen, gab es Framework- und JDBC-Ebenen für Timeouts.

Muster 1

Führen Sie den DB-Zugriff (3 Sekunden) nach dem Ruhezustand (11 Sekunden) unmittelbar nach dem Start der Transaktion aus. Das Timeout von 10 Sekunden geht in den Ruhezustand (11 Sekunden).

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 tritt auf

Eine TransactionTimedOutException wird ausgelöst.

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.

Das Timeout tritt nicht 10 Sekunden nach dem Start der Transaktion auf, sondern zum Zeitpunkt des DB-Zugriffs. Mit anderen Worten, es handelt sich um eine Zeitüberschreitung, die durch das Framework verursacht wird, wenn versucht wird, den vom Framework verwalteten Zeitlimit zu überschreiten.

Wenn Sie die Sitzungsmetriken von JPA überprüfen, können Sie feststellen, dass kein SQL ausgegeben wurde.

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

Sitzungsmetriken können ausgegeben werden, indem Sie die folgenden Einstellungen in application.yml vornehmen.

spring:
  jpa:
    properties:
      hibernate:
        generate_statistics: true

Muster 2

Schleifen zweimal für den Ruhezustand (8 Sekunden) nach dem DB-Zugriff (3 Sekunden). Das 10-Sekunden-Timeout tritt während des Ruhezustands der ersten Schleife auf.

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 tritt auf

Eine TransactionTimedOutException wird ausgelöst. Der Grund für das Auftreten ist der gleiche wie in Muster 1.

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

Wenn Sie Sitzungsmetriken überprüfen, sehen Sie, dass der DB-Zugriff nur einmal erfolgt.

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

Muster 3

Führen Sie den DB-Zugriff (3 Sekunden) nach dem Ruhezustand (8 Sekunden) unmittelbar nach dem Start der Transaktion aus. Das Zeitlimit von 10 Sekunden tritt während der DB-Zugriffsverarbeitung auf.

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 tritt auf

JpaSystemException <-Generische JDBCException wird ausgelöst.

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.

Dieses Muster ist eine Zeitüberschreitung, die durch eine Abfragezeitüberschreitung auf JDBC-Ebene verursacht wird. In diesem Beispiel wird der DB-Zugriff 8 Sekunden nach dem Start der Transaktion ausgeführt, sodass das Abfragezeitlimit auf die verbleibenden 2 Sekunden festgelegt wird. Da der DB-Zugriff (bis das Ergebnis zurückgegeben wird) 3 Sekunden dauert, tritt QueryTime out während des DB-Zugriffs auf. Als ich die MySQL-Protokolldatei überprüfte, wurde der Befehl "KILL QUERY" ausgegeben.

QueryTimeout-Einstellungen

QueryTimeout ist [EntityManagerFactoryUtils.applyTransactionTimeout](https://docs.spring.io/spring/docs/current/javadoc-api/org/springframework/orm/jpa/EntityManagerFactoryUtils.html#applyTransactionTimeoutjav. Dies geschieht in Persistenz.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.

Wenn Sie mit Sitzungsmetriken überprüfen, beträgt die Ausführungszeit des ausgeführten SQL etwa 2 Sekunden, sodass Sie sehen können, dass es mitten in der Ausführung abgebrochen wurde.

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

Muster 4

Schleife zweimal in den Ruhezustand (5 Sekunden) nach Ausführung des DB-Zugriffs (3 Sekunden). Das Zeitlimit von 10 Sekunden tritt während der DB-Zugriffsverarbeitung der zweiten Schleife auf.

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 tritt auf

JpaSystemException <-Generische JDBCException wird ausgelöst. Der Grund für das Auftreten ist der gleiche wie in Muster 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)
}

Muster 5

Führen Sie den DB-Zugriff (3 Sekunden) nach dem Ruhezustand (5 Sekunden) unmittelbar nach dem Start der Transaktion und den Ruhezustand (5 Sekunden) kurz vor dem Ende der Transaktion aus. Das Zeitlimit von 10 Sekunden tritt im Ruhezustand (5 Sekunden) kurz vor dem Ende der Transaktion auf.

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

Es tritt keine Zeitüberschreitung auf

Die Verarbeitungszeit der Prüfmethode selbst beträgt ca. 13 Sekunden und überschreitet die im Timeout angegebenen 10 Sekunden. Es gibt jedoch keine Zeitüberschreitung und die Prüfmethode endet normal. Dies liegt daran, dass der Prozess zum Überprüfen des Zeitlimits (JDBC-Ebene, ORM-Ebene) nicht ausgeführt wird.

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

Muster 6

Schleift zweimal in den Ruhezustand (6 Sekunden) nach Ausführung des DB-Zugriffs (3 Sekunden). Das Zeitlimit von 10 Sekunden tritt während der DB-Zugriffsverarbeitung der zweiten Schleife auf.

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 tritt auf

JpaSystemException <-PersistenceException wird ausgelöst.

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

Zeitüberschreitungen treten auf, aber ich bin mir nicht sicher warum. Ein Zeitlimit auf JDBC-Ebene sollte zu dem in der Abbildung gezeigten Zeitpunkt auftreten, es wurde jedoch keine SQL-Anweisung ausgegeben. Ich denke auch, dass die Ausnahme, die ausgelöst wird, wenn es auf Framework-Ebene eine Zeitüberschreitung gibt, TransactionTimedOutException ist, aber in Wirklichkeit wird JpaSystemException ausgelöst.

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

Untersuchen Sie das Verhalten des JPA-Transaktionszeitlimits
Sehen Sie sich das Verhalten von Entitätsaktualisierungen mit Spring Boot + Spring Data JPA an
[Java] [Spring] Testen Sie das Verhalten des Loggers
Verhalten von ThreadPoolTaskExecutor
Überprüfen Sie das Verhalten von getOne-, findById- und Abfragemethoden mit Spring Boot + Spring Data JPA
Überprüfen Sie das Verhalten von Java Intrinsic Locks mit bpftrace
Bis zur Verwendung von Spring Data und JPA Part 2
Bis zur Verwendung von Spring Data und JPA Part 1
Überprüfen Sie das Verhalten von include, exclude und ExhaustedRetryException von Spring Retry
Die Welt der Clara-Regeln (2)
Beurteilung des Kalenders
Die Welt der Clara-Regeln (4)
Die Welt der Clara-Regeln (1)
Die Welt der Clara-Regeln (3)
Die Welt der Clara-Regeln (5)
Die Idee der schnellen Sortierung
Die Idee von jQuery
Ich habe das Verhalten von Java Scanner und .nextLine () nicht wirklich verstanden.
Java-Anfänger fassten das Verhalten von Array und ArrayList kurz zusammen
Informationen zum Standardverhalten der Bruchrundung mit java.text.NumberFormat
Verhalten von Files.copy (pathA, pathB) zum Zeitpunkt des Fehlers