I´ve working on migrating a project from BC4J to JPA + Hibernate. Just to start, we have migrated one entity with limited scope, and a non-expected behavior has occured.
As querying the entity with a native query, hibernate first checks ehcache to see if the query is there, as it's not, it executes a query.
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]
After that, it seems like hiberate is going to the db for each entity returned by the query to populate it.
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
And the worst is that it seems that each time it´s opening and releasing a JDBC connection. The following log is being repetear SEVERAL times.
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)]
Any idea of what may be causing this behaviour?
Thanks in advance.
Although the JTA specification does not impose to release connections after each statement, Hibernate does that because of some strange behavior in old application servers which led to introducing the AFTER_STATEMENT connection release mode which behaves as follows:
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
So, it happens because you use a JTA environment, as opposed to a RESOURCE_LOCAL one.
You can overwrite this behavior by setting the following Hibernate property:
hibernate.connection.release_mode=after_transaction
You should be aware that there's a performance penalty associated with releasing connections after each statement, as that's after the after_statement connection release mode does.