Транзакции hibernate.connection.handling_mode и REQUIRES_NEW (Hibernate 5.2 + Spring 4.3)

Question

Я замечаю очень разные поведения в нашем приложении JPA / JTA, когда я устанавливаю hibernate.connection.handling_mode и когда я не устанавливаю его.У меня определена следующая сущность -

@Cache(usage = CacheConcurrencyStrategy.TRANSACTIONAL)
@Entity
public class Notification {

    @Id
    @GeneratedValue()
    private long id;

    @OneToMany(mappedBy = "notification", cascade = CascadeType.ALL, fetch = FetchType.EAGER)
    private Set<ErrorDetails> errorDetails;

    ....
}

И мои свойства гиберата установлены следующим образом -

    hibernate.dialect=com.CustomMariaDBDialect
    hibernate.transaction.flush_before_completion=true
    hibernate.cache.use_second_level_cache=true
    hibernate.transaction.auto_close_session=true
    hibernate.show_sql=false
    hibernate.id.new_generator_mappings=false
    hibernate.jta.UserTransaction=UserTransaction
    hibernate.cache.infinispan.cachemanager=java:jboss/infinispan/hibernate
    hibernate.transaction.coordinator_class=com.CustomJTATransactionFactory //A JtaTransactionCoordinatorBuilderImpl Uses JNDI Lookup for getUserTransaction
    hibernate.transaction.jta.platform=org.hibernate.engine.transaction.jta.platform.internal.JBossAppServerJtaPlatform
    hibernate.cache.region.factory_class=org.hibernate.cache.infinispan.JndiInfinispanRegionFactory
    hibernate.connection.handling_mode=DELAYED_ACQUISITION_AND_RELEASE_AFTER_STATEMENT

У меня несколько сущностей уведомлений, сохраняемых в одном потоке , но все в своих собственных транзакциях (, управляемых Spring TxManager с PropagationLevel, установленным в REQUIRES_NEW ).Я создал пользовательский Hibernate SessionEventListener для регистрации активности сеанса.Я заметил, что когда у меня не установлен connection.handling_mode , все мои сущности фиксируются и сбрасываются без проблем -

2018-09-24 22:33:29,740 INFO  [default task-56]-[SessionEventListener] partialFlushStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,741 INFO  [default task-56]-[SessionEventListener] dirtyCalculationStart 0;0;com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,741 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,741 INFO  [default task-56]-[SessionEventListener] jdbcConnectionAcquisitionStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,741 INFO  [default task-56]-[SessionEventListener] jdbcConnectionAcquisitionEnd com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,741 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementEnd com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,741 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,742 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementEnd com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,742 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,743 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementEnd com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,743 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,743 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementEnd com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,743 INFO  [default task-56]-[SessionEventListener] flushStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,743 INFO  [default task-56]-[SessionEventListener] dirtyCalculationStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,743 INFO  [default task-56]-[SessionEventListener] dirtyCalculationEnd false com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,744 INFO  [default task-56]-[SessionEventListener] partialFlushStart 1;0;com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,744 INFO  [default task-56]-[SessionEventListener] Tx completed truefor entity com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,744 INFO  [default task-56]-[SessionEventListener] END com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,744 INFO  [default task-56]-[SessionEventListener] jdbcConnectionReleaseStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,744 INFO  [default task-56]-[SessionEventListener] jdbcConnectionReleaseEnd com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,761 INFO  [default task-56]-[SessionEventListener] partialFlushStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,761 INFO  [default task-56]-[SessionEventListener] dirtyCalculationStart 0;0;com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,761 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,761 INFO  [default task-56]-[SessionEventListener] jdbcConnectionAcquisitionStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,761 INFO  [default task-56]-[SessionEventListener] jdbcConnectionAcquisitionEnd com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,762 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementEnd com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,762 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,762 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementEnd com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,762 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,762 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementEnd com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,762 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementEnd com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] flushStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] dirtyCalculationStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] dirtyCalculationEnd false com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] partialFlushStart 1;0;com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] Tx completed truefor entity com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] END com.myorg.model.Notification@68c6c90d

Но когда у меня есть connection.handling_modeравным DELAYED_ACQUISITION_AND_RELEASE_AFTER_STATEMENT , сеанс зависает в jdbcExecuteStatementStart и после истечения времени транзакции через 5 минут переходит к фиксации - обратите внимание, что jdbcExecuteStatementStart происходит в 23:33:32 и заканчивается в 23:33:32 и заканчивается в 23:33:32после истечения срока действия родительской транзакции -

2018-09-24 23:28:32,506 INFO  [default task-64]-[SessionEventListener] partialFlushStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,506 INFO  [default task-64]-[SessionEventListener] dirtyCalculationStart 0;0;com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,506 INFO  [default task-64]-[SessionEventListener] jdbcPrepareStatementStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,506 INFO  [default task-64]-[SessionEventListener] jdbcConnectionAcquisitionStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,507 INFO  [default task-64]-[SessionEventListener] jdbcConnectionAcquisitionEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,507 INFO  [default task-64]-[SessionEventListener] jdbcPrepareStatementEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,507 INFO  [default task-64]-[SessionEventListener] jdbcExecuteStatementStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcExecuteStatementEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcConnectionReleaseStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcConnectionReleaseEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcPrepareStatementStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcConnectionAcquisitionStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcConnectionAcquisitionEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcPrepareStatementEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcExecuteStatementStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,494 INFO  [default task-64]-[SessionEventListener] jdbcExecuteStatementEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,495 INFO  [default task-64]-[SessionEventListener] jdbcConnectionReleaseStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,495 INFO  [default task-64]-[SessionEventListener] jdbcConnectionReleaseEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,495 INFO  [default task-64]-[SessionEventListener] flushStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,536 INFO  [default task-64]-[SessionEventListener] dirtyCalculationStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,536 INFO  [default task-64]-[SessionEventListener] dirtyCalculationEnd false com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,536 INFO  [default task-64]-[SessionEventListener] partialFlushStart 1;0;com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,538 INFO  [default task-64]-[SessionEventListener] Tx completed truefor entity com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,538 INFO  [default task-64]-[SessionEventListener] END com.myorg.model.Notification@482bb8c8

Для записи я перенес свое приложение из Hibernate 4.x, в котором мы не сталкивались с такими проблемами.В общем, я заметил, что Hibernate 5.2 ведет себя очень странно с вложенными транзакциями, которые требуют приостановки родительских транзакций.Я в значительной степени озадачен: /

Обновление

Я решил сделать дамп потока, пока поток завис, и я заметил, что на самом деле утверждение передано MariaDBдля выполнения, и на самом деле SHOW PROCESSLIST перечислил зависший оператор обновления.Стек потока, пока Java ожидала завершения выполнения оператора -

java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
        - locked <0x0000000699da2af0> (a java.io.BufferedInputStream)
        at org.mariadb.jdbc.internal.common.packet.buffer.ReadUtil.readFully(ReadUtil.java:82)
        at org.mariadb.jdbc.internal.common.packet.buffer.ReadUtil.readFully(ReadUtil.java:92)
        at org.mariadb.jdbc.internal.common.packet.RawPacket.nextPacket(RawPacket.java:77)
        at org.mariadb.jdbc.internal.common.packet.SyncPacketFetcher.getRawPacket(SyncPacketFetcher.java:67)
        at org.mariadb.jdbc.internal.mysql.MySQLProtocol.getResult(MySQLProtocol.java:957)
        at org.mariadb.jdbc.internal.mysql.MySQLProtocol.executeQuery(MySQLProtocol.java:1066)
        at org.mariadb.jdbc.internal.mysql.MySQLProtocol.executeQuery(MySQLProtocol.java:1046)
        at org.mariadb.jdbc.MySQLStatement.execute(MySQLStatement.java:289)
        - locked <0x0000000699da2b18> (a org.mariadb.jdbc.internal.mysql.MySQLProtocol)
        at org.mariadb.jdbc.MySQLStatement.executeUpdate(MySQLStatement.java:364)
        at org.mariadb.jdbc.MySQLPreparedStatement.executeUpdate(MySQLPreparedStatement.java:148)
        at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:537)
        at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:175)
        at org.hibernate.dialect.identity.GetGeneratedKeysDelegate.executeAndExtract(GetGeneratedKeysDelegate.java:57)

Answer 1

Наконец-то я понял!Это был тупик из-за обновлений на связанных таблицах.В таблице присутствовало следующее отношение:

Notification *<-->* Sources

И источник был обновлен до того, как была запущена дочерняя транзакция.

После того, как был подтвержден запрос, который был отправлен в MySQL, но былне выполняясь, я удостоверился, что это не был неисправный драйвер JDBC, обновив драйвер, но проблема осталась.

Итак, наконец, проверка журналов MySQL SHOW INNODB ENGINE STATUS TRANSACTION помогла в пониманиипричина «тупика» -

---TRANSACTION 2735824, ACTIVE 104 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1
MySQL thread id 59, OS thread handle 0x7f72d8fb4b00, query id 47941 localhost 127.0.0.1 amsadminusr update
insert into Notification (id, sourceId, message) values (NULL, 17, 'MISSING')
Trx #rec lock waits 1 #table lock waits 0
Trx total rec lock wait time 0 SEC
Trx total table lock wait time 0 SEC
------- TRX HAS BEEN WAITING 104 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 2726 page no 3 n bits 104 index `PRIMARY` of table `emlplatform`.`Sources` trx table locks 3 total table locks 2  trx id 2735824 lock mode S locks rec but not gap waiting lock hold time 104 wait time before grant 0 
------------------
---TRANSACTION 2735810, ACTIVE 104 sec
5 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 2
MySQL thread id 60, OS thread handle 0x7f72d83feb00, query id 47927 localhost 127.0.0.1 amsadminusr cleaning up
Trx #rec lock waits 0 #table lock waits 0
Trx total rec lock wait time 0 SEC
Trx total table lock wait time 0 SEC

• TRANSACTION 2735810 содержит блокировку строки таблицы Sources, поскольку она «сохранена» в родительской транзакции.
• TRANSACTION 2735824 теперь ожидает этого замка.Причина в том, что один из столбцов в таблице уведомлений определяет внешний ключ к источникам table.Так что, очевидно, поскольку строка заблокирована, дочерняя транзакция вошла в тупик.

Блог Влада объясняет это - https://vladmihalcea.com/how-does-database-pessimistic-locking-interact-with-insert-update-and-delete-sql-statements/

Здесь важно отметить, чтообъект Notification не определил отношение Hibernate к объекту Sources, и ограничение присутствует только в базе данных MySQL.

Итак, я решил обновить сущность родительского Sources после завершения дочерней транзакции, чтобы избежать блокировки родительской таблицы.

Интересно, была ли определена связь, Hibernate будетотносились к этому по-разному.