-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

View unanswered posts | View active topics


Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]


Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 6 posts ] 
  Previous topic | Next topic 
Author Message
pddd
 Post subject: Query cache across multiple requests
PostPosted: Sat Apr 17, 2010 9:47 am 
Newbie

Joined: Thu Jun 25, 2009 10:22 am
Posts: 5
Hi,

I am new to hibernate cache concepts.
Is there a way to use the query cache across multiple request like the second level cache it does?

I wrote the (Grails 1.2.2) code below to experiment with the hibernate cache. I observed that for a request the Composition domain class is cached in the for loop. There is only one database call in the first for loop iteration. This is also true for all subsequent request calls. There is always exactly one database call for every request although the query criteria is always the same. I would like to reduce the database calls for subsequent requests with the same criteria.

Is it possible with hibernate?

Code:
class CompositionController {
    def sessionFactory
    static allowedMethods = [save: "POST", update: "POST", delete: "POST"]
    static mapping = {cache true}

    def index = {
        for(int i=0;i<5;i++){
          def rc = Composition.withCriteria{
            eq("data1", 'data1.1')
            eq("data3", 1)
            cache true
          }
        }
        render sessionFactory.getStatistics()
    }
}

class Composition {
    String data1
    String data2
    int data3
    static constraints = {   
    }
}


Hibernate caching is activated in the datasource.groovy:
Code:
hibernate {
    cache.use_second_level_cache=true
    cache.use_query_cache=true
    cache.provider_class='net.sf.ehcache.hibernate.EhCacheProvider'
}


My ehcache.xml:
Code:
<ehcache xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:noNamespaceSchemaLocation="ehcache.xsd" >
    <diskStore path="java.io.tmpdir"/>
    <cacheManagerEventListenerFactory class="" properties=""/>
    <defaultCache
            maxElementsInMemory="10000"
            eternal="true"
            overflowToDisk="false"
            diskPersistent="false" />

    <cache name="org.hibernate.cache.UpdateTimestampsCache"
           maxElementsInMemory ="5000"
       eternal ="true"
       overflowToDisk ="true" />

    <cache name="org.hibernate.cache.StandardQueryCache"
           maxElementsInMemory="10000"
           eternal="false"
        timeToIdleSeconds="200"
        timeToLiveSeconds="500"
        overflowToDisk="true" />
</ehcache>


Bye
Pddd
Top
 Profile  
 
pb00067
 Post subject: Re: Query cache across multiple requests
PostPosted: Mon Apr 19, 2010 4:17 am 
Expert
Expert

Joined: Tue Jun 16, 2009 3:36 am
Posts: 990
In order to use hibernates second level query cache it is not enough to specify
Code:
  cache.use_query_cache=true

you must also exlicitely call
Code:
criteriaOrQuery.setCacheable(true); 

before you execute your query or criteria,
in order that the regarding result-set gets cached into the second level query cache.

N.B.: With EHCache as 2Lcache, in order that you can benefit of the cached result-set also in other sessions, without hit the database again for the same query, the regarding session must have a start-timestamp which is greater than the start-timestamp of the session in which the query was issued for the first time.
Top
 Profile  
 
pddd
 Post subject: Re: Query cache across multiple requests
PostPosted: Tue Apr 20, 2010 11:49 am 
Newbie

Joined: Thu Jun 25, 2009 10:22 am
Posts: 5
Thanks for the hints.
Code:
def rc = Composition.withCriteria{
            eq("data1", 'data1.1')
            eq("data3", 1)
            cache true
          }


Grails uses a HibernateCriteriaBuilder and "cache true" is mapped to criteria.setCacheable(true).

http://github.com/grails/grails/blob/e4bb5c338d94a5ae8d095a463d7ae9c799be626e/grails/src/java/grails/orm/HibernateCriteriaBuilder.java

Can you please explain why the query is cached in the for loop, but not across multiple requests (and so multiple hibernate sessions)?
I call the requests in subsequent order, so the start-timestamp condition should fit. But every request produces exactly one database hit.

Here is the log of my first and of my second request


    First:
    2010-04-20 18:01:59,008 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
    2010-04-20 18:01:59,009 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
    2010-04-20 18:01:59,009 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209206578548741, result set timestamp: 5209207929143296
    2010-04-20 18:01:59,009 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results
    2010-04-20 18:01:59,009 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
    2010-04-20 18:01:59,016 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
    2010-04-20 18:01:59,021 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
    2010-04-20 18:01:59,026 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
    2010-04-20 18:01:59,026 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
    2010-04-20 18:01:59,026 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209206578548741, result set timestamp: 5209207929143296
    2010-04-20 18:01:59,026 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results
    2010-04-20 18:01:59,027 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
    2010-04-20 18:01:59,027 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
    2010-04-20 18:01:59,027 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209206578548741, result set timestamp: 5209207929143296
    2010-04-20 18:01:59,027 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results
    2010-04-20 18:01:59,028 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
    2010-04-20 18:01:59,028 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
    2010-04-20 18:01:59,028 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209206578548741, result set timestamp: 5209207929143296
    2010-04-20 18:01:59,028 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results
    2010-04-20 18:01:59,029 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
    2010-04-20 18:01:59,029 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
    2010-04-20 18:01:59,029 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209206578548741, result set timestamp: 5209207929143296
    2010-04-20 18:01:59,029 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results


    Second request:

    2010-04-20 18:02:00,785 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
    2010-04-20 18:02:00,786 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
    2010-04-20 18:02:00,786 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209206578548741, result set timestamp: 5209207929143296
    2010-04-20 18:02:00,786 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results
    2010-04-20 18:02:00,786 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
    2010-04-20 18:02:00,794 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
    2010-04-20 18:02:00,832 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
    2010-04-20 18:02:00,849 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
    2010-04-20 18:02:00,850 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
    2010-04-20 18:02:00,850 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209206578548741, result set timestamp: 5209207929143296
    2010-04-20 18:02:00,850 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results
    2010-04-20 18:02:00,858 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
    2010-04-20 18:02:00,858 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
    2010-04-20 18:02:00,858 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209206578548741, result set timestamp: 5209207929143296
    2010-04-20 18:02:00,858 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results
    2010-04-20 18:02:00,859 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
    2010-04-20 18:02:00,860 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
    2010-04-20 18:02:00,860 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209206578548741, result set timestamp: 5209207929143296
    2010-04-20 18:02:00,860 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results
    2010-04-20 18:02:00,861 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
    2010-04-20 18:02:00,861 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
    2010-04-20 18:02:00,861 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209206578548741, result set timestamp: 5209207929143296
    2010-04-20 18:02:00,861 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results
Top
 Profile  
 
pb00067
 Post subject: Re: Query cache across multiple requests
PostPosted: Wed Apr 21, 2010 2:17 am 
Expert
Expert

Joined: Tue Jun 16, 2009 3:36 am
Posts: 990
Hi pddd,

every time your log reports a line like:
Code:
... StandardQueryCache - returning cached query results

a hit in the query cache is made and therefore a database hit should be avoided.
Why there are database hits as well, is hard to explain as long you don't log also the parameters of the where condition.
Can it be that the database hits are done, simply because concerning conditions are executed for the first time (=query don't yet cached at all) ?
Please also log the parameters of the where condition,
either by enabling
Code:
log4j.logger.org.hibernate.type=TRACE

or by using p6spy or org.apache.log4j.jdbc.JDBCAppender
Top
 Profile  
 
pddd
 Post subject: Re: Query cache across multiple requests
PostPosted: Thu Apr 22, 2010 8:56 am 
Newbie

Joined: Thu Jun 25, 2009 10:22 am
Posts: 5
I reduced the loop from 5 to 2 cycles to get a smaller log.
Interestingly the second and third request hits the database (5.th line, 'hibernate.SQL') with a different select statement than the first one.
But I still would expect, there should not be any database hit in the second and third request at all.

First Request:
2010-04-22 14:41:08,933 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
2010-04-22 14:41:08,935 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - query results were not found in cache
2010-04-22 14:41:08,936 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select this_.id as id0_0_, this_.version as version0_0_, this_.data1 as data3_0_0_, this_.data2 as data4_0_0_, this_.data3 as data5_0_0_ from composition this_ where (this_.data1=? and this_.data3=?)
2010-04-22 14:41:08,937 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - binding 'data1.1' to parameter: 1
2010-04-22 14:41:08,937 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - binding '1' to parameter: 2
2010-04-22 14:41:08,947 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '2' as column: id0_0_
2010-04-22 14:41:08,949 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:08,949 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:08,949 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:08,949 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:08,949 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '22' as column: id0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '42' as column: id0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '62' as column: id0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '82' as column: id0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:08,950 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:09,018 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - caching query results in region: org.hibernate.cache.StandardQueryCache; timestamp=5209866522066944
2010-04-22 14:41:09,019 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
2010-04-22 14:41:09,019 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
2010-04-22 14:41:09,020 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209866491052037, result set timestamp: 5209866522066944
2010-04-22 14:41:09,022 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results

Second Request
2010-04-22 14:41:15,041 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
2010-04-22 14:41:15,041 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
2010-04-22 14:41:15,041 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209866491052037, result set timestamp: 5209866522066944
2010-04-22 14:41:15,041 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results
2010-04-22 14:41:15,041 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
2010-04-22 14:41:15,041 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - binding '2' to parameter: 1
2010-04-22 14:41:15,046 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:15,046 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:15,046 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:15,046 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:15,047 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
2010-04-22 14:41:15,048 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - binding '22' to parameter: 1
2010-04-22 14:41:15,050 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:15,050 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:15,050 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:15,050 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:15,051 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
2010-04-22 14:41:15,051 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - binding '42' to parameter: 1
2010-04-22 14:41:15,054 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:15,054 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:15,054 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:15,054 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:15,055 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
2010-04-22 14:41:15,055 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - binding '62' to parameter: 1
2010-04-22 14:41:15,058 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:15,058 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:15,058 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:15,058 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:15,059 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
2010-04-22 14:41:15,059 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - binding '82' to parameter: 1
2010-04-22 14:41:15,063 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:15,063 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:15,063 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:15,063 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:15,064 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
2010-04-22 14:41:15,065 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
2010-04-22 14:41:15,065 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209866491052037, result set timestamp: 5209866522066944
2010-04-22 14:41:15,065 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results

Third Request:
2010-04-22 14:41:17,719 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
2010-04-22 14:41:17,720 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
2010-04-22 14:41:17,720 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209866491052037, result set timestamp: 5209866522066944
2010-04-22 14:41:17,720 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results
2010-04-22 14:41:17,720 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
2010-04-22 14:41:17,720 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - binding '2' to parameter: 1
2010-04-22 14:41:17,728 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:17,728 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:17,728 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:17,728 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:17,729 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
2010-04-22 14:41:17,729 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - binding '22' to parameter: 1
2010-04-22 14:41:17,731 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:17,731 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:17,731 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:17,732 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:17,732 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
2010-04-22 14:41:17,733 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - binding '42' to parameter: 1
2010-04-22 14:41:17,735 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:17,735 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:17,735 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:17,735 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:17,736 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
2010-04-22 14:41:17,736 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - binding '62' to parameter: 1
2010-04-22 14:41:17,738 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:17,739 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:17,739 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:17,739 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:17,739 [http-localhost%2F127.0.0.1-8080-1] DEBUG hibernate.SQL - select compositio0_.id as id0_0_, compositio0_.version as version0_0_, compositio0_.data1 as data3_0_0_, compositio0_.data2 as data4_0_0_, compositio0_.data3 as data5_0_0_ from composition compositio0_ where compositio0_.id=?
2010-04-22 14:41:17,740 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - binding '82' to parameter: 1
2010-04-22 14:41:17,742 [http-localhost%2F127.0.0.1-8080-1] TRACE type.LongType - returning '0' as column: version0_0_
2010-04-22 14:41:17,742 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data1.1' as column: data3_0_0_
2010-04-22 14:41:17,742 [http-localhost%2F127.0.0.1-8080-1] TRACE type.StringType - returning 'data2.1' as column: data4_0_0_
2010-04-22 14:41:17,742 [http-localhost%2F127.0.0.1-8080-1] TRACE type.IntegerType - returning '1' as column: data5_0_0_
2010-04-22 14:41:17,744 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
2010-04-22 14:41:17,744 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - Checking query spaces for up-to-dateness: [composition]
2010-04-22 14:41:17,744 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.UpdateTimestampsCache - [composition] last update timestamp: 5209866491052037, result set timestamp: 5209866522066944
2010-04-22 14:41:17,744 [http-localhost%2F127.0.0.1-8080-1] DEBUG cache.StandardQueryCache - returning cached query results
Top
 Profile  
 
pb00067
 Post subject: Re: Query cache across multiple requests
PostPosted: Fri Apr 23, 2010 5:03 am 
Expert
Expert

Joined: Tue Jun 16, 2009 3:36 am
Posts: 990
Quote:
Interestingly the second and third request hits the database (5.th line, 'hibernate.SQL') with a different select statement than the first one.
But I still would expect, there should not be any database hit in the second and third request at all.


Not the problem is clear to me.
You must be aware of the fact that the second-level-query-cache is only caching the primary-key values of the result-set objects,
assuming that the regarding entities (with all it property values) are still cached too in the entity 2L cache.
If single objects of the cached-result-set are not anymore cached in the entity 2L cache,
then hibernate performs single lookups to (re)load this entities:
this are the queries you see with the different select statement than the first one!

As you defined the defaultCache eternal I assume one of following scenarios happening:
- you configured composition entities to be cached in the defaultCache
but the defaultCache has reached the maxElementsInMemory="10000" and therefore it has begun to evict some composition entities
- you did forget to configured the composition entity class itself to be cached in the 2L cache at all
Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 6 posts ] 

Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]

You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.