we have recently migrated to JBoss 7.1.1 from JBoss 6 and therefore switched from hibernate 3.6.6 to hibernate 4.0.1 and encountered an issue when storing blob data to the database. Persisting a blob of ~80MB took less than 10s with hibernate 3, but with hibernate 4 it takes more than 1 minute to persist it. I have tried several versions of hibernate 4 - 4.0.x,4.1.x,4.2.x and the behaviour is the same.
Environment:
jboss 7.1.1, hibernate 4.0.1, ojdbc6, Oracle DB 11.2.0.3.0 - > 1 min
jboss 6.1.0, hibernate 3.6.6, ojdbc6, Oracle DB 11.2.0.3.0 - ~ 10 sec
I also turned on logging to TRACE level to see where the time is being consumed and found the following:
17:33:58,203 TRACE [org.hibernate.engine.spi.ActionQueue] Adding an EntityInsertAction for [x.x.datastore.persistence.LobDataOutEntity] object
17:33:58,204 TRACE [org.hibernate.engine.spi.ActionQueue] Adding insert with no non-nullable, transient entities: [EntityInsertAction[x.x.datastore.persistence.LobDataOutEntity#2972533]]
17:33:58,205 TRACE [org.hibernate.engine.spi.ActionQueue] Adding resolved non-early insert action.
17:33:58,206 TRACE [org.hibernate.action.internal.UnresolvedEntityInsertActions] No unresolved entity inserts that depended on [[x.x.datastore.persistence.LobDataOutEntity#2972533]]
**17:33:58,206 TRACE [org.hibernate.action.internal.UnresolvedEntityInsertActions] No entity insert actions have non-nullable, transient entity dependencies.
17:34:21,162 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] Flushing session**
17:34:21,163 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] Processing flush-time cascades
17:34:21,163 TRACE [org.hibernate.engine.internal.Cascade] Processing cascade ACTION_PERSIST_ON_FLUSH for: x.x.datastore.persistence.LobDataOutEntity
17:34:21,164 TRACE [org.hibernate.engine.internal.Cascade] Done processing cascade ACTION_PERSIST_ON_FLUSH for: x.x.datastore.persistence.LobDataOutEntity
17:34:21,189 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] Dehydrating entity: [x.x.datastore.persistence.LobDataOutEntity#2972533]
17:34:21,189 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] binding parameter [1] as [BIGINT] - 2972533
17:34:21,190 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] binding parameter [2] as [BLOB] - oracle.sql.BLOB@67c6db48
17:34:48,845 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] binding parameter [3] as [CLOB] - <null>
**17:34:48,846 DEBUG [org.hibernate.engine.jdbc.batch.internal.BatchingBatch] Executing batch size: 1
17:35:21,295 DEBUG [org.hibernate.jdbc.Expectations] Success of batch update unknown: 0**
17:35:21,295 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] Releasing statement [org.jboss.jca.adapters.jdbc.jdk6.WrappedPreparedStatementJDK6@52cc5b6]
17:35:21,296 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] Closing prepared statement [org.jboss.jca.adapters.jdbc.jdk6.WrappedPreparedStatementJDK6@52cc5b6]
17:35:21,297 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] Starting after statement execution processing [AFTER_STATEMENT]
17:35:21,297 DEBUG [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] Skipping aggressive release due to manual disabling
17:35:21,298 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] Starting after statement execution processing [AFTER_STATEMENT]
17:35:21,299 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] Releasing JDBC connection
17:35:21,299 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] Released JDBC connection
17:35:21,300 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] Post flush
From the above tracing logs the time seems to add up when the parameters are being bound to the query and somewhere in the flushing part of the execution. What has changed in hibernate 4 that would cause such delay?
Is there anyone that can give me more insights? Thanks a lot for you help :)
I've added my configuration and source code below.
#persistence.xml
<persistence xmlns="http://java.sun.com/xml/ns/persistence">
<persistence-unit name="DAL-connector-persistence">
<description>Persistence unit for SyncML module</description>
<provider>org.hibernate.ejb.HibernatePersistence</provider>
<jta-data-source>java:jboss/datasources/DS</jta-data-source>
<properties>
<property name="hibernate.dialect" value="org.hibernate.dialect.CustomOracleDialect"/> //the custom dialect is built over Oracle10gDialect
<property name="hibernate.connection.release_mode" value="auto"></property>
<property name="hibernate.transaction.auto_close_session" value="true"></property>
<property name="hibernate.show_sql" value="false"></property>
<property name="hibernate.jdbc.batch_size" value="30"></property>
<property name="hibernate.jdbc.fetch_size" value="30"></property>
<property name="hibernate.cache.use_second_level_cache" value="false"></property>
<property name="hibernate.cache.use_query_cache" value="false"></property>
<property name="hibernate.current_session_context_class" value="jta"></property>
<property name="hibernate.transaction.flush_before_completion" value="true"> </property>
</properties>
</persistence-unit>
#DS definition
<xa-datasource jndi-name="java:jboss/datasources/****DS" pool-name="***LDS" enabled="true" use-java-context="true">
<xa-datasource-property name="URL">jdbc:oracle:thin:@@oracle.ds.ip@:@oracle.ds.sid@</xa-datasource-property>
<xa-datasource-class>oracle.jdbc.xa.client.OracleXADataSource</xa-datasource-class>
<driver>oracle</driver>
<transaction-isolation>TRANSACTION_READ_COMMITTED</transaction-isolation>
<xa-pool>
<min-pool-size>5</min-pool-size>
<max-pool-size>20</max-pool-size>
<prefill>true</prefill>
<is-same-rm-override>false</is-same-rm-override>
</xa-pool>
<security>
<security-domain>***DS-oracle-encrypted-password</security-domain>
</security>
<recovery no-recovery="true"/>
<validation>
<validate-on-match>false</validate-on-match>
<background-validation>true</background-validation>
<exception-sorter class-name="org.jboss.resource.adapter.jdbc.vendor.OracleExceptionSorter"/>
</validation>
<timeout>
<blocking-timeout-millis>5000</blocking-timeout-millis>
<idle-timeout-minutes>2</idle-timeout-minutes>
</timeout>
<statement>
<track-statements>true</track-statements>
<prepared-statement-cache-size>1000</prepared-statement-cache-size>
</statement>
</xa-datasource>
#Java code
//lob initialization
LobDataOutEntity lobEntity = new LobDataOutEntity();
Session session = (Session) manager.getDelegate();
Blob newContent = Hibernate.getLobCreator(session).createBlob(new byte[]{});
lobEntity.setBlobData(newContent);
manager.persist(lobEntity);
//read chunks of bytes and write them into the blob
while (...)
{
lobEntity.getBlobData().setBytes(wrote + 1, b64DataBuf);
}
//merge the content when all bytes have been written into the blob
manager.merge(lobEntity);
