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 来记录会话 activity。我注意到的是，当我有 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:28: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 中我们没有遇到过此类问题。总的来说，我注意到 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

终于解决了！由于相关 table 的更新，这是一个僵局。 table -

上存在以下关系

Notification *<-->* Sources

并且在触发子事务之前更新了源。

在确定查询被提交给 MySQL 但没有被执行后，我通过更新驱动程序确保这不是 JDBC 驱动程序损坏的情况，但是问题仍然存在。

所以，最后检查 MySQL SHOW INNODB ENGINE STATUS TRANSACTION 日志有助于理解 'deadlock' -

背后的原因

---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 adminuser 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 `sample`.`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 adminuser 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 上持有行锁 table 因为它在父事务中 'saved'。
TRANSACTION 2735824 现在正在等待这个锁。原因是通知 table 中的其中一列定义了源 table 的外键。所以，显然，由于行已经被锁定，子事务进入了死锁状态。

Vlad 的博客对此进行了解释 - https://vladmihalcea.com/how-does-database-pessimistic-locking-interact-with-insert-update-and-delete-sql-statements/

这里需要注意的重要一点是 Notification 实体没有定义与 Sources 实体的 Hibernate 关系，并且约束仅存在于 MySQL 数据库中。

因此，我决定在子事务完成后更新父 Sources` 实体，以避免锁定父 table。

我想知道如果关系已经定义，Hibernate 会以不同的方式对待它。

hibernate.connection.handling_mode 和 REQUIRES_NEW 事务（Hibernate 5.2+Spring 4.3）

hibernate.connection.handling_mode and REQUIRES_NEW Transactions (Hibernate 5.2+Spring 4.3)

spring

hibernate

jpa

jta

hibernate-5.x