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)hibernate.connection.handling_mode 和 REQUIRES_NEW 事务（Hibernate 5.2+Spring 4.3）
【发布时间】：2018-09-24 18:34:09
【问题描述】：

当我设置 hibernate.connection.handling_mode 和不设置它时，我注意到 JPA/JTA 应用程序中的行为非常不同。我定义了以下实体 - 

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

    ....
}

而我的hiberate属性设置如下——

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

【问题讨论】：

  • 你已经问过弗拉德，他告诉了你接下来要做什么。所以只有 Hibernate 的人才能真正帮助你。
  • 是的，确实问过 Vlad - 但他怀疑 Spring 引起了问题。有什么想法吗？
  • 为什么需要 DELAYED_ACQUISITION_AND_RELEASE_AFTER_STATEMENT？
  • 因为我不想在整个事务结束之前保持连接。顺便说一句，我做了进一步的调试，并注意到插入查询在发送到 MariaDB 后只是阻塞，即 org.hibernate.dialect.identity.GetGeneratedKeysDelegate.executeAndExtract(PreparedStatement insert, SharedSessionContractImplementor session) 中的第一行。我怀疑是表锁，但是当这个查询被执行时，这是唯一一个在表上持有 WRITE 锁的连接。

标签： spring hibernate jpa jta hibernate-5.x


【解决方案1】：

终于解决了！由于相关表的更新，这是一个死锁。桌子上存在以下关系-

Notification *<-->* Sources

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

在确定查询被提交到 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 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 表的行锁，因为它已“保存”在父事务中。
  • 事务 2735824 现在正在等待此锁。原因是通知表中的一列定义了 Sources table 的外键。因此，显然，由于该行已被锁定，因此子事务已进​​入死锁状态。

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

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

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

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

【讨论】：

    猜你喜欢
    • 1970-01-01
    • 1970-01-01
    • 2012-10-14
    • 2012-09-10
    • 2018-11-27
    • 2011-06-13
    • 2017-11-21
    • 2012-09-05
    • 1970-01-01
    相关资源
    最近更新 更多
    热门标签
    Java Python linux javascript Mysql C# Docker 算法 前端 SpringBoot Redis Vue spring 设计模式 .net core .net kubernetes c++ 数据库 数据结构 大数据 js 机器学习 微服务 Android Go 程序员 面试 JVM ASP.net core 云原生 人工智能 后端 PHP git CSS golang k8s Nginx Django mybatis 深度学习 多线程 React 架构 devops 爬虫 云计算 Spring Boot LeetCode