I've run into an issue where hibernate flushing strategy experiences slowdowns over time as it processes a set of line items on an order. The slowdowns increase in time when subsequent updates are called to the JBoss Seam update.
The business process of the code takes an order with 'n' line items, modifies each line item for a business purpose, calls a seam/hibernate update() on that line item, and then moves onto the next line item. At the Hibernate flushing strategy responds instantly when the call to update() is made. But as the code makes its way down the list of line items, Hibernate slows down (almost exponentially). With logging enabled, I can see the slowdowns start as seconds, then a minute or two, then 5+ minutes, then 20+ minutes. All processing the same order line items in the collection. It does not change the size of the collection, no items are added or deleted.
I have enabled tracing of hibernate transactions and find in the output that the org.hibernate.event.def.AbstractFlushingEventListener runs into a problem somewhere between a call to:
prepareCollectionFlushes(session);
and
flushEntities(event);
I have traced it to an issue between these two method calls based on the log entries created by Hibernate:
2014-12-02 17:50:30,808 DEBUG [org.hibernate.engine.CollectionEntry] (http-0.0.0.0-8443-2) Collection dirty: [com.companioncabinet.ccs.domain.data.Job.jobPhases#10324859]
2014-12-02 18:19:09,015 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] (http-0.0.0.0-8443-2) Flushing entities and processing referenced collections
Notice the group of messages at 17:50 and then the time gap to 18:19. The code is all in Hibernate's AbstractFlushingEventListner. I have checked the Hibernate sources and found their code looks like this which result in the messages above:
prepareCollectionFlushes(session);
// now, any collections that are initialized
// inside this block do not get updated - they
// are ignored until the next flush
persistenceContext.setFlushing(true);
try {
flushEntities(event);
flushCollections(session);
}
finally {
persistenceContext.setFlushing(false);
}
The messages that appear are coming from:
prepareCollectionFlushes(session);
and
flushingEntities(event);
The method prepareCollectionFlushes makes a call to CollectionEntry.preFlush which produces the "Collection dirty" message.
Here are all the methods involved:
prepareCollectionFlushes
/**
* Initialize the flags of the CollectionEntry, including the
* dirty check.
*/
private void prepareCollectionFlushes(SessionImplementor session) throws HibernateException {
// Initialize dirty flags for arrays + collections with composite elements
// and reset reached, doupdate, etc.
log.debug("dirty checking collections");
final List list = IdentityMap.entries( session.getPersistenceContext().getCollectionEntries() );
final int size = list.size();
for ( int i = 0; i < size; i++ ) {
Map.Entry e = ( Map.Entry ) list.get( i );
( (CollectionEntry) e.getValue() ).preFlush( (PersistentCollection) e.getKey() );
}
}
preFlush
public void preFlush(PersistentCollection collection) throws HibernateException {
boolean nonMutableChange = collection.isDirty() &&
getLoadedPersister()!=null &&
!getLoadedPersister().isMutable();
if (nonMutableChange) {
throw new HibernateException(
"changed an immutable collection instance: " +
MessageHelper.collectionInfoString( getLoadedPersister().getRole(), getLoadedKey() )
);
}
dirty(collection);
if ( log.isDebugEnabled() && collection.isDirty() && getLoadedPersister() != null ) {
log.debug(
"Collection dirty: " +
MessageHelper.collectionInfoString( getLoadedPersister().getRole(), getLoadedKey() )
);
}
setDoupdate(false);
setDoremove(false);
setDorecreate(false);
setReached(false);
setProcessed(false);
}
dirty
/**
* Determine if the collection is "really" dirty, by checking dirtiness
* of the collection elements, if necessary
*/
private void dirty(PersistentCollection collection) throws HibernateException {
boolean forceDirty = collection.wasInitialized() &&
!collection.isDirty() && //optimization
getLoadedPersister() != null &&
getLoadedPersister().isMutable() && //optimization
( collection.isDirectlyAccessible() || getLoadedPersister().getElementType().isMutable() ) && //optimization
!collection.equalsSnapshot( getLoadedPersister() );
if ( forceDirty ) {
collection.dirty();
}
}
The collection.dirty() in the above block sets the PersistenceCollection dirty to true.
flushEntities
/**
* 1. detect any dirty entities
* 2. schedule any entity updates
* 3. search out any reachable collections
*/
private void flushEntities(FlushEvent event) throws HibernateException {
log.trace("Flushing entities and processing referenced collections");
...remainder of code omitted since the delay happens before the above log entry appears
With all the code in hand, there is nothing clear happening. There isn't anything in the code happening during the delay. Everything just appears to stop.
The database is PostgreSQL. I have enabled logging of all queries. When I align the last query to immediately before the delay, it appears to be a reload of all entities that were dirty. When I run the logged select it takes less than 1 mili-second.
I know these are older versions and "upgrade" is something to be done. But still, it would be good to point at a specific flaw, bug, or generally known performance issue as the catalyst to trigger the upgrade.
Thanks for looking!
orm.xml
<persistence-unit-metadata>
<persistence-unit-defaults>
<entity-listeners>
<entity-listener class="org.jboss.seam.security.EntitySecurityListener"/>
</entity-listeners>
</persistence-unit-defaults>
</persistence-unit-metadata>
persistence.xml
<persistence-unit name="DS1" transaction-type="JTA">
<provider>org.hibernate.ejb.HibernatePersistence</provider>
<jta-data-source>java:/DS1</jta-data-source>
<properties>
<property name="hibernate.archive.autodetection" value="class" />
<property name="hibernate.search.default.indexBase" value="/home/lucene/DS1" />
<!-- Binds the EntityManagerFactory to JNDI where Seam can look it up.
This is only relevant when the container automatically loads the persistence unit, as is the case in JBoss AS 5. -->
<property name="jboss.entity.manager.factory.jndi.name" value="java:/DS1EntityManagerFactory"/>
</properties>
</persistence-unit>
hibernate.properties is empty
ds.xml
<local-tx-datasource>
<jndi-name>DS1</jndi-name>
<connection-url>jdbc:postgresql://127.0.0.1:5432/data</connection-url>
<driver-class>org.postgresql.Driver</driver-class>
<user-name>a_user</user-name>
<password>a_pw</password>
<idle-timeout-minutes>90</idle-timeout-minutes>
<new-connection-sql>select 1</new-connection-sql>
<check-valid-connection-sql>select 1</check-valid-connection-sql>
</local-tx-datasource>
DB Log excerpt
2014-12-08 19:43:19 EST LOG: duration: 0.000 ms execute <unnamed>: update PurchaseOrder set active=$1, createdby=$2, createdStamp=$3, ...
2014-12-08 19:43:19 EST LOG: duration: 0.000 ms execute <unnamed>: select orderlines0_.purchaseorderid as purchas66_18_5_, ...
2014-12-08 19:49:29 EST LOG: duration: 0.000 ms execute <unnamed>: update PurchaseOrder set active=$1, createdby=$2, createdStamp=$3, ...
2014-12-08 19:49:29 EST LOG: duration: 0.000 ms execute <unnamed>: select orderlines0_.purchaseorderid as purchas66_18_5_, ...
