Hi All,

I am noticing some strange behavior when using the Query Cache ..
The results of a query are cached in the first run and in the next run , I expect the results to be returned from the Cache,
Instead I see multiple SQLs being generated ( one for each Entity and all associations that were cached from the previous result )

Does anybody know why this is happening ?

I have 2 simple objects : Person and Event
Event is a simple class and Person has a Many-to-one relationship with Event :

<many-to-one name="event" column="EVENT_ID" class="example.Event" lazy="false" />

I run this method first :

Session session = HibernateUtil.getSessionFactory().openSession();
Vector list = new Vector();

String queryString = "from Person person left join fetch person.event";
Query query = session.createQuery(queryString).setCacheable(true);

List li = query.list();
Iterator itr = li.iterator();

while (itr.hasNext()) {
Person person = (Person) itr.next();
list.add(person.getId() +","+person.getFirstname()+","+person.getEvent().getTitle());
}

System.out.println("Found : " + list);
HibernateUtil.getSessionFactory().getStatistics().logSummary();


The Query “from Person person left join fetch person.event” generates this SQL/logs

16:25:35,916 DEBUG EhCacheProvider:89 - started EHCache region: org.hibernate.cache.StandardQueryCache
16:25:36,072 DEBUG StandardQueryCache:102 - checking cached query results in region: org.hibernate.cache.StandardQueryCache
16:25:36,072 DEBUG EhCache:68 - key: sql: select person0_.PERSON_ID as PERSON1_1_0_, event1_.EVENT_ID as EVENT1_0_1_, person0_.age as age1_0_, person0_.firstname as firstname1_0_, person0_.lastname as lastname1_0_, person0_.EVENT_ID as EVENT5_1_0_, event1_.EVENT_DATE as EVENT2_0_1_, event1_.title as title0_1_ from PERSON person0_ left outer join EVENTS event1_ on person0_.EVENT_ID=event1_.EVENT_ID; parameters: ; named parameters: {}

16:25:36,072 DEBUG EhCache:77 - Element for sql: select person0_.PERSON_ID as PERSON1_1_0_, event1_.EVENT_ID as EVENT1_0_1_, person0_.age as age1_0_, person0_.firstname as firstname1_0_, person0_.lastname as lastname1_0_, person0_.EVENT_ID as EVENT5_1_0_, event1_.EVENT_DATE as EVENT2_0_1_, event1_.title as title0_1_ from PERSON person0_ left outer join EVENTS event1_ on person0_.EVENT_ID=event1_.EVENT_ID; parameters: ; named parameters: {} is null
16:25:36,072 DEBUG StandardQueryCache:107 - query results were not found in cache

Hibernate: select person0_.PERSON_ID as PERSON1_1_0_, event1_.EVENT_ID as EVENT1_0_1_, person0_.age as age1_0_, person0_.firstname as firstname1_0_, person0_.lastname as lastname1_0_, person0_.EVENT_ID as EVENT5_1_0_, event1_.EVENT_DATE as EVENT2_0_1_, event1_.title as title0_1_ from PERSON person0_ left outer join EVENTS event1_ on person0_.EVENT_ID=event1_.EVENT_ID

16:25:36,260 DEBUG StandardQueryCache:73 - caching query results in region: org.hibernate.cache.StandardQueryCache; timestamp=4892397305511936


After a few seconds , I run the above method again ,
I expect that the SQLs will not be generated and executed again and the results will come from the Query Cache,
But I see the following :

16:25:40,306 DEBUG StandardQueryCache:102 - checking cached query results in region: org.hibernate.cache.StandardQueryCache
16:25:40,306 DEBUG EhCache:68 - key: sql: select person0_.PERSON_ID as PERSON1_1_0_, event1_.EVENT_ID as EVENT1_0_1_, person0_.age as age1_0_, person0_.firstname as firstname1_0_, person0_.lastname as lastname1_0_, person0_.EVENT_ID as EVENT5_1_0_, event1_.EVENT_DATE as EVENT2_0_1_, event1_.title as title0_1_ from PERSON person0_ left outer join EVENTS event1_ on person0_.EVENT_ID=event1_.EVENT_ID; parameters: ; named parameters: {}

16:25:40,306 DEBUG StandardQueryCache:156 - Checking query spaces for up-to-dateness: [PERSON, EVENTS]
16:25:40,306 DEBUG EhCache:68 - key: PERSON
16:25:40,306 DEBUG EhCache:77 - Element for PERSON is null
16:25:40,306 DEBUG EhCache:68 - key: EVENTS
16:25:40,306 DEBUG EhCache:77 - Element for EVENTS is null
16:25:40,306 DEBUG StandardQueryCache:117 - returning cached query results

It then generates the following 2 sets of SQLs ( one for Person and one for Event ) about *410* times..
ie one for each ID :
Hibernate: select person0_.PERSON_ID as PERSON1_1_0_, person0_.age as age1_0_, person0_.firstname as firstname1_0_, person0_.lastname as lastname1_0_, person0_.EVENT_ID as EVENT5_1_0_ from PERSON person0_ where person0_.PERSON_ID=?
Hibernate: select event0_.EVENT_ID as EVENT1_0_0_, event0_.EVENT_DATE as EVENT2_0_0_, event0_.title as title0_0_ from EVENTS event0_ where event0_.EVENT_ID=?

Can anyone explain why this is happening ?
No configuration has been done for EHcache . All values are default.

The only way to avoid the above was to setCacheable(false) and then it ran the same sql as above ( with the left join fetch) once and got the data again.

Am I missing any configuration ? is there any way to "dump" the values from the StandardQueryCache to see what was cached in the first place ?

Thanks
Pat

I think I got the answer (partially ):

Those are the SQLs to actually get the values since the QueryCache only holds the IDs and not the entire "dehydrated" objects.

Hence , it will get the IDs from the QueryCache and make the SQLs again.
and the SQls are going to be for each and every id !...

But should the objects now get fecthed from the secondry cache ?

Do I have to explictly "enable" the cache at the class level ?
( by including <cache usage="read-write" /> in the hbm file )

thanks
Pat