Does lazy load work in Hibernate 3.2.4?

I wrote a little test to try to help myself understand how Hibernate lazy load works. In my test environment, I have two entities: removal order and removal candidate. There is a one-to-many relationship between removal order and removal candidates. One removal order may contain multiple removal candidates.

Then I wrote a simple test. The test code simply loads a couple of removal orders by using order ids. Since the collection is configured as lazy-load collection, I expect that no removal candidates will be loaded by Hibernate. Therefore, upon the exit of my test problem, there should be only two removal order objects in Hibernate cache.

But I was wrong. The log file shows that Hibernate loads removal candidates into memory too. When looked at the log message closely, I noticed that Hibernate loaded removal candidates during dirty check.

This is a huge problem for me. Because in my environment, one removal order may contain 1M removal candidates. Suppose each removal candidate object takes 15K bytes, it will take 15G bytes to load all removal candidates into memory. I cannot afford it. Is there anyway to avoid the loading of removal candidates?

Another question is: it looks weird to me that Hibernate tried to load all removal candidates. What my test code did is just search a couple of removal orders. Why did Hibernate load removal candidates?

Really appreciate if someone can shed light on this issue. thanks.

Hibernate version:
Hibernate 3.2.4;

Mapping documents:
These are simplified map files.

There are two entities in my environment: RemovalOrder and RemovalCandidate. This is a one-to-many relationship between removal order and removal candidate. One removal order may contain multiple removal candidates. The collection is configured as a lazy-load collection.

<class name="com.ihr.hibernate.model.RemovalOrder" table="REMOVAL_ORDERS">
<bag name="removal_candidates" lazy="extra" inverse="true">
<key> <column name="removal_order_id" /> </key>
<one-to-many class="com.ihr.hibernate.model.RemovalCandidate"/>
</bag>
</class>

<class name="com.ihr.hibernate.model.RemovalCandidate" table="REMOVAL_CANDIDATES">
<many-to-one name="removal_order" class="com.ihr.hibernate.model.RemovalOrder" not-null="false">
</class>


Code between sessionFactory.openSession() and session.close():

/**
* This code simply loads a couple of removal orders by their ids.
*
* Each removal order contains a collection of removal candidates. Since
* the collection is a configured as a lazy-load collection, I except that
* no removal candidates will be loaded into memory by Hibernate. In
* other words, upon the exit of the code, I expect to see only two
* removal order objects hydrated by Hibernate.
*
* However, log file shows that Hibernate loads all removal candidate
* collections in memory during dirty check.
*/
private void findByIds() throws Exception {
Long[] ids = new Long[2];
ids[0] = Long.valueOf("4153148662");
ids[1] = Long.valueOf("4155015682");

int lineNo = 0;
while (lineNo <ids.length) {
RemovalCandidateDAO rcDAO = new RemovalCandidateDAO();

Long id = ids[lineNo];
log.warn(">>> ! loading candidates by " + id);
printHibernateStatistics();

RemovalCandidateProxy cand = rcDAO.findById(id);

log.warn(">>> loaded " + cand);
printHibernateStatistics();

lineNo++;
}
}

Name and version of the database you are using:
Oracle 9.2.0.5

Debug level Hibernate log excerpt:

Here is the annotated log file. Important parts are highlighted in blue. My comments and questions are surrounded by [[[ and ]]].

587 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - >>> ! loading order by 161253162
[[[ We are about to load the first removal order. ]]]


6401 [main] DEBUG org.hibernate.impl.SessionFactoryImpl - instantiated session factory
6401 [main] DEBUG org.hibernate.impl.SessionFactoryImpl - Checking 0 named HQL queries
6401 [main] DEBUG org.hibernate.impl.SessionFactoryImpl - Checking 0 named SQL queries
6401 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====JVM has free memory:5905272
6402 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====hibernate load count: 0
6403 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====hibernate loaded removal order: 0
6403 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====hibernate loaded removal candidate: 0
[[[ Obviously, this is a new clean hibernate session. ]]]

6440 [main] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 12257312510
6440 [main] DEBUG com.amazon.ihr.hibernate.util.HibernateSession - Created brand new Session for IhrDb SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[]])
6440 [main] DEBUG org.hibernate.impl.SessionImpl - checking session dirtiness
6441 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - flushing session
6441 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - processing flush-time cascades
6441 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - dirty checking collections
6441 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushing entities and processing referenced collections
6441 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Processing unreferenced collections
6441 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Scheduling collection removes/(re)creates/updates
6441 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
6442 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
6447 [main] DEBUG org.hibernate.event.def.DefaultDirtyCheckEventListener - session not dirty
6450 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener - loading entity: [com.amazon.ihr.hibernate.model.RemovalOrder#161253162]

<<< Here hibernate loads the first removal order. >>>

11048 [main] DEBUG org.hibernate.loader.Loader - total objects hydrated: 1
[[[ OK. The removal order has been loaded ]]]


11048 [main] DEBUG org.hibernate.engine.TwoPhaseLoad - resolving associations for [com.amazon.ihr.hibernate.model.RemovalOrder#161253162]
11051 [main] DEBUG org.hibernate.engine.loading.LoadContexts - creating collection wrapper:[com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161253162]
11058 [main] DEBUG org.hibernate.engine.loading.LoadContexts - creating collection wrapper:[com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns#161253162]
11060 [main] DEBUG org.hibernate.engine.TwoPhaseLoad - done materializing entity [com.amazon.ihr.hibernate.model.RemovalOrder#161253162]
11060 [main] DEBUG org.hibernate.engine.StatefulPersistenceContext - initializing non-lazy collections
[[[ What is this? What does this non-lazy collection initialization do? Why does hibernate think the collection is non-lazy? ]]]


11060 [main] DEBUG org.hibernate.loader.Loader - done entity load
11083 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - >>> loaded (161253162|Defective|Amazon.JP|Excluded|gl_book|NRT1|1|null|null|none|Destroy Liquidate|0)
11083 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====JVM has free memory:13761152
11083 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====hibernate load count: 1
11083 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====hibernate loaded removal order: 1
11083 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====hibernate loaded removal candidate: 0
[[[OK. The first Removal Order object has been completed loaded. I noticed that no removal candidates were loaded. This is good. It means that our lazy configuration works. So far so good.]]]


11083 [main] DEBUG org.hibernate.impl.SessionImpl - checking session dirtiness
[[[Here comes the problem. In order to check dirtiness, Hibernate will try to load all removal candidates in memory. This is something I try to avoid. Why check dirtiness? There is no change at all.]]]


11083 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - flushing session
11084 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - processing flush-time cascades
11086 [main] DEBUG org.hibernate.engine.Cascade - processing cascade ACTION_SAVE_UPDATE for: com.amazon.ihr.hibernate.model.RemovalOrder
11086 [main] DEBUG org.hibernate.engine.Cascade - cascade ACTION_SAVE_UPDATE for collection: com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns
11086 [main] DEBUG org.hibernate.engine.Cascade - done cascade ACTION_SAVE_UPDATE for collection: com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns
11086 [main] DEBUG org.hibernate.engine.Cascade - done processing cascade ACTION_SAVE_UPDATE for: com.amazon.ihr.hibernate.model.RemovalOrder
11087 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - dirty checking collections
11087 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushing entities and processing referenced collections
[[[Why flushing the entities? Is it because by default Hibernate will do a flush before running a query? ]]]


11089 [main] DEBUG org.hibernate.event.def.DefaultInitializeCollectionEventListener - initializing collection [com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161253162]
11089 [main] DEBUG org.hibernate.event.def.DefaultInitializeCollectionEventListener - checking second-level cache
11089 [main] DEBUG org.hibernate.event.def.DefaultInitializeCollectionEventListener - collection not cached
11089 [main] DEBUG org.hibernate.loader.Loader - loading collection: [com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161253162]
11089 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)

11089 [main] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
<<< Evil. Here, Hibernate loads all removal candidates that belong to the order. This is a huge problem. Can we avoid it? >>>


11170 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext - ending loading collection [org.hibernate.engine.loading.LoadingCollectionEntry<rs=com.mchange.v2.c3p0.impl.NewProxyResultSet@16274ea, coll=[com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161253162]>@1d59ff0]
11170 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext - collection fully initialized: [com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161253162]
11171 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext - 1 collections initialized for role: com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates
11171 [main] DEBUG org.hibernate.engine.StatefulPersistenceContext - initializing non-lazy collections
[[[ Again, why does hibernate think the collection is non-lazy?]]]

11171 [main] DEBUG org.hibernate.loader.Loader - done loading collection
11171 [main] DEBUG org.hibernate.event.def.DefaultInitializeCollectionEventListener - collection initialized
11185 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister - com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates is dirty
11196 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 insertions, 1 updates, 0 deletions to 2 objects
11197 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 1 (re)creations, 0 updates, 1 removals to 3 collections

11200 [main] DEBUG org.hibernate.event.def.DefaultEvictEventListener - evicting [com.amazon.ihr.hibernate.model.RemovalOrder]
11202 [main] DEBUG org.hibernate.event.def.EvictVisitor - evicting collection: [com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns#161253162]
11202 [main] DEBUG org.hibernate.engine.Cascade - processing cascade ACTION_EVICT for: com.amazon.ihr.hibernate.model.RemovalOrder
11202 [main] DEBUG org.hibernate.engine.Cascade - cascade ACTION_EVICT for collection: com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns
11202 [main] DEBUG org.hibernate.engine.Cascade - done cascade ACTION_EVICT for collection: com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns
11202 [main] DEBUG org.hibernate.engine.Cascade - done processing cascade ACTION_EVICT for: com.amazon.ihr.hibernate.model.RemovalOrder

11204 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - >>> ! loading order by 161170052
11204 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====JVM has free memory:12515112
11204 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====hibernate load count: 2
11204 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====hibernate loaded removal order: 1
11204 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====hibernate loaded removal candidate: 1
[[[ Now we are about to load the second removal order. Right now, hibernate has one removal order and one removal candidate in memory. ]]]

11204 [main] DEBUG org.hibernate.impl.SessionImpl - checking session dirtiness
11204 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - flushing session
11204 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - processing flush-time cascades
11204 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - dirty checking collections
11204 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushing entities and processing referenced collections

11205 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Processing unreferenced collections
11205 [main] DEBUG org.hibernate.engine.Collections - Collection dereferenced: [com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161253162]
11205 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Scheduling collection removes/(re)creates/updates
11205 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
11205 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 1 removals to 2 collections
11205 [main] DEBUG org.hibernate.event.def.DefaultDirtyCheckEventListener - session dirty
[[[ This is weird. Why does hibernate think the session is dirty? I didn't make any change. ]]]


11211 [main] DEBUG org.hibernate.impl.SessionImpl - after transaction completion
11212 [main] DEBUG org.hibernate.impl.SessionImpl - initializing proxy: [com.amazon.ihr.hibernate.model.RemovalOrder#161170052]
11212 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener - attempting to resolve: [com.amazon.ihr.hibernate.model.RemovalOrder#161170052]
11212 [main] DEBUG org.hibernate.event.def.DefaultLoadEventListener - object not resolved in any cache: [com.amazon.ihr.hibernate.model.RemovalOrder#161170052]
11212 [main] DEBUG org.hibernate.persister.entity.AbstractEntityPersister - Fetching entity: [com.amazon.ihr.hibernate.model.RemovalOrder#161170052]
11212 [main] DEBUG org.hibernate.loader.Loader - loading entity: [com.amazon.ihr.hibernate.model.RemovalOrder#161170052]
11212 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
11212 [main] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection

<<< Here, Hibernate loads the second removal order. >>>

11228 [main] DEBUG org.hibernate.loader.Loader - total objects hydrated: 1
11228 [main] DEBUG org.hibernate.engine.TwoPhaseLoad - resolving associations for [com.amazon.ihr.hibernate.model.RemovalOrder#161170052]
11229 [main] DEBUG org.hibernate.engine.loading.LoadContexts - attempting to locate loading collection entry [CollectionKey[com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161170052]] in any result-set context
11229 [main] DEBUG org.hibernate.engine.loading.LoadContexts - collection [CollectionKey[com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161170052]] located in load context
11229 [main] DEBUG org.hibernate.engine.loading.LoadContexts - creating collection wrapper:[com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161170052]
11229 [main] DEBUG org.hibernate.engine.loading.LoadContexts - attempting to locate loading collection entry [CollectionKey[com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns#161170052]] in any result-set context
11229 [main] DEBUG org.hibernate.engine.loading.LoadContexts - collection [CollectionKey[com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns#161170052]] located in load context
11229 [main] DEBUG org.hibernate.engine.loading.LoadContexts - creating collection wrapper:[com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns#161170052]
11229 [main] DEBUG org.hibernate.engine.TwoPhaseLoad - done materializing entity [com.amazon.ihr.hibernate.model.RemovalOrder#161170052]
11229 [main] DEBUG org.hibernate.engine.StatefulPersistenceContext - initializing non-lazy collections
11229 [main] DEBUG org.hibernate.loader.Loader - done entity load
11229 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - >>> loaded (161170052|Defective|Amazon.JP|Prepared|gl_book|NRT1|3|null|null|MDLJM|Return|12072)
11229 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====JVM has free memory:14338128
11229 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====hibernate load count: 3
11229 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====hibernate loaded removal order: 2
11229 [main] WARN com.amazon.ihr.hibernate.util.TestUtil - ====hibernate loaded removal candidate: 1

11229 [main] DEBUG org.hibernate.impl.SessionImpl - checking session dirtiness
11229 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - flushing session
11229 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - processing flush-time cascades
11230 [main] DEBUG org.hibernate.engine.Cascade - processing cascade ACTION_SAVE_UPDATE for: com.amazon.ihr.hibernate.model.RemovalOrder
11230 [main] DEBUG org.hibernate.engine.Cascade - cascade ACTION_SAVE_UPDATE for collection: com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns
11230 [main] DEBUG org.hibernate.engine.Cascade - done cascade ACTION_SAVE_UPDATE for collection: com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns
11230 [main] DEBUG org.hibernate.engine.Cascade - done processing cascade ACTION_SAVE_UPDATE for: com.amazon.ihr.hibernate.model.RemovalOrder
11230 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - dirty checking collections
[[[ OK. The problem comes again. Hibernate is about to check the dirtiness of the entity. But in order to do the dirtiness check, it will load all removal candidates.]]]


11230 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushing entities and processing referenced collections
11230 [main] DEBUG org.hibernate.event.def.DefaultInitializeCollectionEventListener - initializing collection [com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161170052]
11230 [main] DEBUG org.hibernate.event.def.DefaultInitializeCollectionEventListener - checking second-level cache
11230 [main] DEBUG org.hibernate.event.def.DefaultInitializeCollectionEventListener - collection not cached
11230 [main] DEBUG org.hibernate.loader.Loader - loading collection: [com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161170052]
11230 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
11230 [main] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection

<<< Here, Hibernate Loads all removal candidates for the second order >>>


11247 [main] DEBUG org.hibernate.loader.Loader - total objects hydrated: 3
11248 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext - ending loading collection [org.hibernate.engine.loading.LoadingCollectionEntry<rs=com.mchange.v2.c3p0.impl.NewProxyResultSet@1deda00, coll=[com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161170052]>@eab1f2]
11248 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext - collection fully initialized: [com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates#161170052]
11248 [main] DEBUG org.hibernate.engine.loading.CollectionLoadContext - 1 collections initialized for role: com.amazon.ihr.hibernate.model.RemovalOrder.removal_candidates
11248 [main] DEBUG org.hibernate.engine.StatefulPersistenceContext - initializing non-lazy collections
11248 [main] DEBUG org.hibernate.loader.Loader - done loading collection
11248 [main] DEBUG org.hibernate.event.def.DefaultInitializeCollectionEventListener - collection initialized
11252 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 insertions, 1 updates, 0 deletions to 5 objects
11252 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 1 (re)creations, 0 updates, 2 removals to 5 collections

11262 [main] DEBUG org.hibernate.event.def.DefaultDirtyCheckEventListener - session dirty
[[[ Again, why the session is dirty? We just did a couple of queires. ]]]


11263 [main] DEBUG org.hibernate.event.def.EvictVisitor - evicting collection: [com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns#161170052]
11263 [main] DEBUG org.hibernate.engine.Cascade - processing cascade ACTION_EVICT for: com.amazon.ihr.hibernate.model.RemovalOrder
11263 [main] DEBUG org.hibernate.engine.Cascade - cascade ACTION_EVICT for collection: com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns
11263 [main] DEBUG org.hibernate.engine.Cascade - done cascade ACTION_EVICT for collection: com.amazon.ihr.hibernate.model.RemovalOrder.distributor_returns
11263 [main] DEBUG org.hibernate.engine.Cascade - done processing cascade ACTION_EVICT for: com.amazon.ihr.hibernate.model.RemovalOrder 11263 [main] WARN

I'll try to answer some of your questions.



As you noticed just a few lines later no collections was loaded. But if you have any non-lazy collections in your entity, this is the place were they should have been initialized.



But Hibernate doesn't know that without the checking it.



Probably. Are you doing a query? It is not in the code you posted. You should be able to change this by setting Session.setFlushMode(). The default setting can kill performance if you do a lot of queries in a session with a lot of objects loaded.



This may indicate some kind of problem. Are your RemovalOrder.getRemovalCandiates() method returning the very same object that was passed to RemovalOrder.setRemovalCandidates()? Can you post the code in your RemovaOrder and RemovalCandidate classes?

Suppose I just want to search for a few removal orders. Is there a way to avoid the loading of the collection?

It seems that this is not the hibernate normal behavior. Something is not set properly in the test environment. I have the same problem, but I can't find any solution.

viewtopic.php?f=1&t=997113
viewtopic.php?f=1&t=995960
viewtopic.php?f=1&t=983747