Hibernate 在 JTA 事务期间从池中获取多个 JDBC 连接
Hibernate obtains multiple JDBC Connections from the pool during a JTA transaction
我正在努力将一个项目从 BC4J 迁移到 JPA + Hibernate。
刚刚开始，我们迁移了一个范围有限的实体，并且发生了意外行为。
作为使用本机查询查询实体，hibernate 首先检查ehcache 以查看查询是否存在，如果不存在，则执行查询。
DEBUG 2015-01-28 13:23:19,465 AbstractEntityManagerImpl: Looking for a JTA transaction to join
DEBUG 2015-01-28 13:23:19,465 AbstractEntityManagerImpl: No JTA transaction found
DEBUG 2015-01-28 13:23:19,466 StandardQueryCache: checking cached query results in region: org.hibernate.cache.StandardQueryCache
DEBUG 2015-01-28 13:23:19,466 EhcacheGeneralDataRegion: key: sql: select linearepro0_.C_ID as C1_215_, linearepro0_.C_ID_ACCION as C2_215_, linearepro0_.C_LINEA_OBS as C3_215_, linearepro0_.C_LINEA_REPROCESO as C4_215_ from PISOPLTA.LNA_LINEA_REPROCESO linearepro0_ where (linearepro0_.C_LINEA_OBS=? ); parameters: DEC3_CHU, ; named parameters: {}
DEBUG 2015-01-28 13:23:19,466 Cache: Cache: org.hibernate.cache.StandardQueryCache store hit for sql: select linearepro0_.C_ID as C1_215_, linearepro0_.C_ID_ACCION as C2_215_, linearepro0_.C_LINEA_OBS as C3_215_, linearepro0_.C_LINEA_REPROCESO as C4_215_ from PISOPLTA.LNA_LINEA_REPROCESO linearepro0_ where (linearepro0_.C_LINEA_OBS=? ); parameters: DEC3_CHU, ; named parameters: {}
DEBUG 2015-01-28 13:23:19,466 StandardQueryCache: Checking query spaces for up-to-dateness: [PISOPLTA.LNA_LINEA_REPROCESO]
DEBUG 2015-01-28 13:23:19,467 EhcacheGeneralDataRegion: key: PISOPLTA.LNA_LINEA_REPROCESO
DEBUG 2015-01-28 13:23:19,467 Cache: org.hibernate.cache.UpdateTimestampsCache cache - Miss
DEBUG 2015-01-28 13:23:19,467 EhcacheGeneralDataRegion: Element for key PISOPLTA.LNA_LINEA_REPROCESO is null
DEBUG 2015-01-28 13:23:19,467 StandardQueryCache: returning cached query results
DEBUG 2015-01-28 13:23:19,467 Loader: loading entity: [com.business.entity.jpa.LineaReproceso#1906]
在那之后，似乎 hiberate 正在为查询返回的每个实体进入数据库以填充它。
DEBUG 2015-01-28 13:23:19,467 Loader: loading entity: [com.business.entity.jpa.LineaReproceso#1906]
DEBUG 2015-01-28 13:23:19,468 AbstractBatcher: about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG 2015-01-28 13:23:19,468 ConnectionManager: opening JDBC connection
DEBUG 2015-01-28 13:23:19,468 SQL: select linearepro0_.C_ID as C1_215_0_, linearepro0_.C_ID_ACCION as C2_215_0_, linearepro0_.C_LINEA_OBS as C3_215_0_, linearepro0_.C_LINEA_REPROCESO as C4_215_0_ from PISOPLTA.LNA_LINEA_REPROCESO linearepro0_ where linearepro0_.C_ID=?
DEBUG 2015-01-28 13:23:19,471 AbstractBatcher: about to open ResultSet (open ResultSets: 0, globally: 0)
DEBUG 2015-01-28 13:23:19,471 Loader: result row: EntityKey[com.business.entity.jpa.LineaReproceso#1906]
DEBUG 2015-01-28 13:23:19,471 AbstractBatcher: about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG 2015-01-28 13:23:19,471 AbstractBatcher: about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG 2015-01-28 13:23:19,471 ConnectionManager: aggressively releasing JDBC connection
DEBUG 2015-01-28 13:23:19,472 ConnectionManager: releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
DEBUG 2015-01-28 13:23:19,472 TwoPhaseLoad: resolving associations for [com.business.entity.jpa.LineaReproceso#1906]
DEBUG 2015-01-28 13:23:19,472 TwoPhaseLoad: adding entity to second-level cache: [com.business.entity.jpa.LineaReproceso#1906]
DEBUG 2015-01-28 13:23:19,473 TwoPhaseLoad: done materializing entity [com.business.entity.jpa.LineaReproceso#1906]
DEBUG 2015-01-28 13:23:19,473 StatefulPersistenceContext: initializing non-lazy collections
DEBUG 2015-01-28 13:23:19,473 Loader: done entity load
DEBUG 2015-01-28 13:23:19,474 Loader: loading entity: [com.business.entity.jpa.LineaReproceso#2659]
DEBUG 2015-01-28 13:23:19,474 AbstractBatcher: about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG 2015-01-28 13:23:19,474 ConnectionManager: opening JDBC connection
DEBUG 2015-01-28 13:23:19,474 SQL: select linearepro0_.C_ID as C1_215_0_, linearepro0_.C_ID_ACCION as C2_215_0_, linearepro0_.C_LINEA_OBS as C3_215_0_, linearepro0_.C_LINEA_REPROCESO as C4_215_0_ from PISOPLTA.LNA_LINEA_REPROCESO linearepro0_ where linearepro0_.C_ID=?
DEBUG 2015-01-28 13:23:19,477 AbstractBatcher: about to open ResultSet (open ResultSets: 0, globally: 0)
DEBUG 2015-01-28 13:23:19,477 Loader: result row: EntityKey[com.business.entity.jpa.LineaReproceso#2659]
DEBUG 2015-01-28 13:23:19,477 AbstractBatcher: about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG 2015-01-28 13:23:19,477 AbstractBatcher: about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG 2015-01-28 13:23:19,477 ConnectionManager: aggressively releasing JDBC connection
DEBUG 2015-01-28 13:23:19,477 ConnectionManager: releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
DEBUG 2015-01-28 13:23:19,478 TwoPhaseLoad: resolving associations for [com.business.entity.jpa.LineaReproceso#2659]
DEBUG 2015-01-28 13:23:19,478 TwoPhaseLoad: adding entity to second-level cache: [com.business.entity.jpa.LineaReproceso#2659]
DEBUG 2015-01-28 13:23:19,479 TwoPhaseLoad: done materializing entity [com.business.entity.jpa.LineaReproceso#2659]
DEBUG 2015-01-28 13:23:19,479 StatefulPersistenceContext: initializing non-lazy collections
DEBUG 2015-01-28 13:23:19,479 Loader: done entity load
最糟糕的是，似乎每次打开和释放一个 JDBC 连接。以下日志正在重复多次。
DEBUG 2015-01-28 13:23:19,474 ConnectionManager: opening JDBC connection
DEBUG 2015-01-28 13:23:19,474 SQL: select linearepro0_.C_ID as C1_215_0_, linearepro0_.C_ID_ACCION as C2_215_0_, linearepro0_.C_LINEA_OBS as C3_215_0_, linearepro0_.C_LINEA_REPROCESO as C4_215_0_ from PISOPLTA.LNA_LINEA_REPROCESO linearepro0_ where linearepro0_.C_ID=?
DEBUG 2015-01-28 13:23:19,477 AbstractBatcher: about to open ResultSet (open ResultSets: 0, globally: 0)
DEBUG 2015-01-28 13:23:19,477 Loader: result row: EntityKey[com.business.entity.jpa.LineaReproceso#2659]
DEBUG 2015-01-28 13:23:19,477 AbstractBatcher: about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG 2015-01-28 13:23:19,477 AbstractBatcher: about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG 2015-01-28 13:23:19,477 ConnectionManager: aggressively releasing JDBC connection
DEBUG 2015-01-28 13:23:19,477 ConnectionManager: releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
知道是什么导致了这种行为吗？
提前致谢。
虽然 JTA 规范没有强制要求在每个语句后释放连接，但 Hibernate 会这样做，因为 some strange behavior in old application servers which led to introducing the AFTER_STATEMENT connection release mode 其行为如下：
The connection is released after each statement execution and
reacquired prior to running the next statement. Although not required
by either JDBC or JTA specifications, this strategy is meant to
prevent application servers from mistakenly detecting a connection
leak between successive EJB (Enterprise Java Beans) calls
所以，这是因为您使用的是 JTA 环境，而不是 RESOURCE_LOCAL 环境。
您可以通过设置以下 Hibernate 属性 来覆盖此行为：
hibernate.connection.release_mode=after_transaction
您应该知道，在每个语句之后释放连接会导致性能下降，因为这是在 after_statement 连接释放模式之后。
我正在努力将一个项目从 BC4J 迁移到 JPA + Hibernate。 刚刚开始，我们迁移了一个范围有限的实体，并且发生了意外行为。
作为使用本机查询查询实体，hibernate 首先检查ehcache 以查看查询是否存在，如果不存在，则执行查询。
DEBUG 2015-01-28 13:23:19,465 AbstractEntityManagerImpl: Looking for a JTA transaction to join
DEBUG 2015-01-28 13:23:19,465 AbstractEntityManagerImpl: No JTA transaction found
DEBUG 2015-01-28 13:23:19,466 StandardQueryCache: checking cached query results in region: org.hibernate.cache.StandardQueryCache
DEBUG 2015-01-28 13:23:19,466 EhcacheGeneralDataRegion: key: sql: select linearepro0_.C_ID as C1_215_, linearepro0_.C_ID_ACCION as C2_215_, linearepro0_.C_LINEA_OBS as C3_215_, linearepro0_.C_LINEA_REPROCESO as C4_215_ from PISOPLTA.LNA_LINEA_REPROCESO linearepro0_ where (linearepro0_.C_LINEA_OBS=? ); parameters: DEC3_CHU, ; named parameters: {}
DEBUG 2015-01-28 13:23:19,466 Cache: Cache: org.hibernate.cache.StandardQueryCache store hit for sql: select linearepro0_.C_ID as C1_215_, linearepro0_.C_ID_ACCION as C2_215_, linearepro0_.C_LINEA_OBS as C3_215_, linearepro0_.C_LINEA_REPROCESO as C4_215_ from PISOPLTA.LNA_LINEA_REPROCESO linearepro0_ where (linearepro0_.C_LINEA_OBS=? ); parameters: DEC3_CHU, ; named parameters: {}
DEBUG 2015-01-28 13:23:19,466 StandardQueryCache: Checking query spaces for up-to-dateness: [PISOPLTA.LNA_LINEA_REPROCESO]
DEBUG 2015-01-28 13:23:19,467 EhcacheGeneralDataRegion: key: PISOPLTA.LNA_LINEA_REPROCESO
DEBUG 2015-01-28 13:23:19,467 Cache: org.hibernate.cache.UpdateTimestampsCache cache - Miss
DEBUG 2015-01-28 13:23:19,467 EhcacheGeneralDataRegion: Element for key PISOPLTA.LNA_LINEA_REPROCESO is null
DEBUG 2015-01-28 13:23:19,467 StandardQueryCache: returning cached query results
DEBUG 2015-01-28 13:23:19,467 Loader: loading entity: [com.business.entity.jpa.LineaReproceso#1906]
在那之后，似乎 hiberate 正在为查询返回的每个实体进入数据库以填充它。
DEBUG 2015-01-28 13:23:19,467 Loader: loading entity: [com.business.entity.jpa.LineaReproceso#1906]
DEBUG 2015-01-28 13:23:19,468 AbstractBatcher: about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG 2015-01-28 13:23:19,468 ConnectionManager: opening JDBC connection
DEBUG 2015-01-28 13:23:19,468 SQL: select linearepro0_.C_ID as C1_215_0_, linearepro0_.C_ID_ACCION as C2_215_0_, linearepro0_.C_LINEA_OBS as C3_215_0_, linearepro0_.C_LINEA_REPROCESO as C4_215_0_ from PISOPLTA.LNA_LINEA_REPROCESO linearepro0_ where linearepro0_.C_ID=?
DEBUG 2015-01-28 13:23:19,471 AbstractBatcher: about to open ResultSet (open ResultSets: 0, globally: 0)
DEBUG 2015-01-28 13:23:19,471 Loader: result row: EntityKey[com.business.entity.jpa.LineaReproceso#1906]
DEBUG 2015-01-28 13:23:19,471 AbstractBatcher: about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG 2015-01-28 13:23:19,471 AbstractBatcher: about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG 2015-01-28 13:23:19,471 ConnectionManager: aggressively releasing JDBC connection
DEBUG 2015-01-28 13:23:19,472 ConnectionManager: releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
DEBUG 2015-01-28 13:23:19,472 TwoPhaseLoad: resolving associations for [com.business.entity.jpa.LineaReproceso#1906]
DEBUG 2015-01-28 13:23:19,472 TwoPhaseLoad: adding entity to second-level cache: [com.business.entity.jpa.LineaReproceso#1906]
DEBUG 2015-01-28 13:23:19,473 TwoPhaseLoad: done materializing entity [com.business.entity.jpa.LineaReproceso#1906]
DEBUG 2015-01-28 13:23:19,473 StatefulPersistenceContext: initializing non-lazy collections
DEBUG 2015-01-28 13:23:19,473 Loader: done entity load
DEBUG 2015-01-28 13:23:19,474 Loader: loading entity: [com.business.entity.jpa.LineaReproceso#2659]
DEBUG 2015-01-28 13:23:19,474 AbstractBatcher: about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG 2015-01-28 13:23:19,474 ConnectionManager: opening JDBC connection
DEBUG 2015-01-28 13:23:19,474 SQL: select linearepro0_.C_ID as C1_215_0_, linearepro0_.C_ID_ACCION as C2_215_0_, linearepro0_.C_LINEA_OBS as C3_215_0_, linearepro0_.C_LINEA_REPROCESO as C4_215_0_ from PISOPLTA.LNA_LINEA_REPROCESO linearepro0_ where linearepro0_.C_ID=?
DEBUG 2015-01-28 13:23:19,477 AbstractBatcher: about to open ResultSet (open ResultSets: 0, globally: 0)
DEBUG 2015-01-28 13:23:19,477 Loader: result row: EntityKey[com.business.entity.jpa.LineaReproceso#2659]
DEBUG 2015-01-28 13:23:19,477 AbstractBatcher: about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG 2015-01-28 13:23:19,477 AbstractBatcher: about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG 2015-01-28 13:23:19,477 ConnectionManager: aggressively releasing JDBC connection
DEBUG 2015-01-28 13:23:19,477 ConnectionManager: releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
DEBUG 2015-01-28 13:23:19,478 TwoPhaseLoad: resolving associations for [com.business.entity.jpa.LineaReproceso#2659]
DEBUG 2015-01-28 13:23:19,478 TwoPhaseLoad: adding entity to second-level cache: [com.business.entity.jpa.LineaReproceso#2659]
DEBUG 2015-01-28 13:23:19,479 TwoPhaseLoad: done materializing entity [com.business.entity.jpa.LineaReproceso#2659]
DEBUG 2015-01-28 13:23:19,479 StatefulPersistenceContext: initializing non-lazy collections
DEBUG 2015-01-28 13:23:19,479 Loader: done entity load
最糟糕的是，似乎每次打开和释放一个 JDBC 连接。以下日志正在重复多次。
DEBUG 2015-01-28 13:23:19,474 ConnectionManager: opening JDBC connection
DEBUG 2015-01-28 13:23:19,474 SQL: select linearepro0_.C_ID as C1_215_0_, linearepro0_.C_ID_ACCION as C2_215_0_, linearepro0_.C_LINEA_OBS as C3_215_0_, linearepro0_.C_LINEA_REPROCESO as C4_215_0_ from PISOPLTA.LNA_LINEA_REPROCESO linearepro0_ where linearepro0_.C_ID=?
DEBUG 2015-01-28 13:23:19,477 AbstractBatcher: about to open ResultSet (open ResultSets: 0, globally: 0)
DEBUG 2015-01-28 13:23:19,477 Loader: result row: EntityKey[com.business.entity.jpa.LineaReproceso#2659]
DEBUG 2015-01-28 13:23:19,477 AbstractBatcher: about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG 2015-01-28 13:23:19,477 AbstractBatcher: about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG 2015-01-28 13:23:19,477 ConnectionManager: aggressively releasing JDBC connection
DEBUG 2015-01-28 13:23:19,477 ConnectionManager: releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
知道是什么导致了这种行为吗？
提前致谢。
虽然 JTA 规范没有强制要求在每个语句后释放连接，但 Hibernate 会这样做，因为 some strange behavior in old application servers which led to introducing the AFTER_STATEMENT connection release mode 其行为如下：
The connection is released after each statement execution and reacquired prior to running the next statement. Although not required by either JDBC or JTA specifications, this strategy is meant to prevent application servers from mistakenly detecting a connection leak between successive EJB (Enterprise Java Beans) calls
所以，这是因为您使用的是 JTA 环境，而不是 RESOURCE_LOCAL 环境。
您可以通过设置以下 Hibernate 属性 来覆盖此行为：
hibernate.connection.release_mode=after_transaction
您应该知道，在每个语句之后释放连接会导致性能下降，因为这是在 after_statement 连接释放模式之后。