LazyInitializationError on enabling query cache

binil · **Posted:** Tue Feb 21, 2006 7:07 am

I have two domain objects - Employee and Department - and there is a 1:N relationship from Department to Employee. When I join fetch an Employee with its Department, without query cache enabled, it works fine. If I enable query cache for this same query, it bombs with a LazyInitializationException.
Notes:

We get this error only if query cache is enabled.
We observed the same behaviour on both oscache and ehcache
Calling Hibernate.initialize() explicitly after firing the HQL seems to work. The initialization does not fire and extra query though (it seems to pick it from the cache)

Kindly help.

Hibernate version: 3.0.5

Mapping documents:
Employee.hbm.xml

Code:

<hibernate-mapping>
    <class name="tavant.platform.test.domain.Employee"
        table="CACHE_ISSUE_EMP" lazy="true" proxy="tavant.platform.test.domain.Employee" 
   dynamic-update="true" dynamic-insert="true">

        <cache usage="read-write" />

        <id name="id" column="EMP_ID" type="java.lang.Long" 
       access="field" unsaved-value="null">
            <generator class="increment" />
        </id>
        
        <property name="name" type="string" update="true"
            insert="true" column="EMP_NAME"/>

        <many-to-one name="department" class="tavant.platform.test.domain.Department"
            cascade="none" outer-join="auto" update="true" insert="true" column="DEPARTMENT_ID"/>
    </class>
</hibernate-mapping>

Department.hbm.xml

Code:

<hibernate-mapping>
    <class name="tavant.platform.test.domain.Department" table="CACHE_ISSUE_DEP"
        lazy="true" proxy="tavant.platform.test.domain.Department" 
   dynamic-update="true" dynamic-insert="true">
        
        <cache usage="read-write" />

        <id name="id" column="DEPARTMENT_ID" 
       type="java.lang.Long" access="field">            
       <generator class="increment"/>
        </id>

        <property name="name" type="java.lang.String"
            update="false" insert="true" column="NAME"/>

        <bag name="employees" lazy="true"
            inverse="true" cascade="save-update" access="field">
            <cache usage="read-write"/>

            <key column="DEPARTMENT_ID"/>

            <one-to-many class="tavant.platform.test.domain.Employee"/>
      </bag>
    </class>
</hibernate-mapping>

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

Code:

    public Employee getEmployeeWithDepartment(String empName) {
        Session session = null;
        try {
            session = sessionFactory.openSession();
            Employee emp = (Employee) session.createQuery(
                            "from Employee e join fetch e.department where e.name = :name")
                            .setString("name", empName)
                            .setCacheable(true)
                            .uniqueResult();
            // If I uncomment the next line, this works (even without
            // firing an extra query)!
            // Hibernate.initialize(emp.getDepartment());
            return emp;
        } finally {
            if (session != null) {
                session.close();
            }
        }
    }
        
        // First load employee and populate cahces 
        Employee emp = test.getEmployeeWithDepartment(EMPLOYEE_NAME);
        System.out.println("Employee : " + emp + ", Employee.Department : "
                        + emp.getDepartment());
        
        // Now try to make use of the cache
        emp = test.getEmployeeWithDepartment(EMPLOYEE_NAME);
        System.out.println("Employee : " + emp + ", Employee.Department : "
                        + emp.getDepartment());        

Full stack trace of any exception that occurs:

Code:

   at tavant.platform.test.client.HibernateTest.main(HibernateTest.java:106)
org.hibernate.LazyInitializationException: could not initialize proxy - the owning Session was closed
   at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:53)
   at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:84)
   at org.hibernate.proxy.CGLIBLazyInitializer.intercept(CGLIBLazyInitializer.java:134)
   at tavant.platform.test.domain.Department$$EnhancerByCGLIB$$6ebb5e40.toString(<generated>)
   at java.lang.String.valueOf(String.java:2131)
   at java.lang.StringBuffer.append(StringBuffer.java:370)
   at tavant.platform.test.client.HibernateTest.main(HibernateTest.java:106)

Name and version of the database you are using:
We have noticed this on Oracle and HSQL

The generated SQL (show_sql=true):

Code:

#First read, goes fine
Hibernate: select employee0_.EMP_ID as EMP1_0_, department1_.DEPARTMENT_ID as DEPARTMENT1_1_, employee0_.EMP_NAME as EMP2_1_0_, employee0_.DEPARTMENT_ID as DEPARTMENT3_1_0_, department1_.NAME as NAME0_1_ from CACHE_ISSUE_EMP employee0_ inner join CACHE_ISSUE_DEP department1_ on employee0_.DEPARTMENT_ID=department1_.DEPARTMENT_ID where (employee0_.EMP_NAME=? )

#Prints the Employee and Department fine
Employee : [Id : 1, name : testEmployee], Employee.Department : [Id : 1, name : testDepartment]

#Second read bombs!
org.hibernate.LazyInitializationException: could not initialize proxy - the owning Session was closed
   at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:53)
               [..]

Debug level Hibernate log excerpt:

Code:

#Going to make the first read
[org.hibernate.impl.SessionImpl],opened session at timestamp: 4671568770453509
[org.hibernate.impl.SessionImpl],find: from Employee e join fetch e.department where e.name = :name
[org.hibernate.engine.QueryParameters],named parameters: {name=testEmployee}
[org.hibernate.hql.classic.QueryTranslatorImpl],compiling query
[org.hibernate.cache.StandardQueryCache],checking cached query results in region: org.hibernate.cache.StandardQueryCache
[org.hibernate.cache.EhCache],key: sql: select employee0_.EMP_ID as EMP1_0_, department1_.DEPARTMENT_ID as DEPARTMENT1_1_, employee0_.EMP_NAME as EMP2_1_0_, employee0_.DEPARTMENT_ID as DEPARTMENT3_1_0_, department1_.NAME as NAME0_1_ from CACHE_ISSUE_EMP employee0_ inner join CACHE_ISSUE_DEP department1_ on employee0_.DEPARTMENT_ID=department1_.DEPARTMENT_ID where (employee0_.EMP_NAME=? ); parameters: ; named parameters: {name=testEmployee}
[org.hibernate.cache.EhCache],Element for sql: select employee0_.EMP_ID as EMP1_0_, department1_.DEPARTMENT_ID as DEPARTMENT1_1_, employee0_.EMP_NAME as EMP2_1_0_, employee0_.DEPARTMENT_ID as DEPARTMENT3_1_0_, department1_.NAME as NAME0_1_ from CACHE_ISSUE_EMP employee0_ inner join CACHE_ISSUE_DEP department1_ on employee0_.DEPARTMENT_ID=department1_.DEPARTMENT_ID where (employee0_.EMP_NAME=? ); parameters: ; named parameters: {name=testEmployee} is null
[org.hibernate.cache.StandardQueryCache],query results were not found in cache
[org.hibernate.hql.classic.QueryTranslatorImpl],HQL: from tavant.platform.test.domain.Employee e join fetch e.department where e.name = :name
[org.hibernate.hql.classic.QueryTranslatorImpl],SQL: select employee0_.EMP_ID as EMP1_0_, department1_.DEPARTMENT_ID as DEPARTMENT1_1_, employee0_.EMP_NAME as EMP2_1_0_, employee0_.DEPARTMENT_ID as DEPARTMENT3_1_0_, department1_.NAME as NAME0_1_ from CACHE_ISSUE_EMP employee0_ inner join CACHE_ISSUE_DEP department1_ on employee0_.DEPARTMENT_ID=department1_.DEPARTMENT_ID where (employee0_.EMP_NAME=? )
[org.hibernate.jdbc.AbstractBatcher],about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
[org.hibernate.jdbc.ConnectionManager],opening JDBC connection
[org.hibernate.connection.DriverManagerConnectionProvider],total checked-out connections: 0
[org.hibernate.connection.DriverManagerConnectionProvider],using pooled JDBC connection, pool size: 0
[org.hibernate.SQL],select employee0_.EMP_ID as EMP1_0_, department1_.DEPARTMENT_ID as DEPARTMENT1_1_, employee0_.EMP_NAME as EMP2_1_0_, employee0_.DEPARTMENT_ID as DEPARTMENT3_1_0_, department1_.NAME as NAME0_1_ from CACHE_ISSUE_EMP employee0_ inner join CACHE_ISSUE_DEP department1_ on employee0_.DEPARTMENT_ID=department1_.DEPARTMENT_ID where (employee0_.EMP_NAME=? )
Hibernate: select employee0_.EMP_ID as EMP1_0_, department1_.DEPARTMENT_ID as DEPARTMENT1_1_, employee0_.EMP_NAME as EMP2_1_0_, employee0_.DEPARTMENT_ID as DEPARTMENT3_1_0_, department1_.NAME as NAME0_1_ from CACHE_ISSUE_EMP employee0_ inner join CACHE_ISSUE_DEP department1_ on employee0_.DEPARTMENT_ID=department1_.DEPARTMENT_ID where (employee0_.EMP_NAME=? )
[org.hibernate.jdbc.AbstractBatcher],preparing statement
[org.hibernate.type.StringType],binding 'testEmployee' to parameter: 1
[org.hibernate.jdbc.AbstractBatcher],about to open ResultSet (open ResultSets: 0, globally: 0)
[org.hibernate.loader.Loader],processing result set
[org.hibernate.loader.Loader],result set row: 0
[org.hibernate.type.LongType],returning '1' as column: EMP1_0_
[org.hibernate.type.LongType],returning '1' as column: DEPARTMENT1_1_
[org.hibernate.loader.Loader],result row: EntityKey[tavant.platform.test.domain.Employee#1], EntityKey[tavant.platform.test.domain.Department#1]
[org.hibernate.loader.Loader],Initializing object from ResultSet: [tavant.platform.test.domain.Employee#1]
[org.hibernate.persister.entity.BasicEntityPersister],Hydrating entity: [tavant.platform.test.domain.Employee#1]
[org.hibernate.type.StringType],returning 'testEmployee' as column: EMP2_1_0_
[org.hibernate.type.LongType],returning '1' as column: DEPARTMENT3_1_0_
[org.hibernate.loader.Loader],Initializing object from ResultSet: [tavant.platform.test.domain.Department#1]
[org.hibernate.persister.entity.BasicEntityPersister],Hydrating entity: [tavant.platform.test.domain.Department#1]
[org.hibernate.type.StringType],returning 'testDepartment' as column: NAME0_1_
[org.hibernate.loader.Loader],done processing result set (1 rows)
[org.hibernate.jdbc.AbstractBatcher],about to close ResultSet (open ResultSets: 1, globally: 1)
[org.hibernate.jdbc.AbstractBatcher],about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
[org.hibernate.jdbc.AbstractBatcher],closing statement
[org.hibernate.loader.Loader],total objects hydrated: 2
[org.hibernate.engine.TwoPhaseLoad],resolving associations for [tavant.platform.test.domain.Employee#1]
[org.hibernate.event.def.DefaultLoadEventListener],loading entity: [tavant.platform.test.domain.Department#1]
[org.hibernate.event.def.DefaultLoadEventListener],entity found in session cache
[org.hibernate.engine.TwoPhaseLoad],adding entity to second-level cache: [tavant.platform.test.domain.Employee#1]
[org.hibernate.cache.ReadWriteCache],Caching: tavant.platform.test.domain.Employee#1
[org.hibernate.cache.EhCache],key: tavant.platform.test.domain.Employee#1
[org.hibernate.cache.EhCache],Element for tavant.platform.test.domain.Employee#1 is null
[org.hibernate.cache.ReadWriteCache],Cached: tavant.platform.test.domain.Employee#1
[org.hibernate.engine.TwoPhaseLoad],done materializing entity [tavant.platform.test.domain.Employee#1]
[org.hibernate.engine.TwoPhaseLoad],resolving associations for [tavant.platform.test.domain.Department#1]
[org.hibernate.engine.CollectionLoadContext],creating collection wrapper:[tavant.platform.test.domain.Department.employees#1]
[org.hibernate.engine.TwoPhaseLoad],adding entity to second-level cache: [tavant.platform.test.domain.Department#1]
[org.hibernate.cache.ReadWriteCache],Caching: tavant.platform.test.domain.Department#1
[org.hibernate.cache.EhCache],key: tavant.platform.test.domain.Department#1
[org.hibernate.cache.EhCache],Element for tavant.platform.test.domain.Department#1 is null
[org.hibernate.cache.ReadWriteCache],Cached: tavant.platform.test.domain.Department#1
[org.hibernate.engine.TwoPhaseLoad],done materializing entity [tavant.platform.test.domain.Department#1]
[org.hibernate.engine.PersistenceContext],initializing non-lazy collections
[org.hibernate.cache.StandardQueryCache],caching query results in region: org.hibernate.cache.StandardQueryCache
[org.hibernate.jdbc.JDBCContext],after autocommit
[org.hibernate.impl.SessionImpl],closing session
[org.hibernate.jdbc.ConnectionManager],closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
[org.hibernate.connection.DriverManagerConnectionProvider],returning connection to pool, pool size: 1
[org.hibernate.jdbc.JDBCContext],after transaction completion
[org.hibernate.impl.SessionImpl],after transaction completion
Employee : [Id : 1, name : testEmployee], Employee.Department : [Id : 1, name : testDepartment]



# Going to make the second read
[org.hibernate.impl.SessionImpl],opened session at timestamp: 4671568772501504
[org.hibernate.impl.SessionImpl],find: from Employee e join fetch e.department where e.name = :name
[org.hibernate.engine.QueryParameters],named parameters: {name=testEmployee}
[org.hibernate.cache.StandardQueryCache],checking cached query results in region: org.hibernate.cache.StandardQueryCache
[org.hibernate.cache.EhCache],key: sql: select employee0_.EMP_ID as EMP1_0_, department1_.DEPARTMENT_ID as DEPARTMENT1_1_, employee0_.EMP_NAME as EMP2_1_0_, employee0_.DEPARTMENT_ID as DEPARTMENT3_1_0_, department1_.NAME as NAME0_1_ from CACHE_ISSUE_EMP employee0_ inner join CACHE_ISSUE_DEP department1_ on employee0_.DEPARTMENT_ID=department1_.DEPARTMENT_ID where (employee0_.EMP_NAME=? ); parameters: ; named parameters: {name=testEmployee}
[org.hibernate.cache.StandardQueryCache],Checking query spaces for up-to-dateness: [[CACHE_ISSUE_DEP, CACHE_ISSUE_EMP]]
[org.hibernate.cache.EhCache],key: CACHE_ISSUE_DEP
[org.hibernate.cache.UpdateTimestampsCache],[CACHE_ISSUE_DEP] last update timstamp: 4671568770453505, result set timestamp: 4671568770453509
[org.hibernate.cache.EhCache],key: CACHE_ISSUE_EMP
[org.hibernate.cache.UpdateTimestampsCache],[CACHE_ISSUE_EMP] last update timstamp: 4671568770453508, result set timestamp: 4671568770453509
[org.hibernate.cache.StandardQueryCache],returning cached query results
[org.hibernate.event.def.DefaultLoadEventListener],loading entity: [tavant.platform.test.domain.Employee#1]
[org.hibernate.event.def.DefaultLoadEventListener],attempting to resolve: [tavant.platform.test.domain.Employee#1]
[org.hibernate.cache.ReadWriteCache],Cache lookup: tavant.platform.test.domain.Employee#1
[org.hibernate.cache.EhCache],key: tavant.platform.test.domain.Employee#1
[org.hibernate.cache.ReadWriteCache],Cache hit: tavant.platform.test.domain.Employee#1
[org.hibernate.event.def.DefaultLoadEventListener],resolved object in second-level cache: [tavant.platform.test.domain.Employee#1]
[org.hibernate.event.def.DefaultLoadEventListener],loading entity: [tavant.platform.test.domain.Department#1]
[org.hibernate.event.def.DefaultLoadEventListener],creating new proxy for entity
[org.hibernate.event.def.DefaultLoadEventListener],Cached Version: null
[org.hibernate.engine.PersistenceContext],initializing non-lazy collections
[org.hibernate.event.def.DefaultLoadEventListener],resolved object in second-level cache: [tavant.platform.test.domain.Employee#1]
[org.hibernate.jdbc.JDBCContext],after autocommit
[org.hibernate.impl.SessionImpl],after transaction completion
[org.hibernate.impl.SessionImpl],closing session
[org.hibernate.LazyInitializationException],could not initialize proxy - the owning Session was closed
org.hibernate.LazyInitializationException: could not initialize proxy - the owning Session was closed
   at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:53)
                [..]

tenwit · **Joined:** Thu Dec 23, 2004 9:08 pm **Posts:** 2008

The query cache is not like the session cache: it caches only IDs. I don't know what it does with them, but what you're seeing suggests to me that the emp object (rather than the emp.getDepartment() object) is being returned proxied, with just its ID intact. When you access any propery in it (including emp.getDepartment()), it is de-proxied from the session cache.

You can test this theory by calling emp.getDepartment() instead of Hibernate.initialize(emp.getDepartment()). If you do that and all works well after you close the session, then that's your solution.

vikas_s · **Posted:** Wed Feb 22, 2006 10:31 am

tenwit wrote:

The query cache is not like the session cache: it caches only IDs.

You are right about the query cache. It caches only the ids and these ids are then used to load the actual object from either the session cache, second level cache or db, in that order.

tenwit wrote:

I don't know what it does with them, but what you're seeing suggests to me that the emp object (rather than the emp.getDepartment() object) is being returned proxied, with just its ID intact. When you access any propery in it (including emp.getDepartment()), it is de-proxied from the session cache.

I rather get the feeling that the employee object is getting loaded fully but the department relation is getting loaded as a proxy. This is also what the logs seem to suggest :

Code:

[org.hibernate.event.def.DefaultLoadEventListener],resolved object in second-level cache: [tavant.platform.test.domain.Employee#1]
[org.hibernate.event.def.DefaultLoadEventListener],loading entity: [tavant.platform.test.domain.Department#1]
[org.hibernate.event.def.DefaultLoadEventListener],creating new proxy for entity

I tried debugging through this usecase myself and this is how the "second read" seemed to be happening :

Hibernate figures out that the query that you are trying to run is already cached in the query cache. It gets the ids (corresponding to the resultset) from the cache.
In the process of assembling the Employee (via ManyToOneType.assemble(..) ), it calls SessionImpl.internalLoad(...). This loads the Employee object from the Second Level cache, w/o applying any proxy wrapper over that.
Later, when it has to assemble the Department for the user, it again performs the same step as above. Only difference is, it actually applies a proxy wrapper over the Department object, even though the object is fully initialized.
When employee.getDepartment() is called from outside session, Hibernate ofcourse won't be able to "figure out" that the object inside the proxy is already initialized. The moment Hibernate realizes that there is a proxy, it tries to initialize it and the very first thing it checks during this process is that a session should be open. That check fails and you get the exception.

And to make it more interesting, here is the very first line of the SessionImpl.internalLoad(...) method:

Code:

LoadEventListener.LoadType type = nullable ? INTERNAL_LOAD_NULLABLE : eager ? LoadEventListener.INTERNAL_LOAD_EAGER : LoadEventListener.INTERNAL_LOAD_LAZY;

As it turns out, the "eager" variable is true while loading the Employee and false while loading Department. Consequently, Hibernate uses the INTERNAL_LOAD_EAGER strategy for Employee and INTERNAL_LOAD_LAZY for Department.

Now, if you look at this snippet in DefaultLoadEventListener.proxyOrLoad(...) (invoked by SessionImpl.internalLoad(...)) :

Code:

if ( options.isAllowProxyCreation() ) {
  return createProxyIfNecessary( event, persister, keyToLoad, options, persistenceContext );
} else {
  // return a newly loaded object
  return load(event, persister, keyToLoad, options);
}

The only difference b/w INTERNAL_LOAD_EAGER strategy and INTERNAL_LOAD_LAZY are that allowProxyCreation is true for the latter.

I don't know if it's just me, but this is actually starting to smell of a hibenate bug... But then that's just me ;-)

Rgds,
Vikas

vikas_s · **Posted:** Sat Feb 25, 2006 4:35 pm

Raised this as a bug. The JIRA entry is HHH-1523.

Rgds,
Vikas.

saikrishna · **Joined:** Mon Mar 27, 2006 3:44 pm **Posts:** 26

I have a similar problem
Look at this
http://forum.hibernate.org/viewtopic.ph ... highlight=