Can't see ehcache working across sessions

amezick · **Joined:** Mon Nov 03, 2003 11:48 pm **Posts:** 29

Ok, I am running a junit test. I get VA from the StateList table, it is added to the 2ndlvl cache, close the session, open a new session, get VA from the StateList table and there is a miss in the cache. Shouldn't I get a cache hit from this?

Code:

    public void testGetStateById() {
        cdm=new CodesDataManager();
        StateCode code = cdm.getStateById("VA");
        assertTrue("StateCode test ", "Virginia".equals(code.getDescription()));
        cdm.closeSession();
        cdm=new CodesDataManager();
        code = cdm.getStateById("MD");
        code = cdm.getStateById("VA");
        code = cdm.getStateById("MD");
        }

Here is a trace:

Code:

Hibernate inited
DEBUG - opened session
DEBUG - find: select code from StateCode code where code.stateCode = ?
DEBUG - parameters: [VA]
DEBUG - compiling query
DEBUG - flushing session
DEBUG - Flushing entities and processing referenced collections
DEBUG - Processing unreferenced collections
DEBUG - Scheduling collection removes/(re)creates/updates
DEBUG - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
DEBUG - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
DEBUG - Dont need to execute flush
DEBUG - HQL: select code from org.guidestar.wb.codes.hibernate.StateCode code where code.stateCode = ?
DEBUG - SQL: select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code=? )
DEBUG - about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG - total checked-out connections: 0
DEBUG - using pooled JDBC connection, pool size: 0
DEBUG - prepared statement get: select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code=? )
DEBUG - preparing statement
DEBUG - binding 'VA' to parameter: 1
DEBUG - processing result set
DEBUG - returning 'VA' as column: state_code
DEBUG - result row: VA
DEBUG - Initializing object from ResultSet: VA
DEBUG - Hydrating entity: org.guidestar.wb.codes.hibernate.StateCode#VA
DEBUG - returning 'Virginia' as column: descript2_
DEBUG - done processing result set (1 rows)
DEBUG - done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG - closing statement
DEBUG - total objects hydrated: 1
DEBUG - resolving associations for [org.guidestar.wb.codes.hibernate.StateCode#VA]
DEBUG - adding entity to second-level cache [org.guidestar.wb.codes.hibernate.StateCode#VA]
DEBUG - Caching: VA
DEBUG - calling onLoad()
DEBUG - done materializing entity [org.guidestar.wb.codes.hibernate.StateCode#VA]
DEBUG - initializing non-lazy collections
DEBUG - closing session
DEBUG - disconnecting session
DEBUG - SQL Warning
java.sql.SQLWarning: [WBVS02]Changed database context to 'black_prince'.
   at com.inet.tds.a.a(Unknown Source)
   at com.inet.tds.a.a(Unknown Source)
   at com.inet.tds.a.<init>(Unknown Source)
   at com.inet.tds.TdsDriver.connect(Unknown Source)
   at com.p6spy.engine.spy.P6SpyDriverCore.connect(P6SpyDriverCore.java:388)
   at java.sql.DriverManager.getConnection(DriverManager.java:512)
   at java.sql.DriverManager.getConnection(DriverManager.java:140)
   at net.sf.hibernate.connection.DriverManagerConnectionProvider.getConnection(DriverManagerConnectionProvider.java:95)
   at net.sf.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:71)
   at net.sf.hibernate.cfg.Configuration.buildSettings(Configuration.java:1078)
   at net.sf.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:724)
   at org.guidestar.wb.database.session.HibernateSession.init(HibernateSession.java:29)
   at org.guidestar.wb.codes.dm.CodesDataManagerTest.<init>(CodesDataManagerTest.java:53)
   at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
   at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
   at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
   at java.lang.reflect.Constructor.newInstance(Constructor.java:274)
   at junit.framework.TestSuite.createTest(TestSuite.java:135)
   at junit.framework.TestSuite.addTestMethod(TestSuite.java:114)
   at junit.framework.TestSuite.<init>(TestSuite.java:75)
   at org.guidestar.wb.codes.CodesTests.suite(CodesTests.java:29)
   at org.guidestar.wb.WbTests.suite(WbTests.java:29)
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
   at java.lang.reflect.Method.invoke(Method.java:324)
   at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.getTest(RemoteTestRunner.java:335)
   at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:369)
   at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:276)
   at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:167)
WARN - SQL Warning: 5701, SQLState: 01000
WARN - [WBVS02]Changed database context to 'black_prince'.
WARN - SQL Warning: 5703, SQLState: 01000
WARN - [WBVS02]Changed language setting to us_english.
DEBUG - returning connection to pool, pool size: 1
DEBUG - transaction completion
DEBUG - opened session
DEBUG - find: select code from StateCode code where code.stateCode = ?
DEBUG - parameters: [MD]
DEBUG - flushing session
DEBUG - Flushing entities and processing referenced collections
DEBUG - Processing unreferenced collections
DEBUG - Scheduling collection removes/(re)creates/updates
DEBUG - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
DEBUG - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
DEBUG - Dont need to execute flush
DEBUG - HQL: select code from org.guidestar.wb.codes.hibernate.StateCode code where code.stateCode = ?
DEBUG - SQL: select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code=? )
DEBUG - about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG - total checked-out connections: 0
DEBUG - using pooled JDBC connection, pool size: 0
DEBUG - prepared statement get: select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code=? )
DEBUG - preparing statement
DEBUG - binding 'MD' to parameter: 1
DEBUG - processing result set
DEBUG - returning 'MD' as column: state_code
DEBUG - result row: MD
DEBUG - Initializing object from ResultSet: MD
DEBUG - Hydrating entity: org.guidestar.wb.codes.hibernate.StateCode#MD
DEBUG - returning 'Maryland' as column: descript2_
DEBUG - done processing result set (1 rows)
DEBUG - done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG - closing statement
DEBUG - total objects hydrated: 1
DEBUG - resolving associations for [org.guidestar.wb.codes.hibernate.StateCode#MD]
DEBUG - adding entity to second-level cache [org.guidestar.wb.codes.hibernate.StateCode#MD]
DEBUG - Caching: MD
DEBUG - calling onLoad()
DEBUG - done materializing entity [org.guidestar.wb.codes.hibernate.StateCode#MD]
DEBUG - initializing non-lazy collections
DEBUG - find: select code from StateCode code where code.stateCode = ?
DEBUG - parameters: [VA]
DEBUG - flushing session
DEBUG - Flushing entities and processing referenced collections
DEBUG - Processing unreferenced collections
DEBUG - Scheduling collection removes/(re)creates/updates
DEBUG - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
DEBUG - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
DEBUG - listing entities:
DEBUG - org.guidestar.wb.codes.hibernate.StateCode{description=Maryland, stateCode=MD}
DEBUG - Dont need to execute flush
DEBUG - HQL: select code from org.guidestar.wb.codes.hibernate.StateCode code where code.stateCode = ?
DEBUG - SQL: select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code=? )
DEBUG - about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG - prepared statement get: select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code=? )
DEBUG - preparing statement
DEBUG - binding 'VA' to parameter: 1
DEBUG - processing result set
DEBUG - returning 'VA' as column: state_code
DEBUG - result row: VA
DEBUG - Initializing object from ResultSet: VA
DEBUG - Hydrating entity: org.guidestar.wb.codes.hibernate.StateCode#VA
DEBUG - returning 'Virginia' as column: descript2_
DEBUG - done processing result set (1 rows)
DEBUG - done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG - closing statement
DEBUG - total objects hydrated: 1
DEBUG - resolving associations for [org.guidestar.wb.codes.hibernate.StateCode#VA]
DEBUG - adding entity to second-level cache [org.guidestar.wb.codes.hibernate.StateCode#VA]
DEBUG - Caching: VA
DEBUG - calling onLoad()
DEBUG - done materializing entity [org.guidestar.wb.codes.hibernate.StateCode#VA]
DEBUG - initializing non-lazy collections
DEBUG - find: select code from StateCode code where code.stateCode = ?
DEBUG - parameters: [MD]
DEBUG - flushing session
DEBUG - Flushing entities and processing referenced collections
DEBUG - Processing unreferenced collections
DEBUG - Scheduling collection removes/(re)creates/updates
DEBUG - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
DEBUG - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
DEBUG - listing entities:
DEBUG - org.guidestar.wb.codes.hibernate.StateCode{description=Virginia, stateCode=VA}
DEBUG - org.guidestar.wb.codes.hibernate.StateCode{description=Maryland, stateCode=MD}
DEBUG - Dont need to execute flush
DEBUG - HQL: select code from org.guidestar.wb.codes.hibernate.StateCode code where code.stateCode = ?
DEBUG - SQL: select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code=? )
DEBUG - about to open: 0 open PreparedStatements, 0 open ResultSets
DEBUG - prepared statement get: select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code=? )
DEBUG - preparing statement
DEBUG - binding 'MD' to parameter: 1
DEBUG - processing result set
DEBUG - returning 'MD' as column: state_code
DEBUG - result row: MD
DEBUG - done processing result set (1 rows)
DEBUG - done closing: 0 open PreparedStatements, 0 open ResultSets
DEBUG - closing statement
DEBUG - total objects hydrated: 0
DEBUG - initializing non-lazy collections

As you can see, Va gets added to the 2ndlvl cache twice while MD only gets added once. Even freaker, when I hook p6pspy up to this I get:

Code:

1071504170001|15|0|statement|select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code=? )|select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code='VA' )
1071504170017|-1||resultset|select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code='VA' )|descript2_ = Virginia, state_code = VA
1071504170032|0|0|statement|select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code=? )|select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code='MD' )
1071504170032|-1||resultset|select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code='MD' )|descript2_ = Maryland, state_code = MD
1071504170048|0|0|statement|select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code=? )|select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code='VA' )
1071504170048|-1||resultset|select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code='VA' )|descript2_ = Virginia, state_code = VA
1071504170048|0|0|statement|select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code=? )|select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code='MD' )
1071504170048|-1||resultset|select statecode0_.state_code as state_code, statecode0_.description as descript2_ from dbo.state_codes statecode0_ where (statecode0_.state_code='MD' )|state_code = MD

Here is my hibernate mapping:

Code:

<hibernate-mapping>
    <class
        name="org.guidestar.wb.codes.hibernate.StateCode"
        table="state_codes"
        proxy="org.guidestar.wb.codes.hibernate.StateCode"
        dynamic-update="false"
        dynamic-insert="false"
        mutable="false"
    >

        <cache usage="read-only"/>

        <id 
            name="stateCode"
            column="state_code"
            type="string"
            length="2"
            unsaved-value="null" 
        >
            <generator class="assigned">
            </generator>
        </id>

        <version
            name="lastModified"
            type="java.util.Date"
            column="last_modified"
        />

        <property
            name="description"
            type="string"
            update="true"
            insert="true"
            column="description"
            length="100"
            not-null="true"
            unique="false"
        />

        <!--
            To add non XDoclet property mappings, create a file named
                hibernate-properties-StateCode.xml
            containing the additional properties and place it in your merge dir.
        -->

    </class>

Am I really confused or is there something wrong with the cache?

emmanuel · **Posted:** Mon Dec 15, 2003 1:18 pm

session.find() does not look at the cache.

session.load and session.iterate do.

amezick · **Joined:** Mon Nov 03, 2003 11:48 pm **Posts:** 29

Ok, I see that documented in section 12.1. I was expecting to see this type of thing mentioned in section 12.2 as they seem to be talking about things that are only slightly related to each other. Thanks for the help! I got it working when I switched over to using .load from .find.
--Angus

emmanuel · **Posted:** Mon Dec 15, 2003 2:21 pm

A patch to the doc would be greatly appreciated, by Christian and Hibernate team ;-)

amezick · **Joined:** Mon Nov 03, 2003 11:48 pm **Posts:** 29

epbernard wrote:

A patch to the doc would be greatly appreciated, by Christian and Hibernate team ;-)

Ok, before I do that I need to know exactly how the different query types affect the cache? I really am, as the line by my name describes, a New User. I don't yet know enough to correct documentation so that it can help a beginner.
--Angus