-->
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.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 15 posts ] 
Author Message
 Post subject: ehcache seems configured, query not being cached
PostPosted: Wed Mar 28, 2007 3:03 pm 
Newbie

Joined: Mon Mar 12, 2007 2:47 pm
Posts: 11
Hibernate version: 3.2.0

Ehcache version: 1.2.4

I'm having issues with getting the "caching" behaviour to work. I've just mapped a simple Country business object to my country table in the database and enabled ehcache to cache on this particular table. However, when i load up my page that calls the function to get all countries, there does not seem to be any performance increase after the first hit like i would expect. the outputted log times are as follows (according to the code i've pasted below).

****** Get Country List exec time: 2890ms -- 236 items ******
****** Get Country List exec time: 2109ms -- 236 items ******
****** Get Country List exec time: 2344ms -- 236 items ******
****** Get Country List exec time: 2032ms -- 236 items ******

When i start up my Resin, the logs show that my ehcache provider is enabled, and i see the log message "- read-only cache configured for mutable class: com.gdi.core.businessobjects.Country" so i would assume my Country should be returning from cache after first hit. Is there anything i'm missing or should be doing differently? I've posted details of my current setup including the source code that is getting the country list below. Thanks for any help


Mapping documents:

For country

Code:
<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC "-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<!-- Generated 10-Aug-2006 12:24:19 PM by Hibernate Tools 3.2.0.beta6a -->
<hibernate-mapping>
    <class name="com.gdi.core.businessobjects.Country" table="country">
        <id name="id" type="int">
            <column name="id" />
            <generator class="sequence">
               <param name="sequence">country_id_seq</param>
            </generator>
        </id>
        <property name="name" type="string">
            <column name="name" length="32" not-null="true" />
        </property>
        <property name="code" type="string">
            <column name="code" length="5" not-null="true" />
        </property>
        <property name="numericCode" type="string">
            <column name="numericcode" length="3" not-null="true" />
        </property>
        <property name="alphaCode" type="string">
            <column name="alphacode" length="3" not-null="true" />
        </property>
    </class>
</hibernate-mapping>


in my spring/hibernate configuration session factory definition

Code:
      <property name="hibernateProperties">
         <props>
            <prop key="hibernate.dialect">org.hibernate.dialect.PostgreSQLDialect</prop>
            <prop key="hibernate.show_sql">false</prop>
            <prop key="hibernate.generate_statistics">true</prop>

            <prop key="hibernate.cache.provider_class">org.hibernate.cache.EhCacheProvider</prop>
            <prop key="hibernate.cache.provider_configuration_file_resource_path">gdi-ehcache.xml</prop>            
            <prop key="hibernate.cache.use_query_cache">true</prop>
         </props>
      </property>         

      <property name="entityCacheStrategies">
         <props>
             <prop key="com.gdi.core.businessobjects.Licensee">read-only</prop>
             <prop key="com.gdi.core.businessobjects.Country">read-only</prop>
             <prop key="com.gdi.core.businessobjects.CountryRegion">read-only</prop>
          </props>
      </property>   


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

Code:
        return getHibernateTemplate().executeFind(new HibernateCallback()
        {
            public Object doInHibernate(Session session) throws HibernateException, SQLException
            {
                long startTime = System.currentTimeMillis();
                               
                Query query = session.createQuery("from Country order by name asc");                               
                List list = query.list();
                               
                long endTime = System.currentTimeMillis();
                System.out.println("****** Get Country List exec time:  " + (endTime - startTime) + "ms -- " + list.size() + " items  ******" );               
                                               
                return list;
            }
        }
        );


Name and version of the database you are using:

PostGres 7.4

Debug level Hibernate log excerpt:

- Second-level cache: enabled
- Query cache: enabled
- Cache provider: org.hibernate.cache.EhCacheProvider
- Optimize cache for minimal puts: disabled
- Structured second-level cache entries: disabled
- Query cache factory: org.hibernate.cache.StandardQueryCacheFactory
- Statistics: enabled
- Deleted entity synthetic identifier rollback: disabled
- Default entity-mode: pojo
- building session factory
- read-only cache configured for mutable class: com.gdi.core.businessobjects.Licensee
- read-only cache configured for mutable class: com.gdi.core.businessobjects.CountryRegion
- read-only cache configured for mutable class: com.gdi.core.businessobjects.Country
- Not binding factory to JNDI, no JNDI name configured
- starting update timestamps cache at region: org.hibernate.cache.UpdateTimestampsCache
- Could not find configuration [org.hibernate.cache.UpdateTimestampsCache]; using defaults.
- starting query cache at region: org.hibernate.cache.StandardQueryCache
- Could not find configuration [org.hibernate.cache.StandardQueryCache]; using defaults.


Top
 Profile  
 
 Post subject:
PostPosted: Wed Mar 28, 2007 3:53 pm 
Expert
Expert

Joined: Tue Jul 11, 2006 10:21 am
Posts: 457
Location: Columbus, Ohio
Queries are not cached by default, you must enable them on a query-by-query basis thusly:

Code:
Query query = session.createQuery("from Country order by name asc").setCacheable(true);                               


Top
 Profile  
 
 Post subject:
PostPosted: Wed Mar 28, 2007 4:46 pm 
Newbie

Joined: Mon Mar 12, 2007 2:47 pm
Posts: 11
I guess i should've been clear about the question hehe. I am wondering why it "appears" that it's not grabbing the result set from cache... given the times of execution of that function, it's telling me that every call is hitting the database to regrab the results instead of grabbing it from cache after the first hit.


Top
 Profile  
 
 Post subject:
PostPosted: Wed Mar 28, 2007 7:35 pm 
Newbie

Joined: Mon Mar 12, 2007 2:47 pm
Posts: 11
Also, is there anywhere i can dig into the SessionFactory... or ehcache manager for statistics during each call? I'd like to somehow know if the system is actually caching or not caching the results. I'm just assuming it's not caching based on the response time between each calls on such a simple query. Most examples i've seen calls that take 1800 ms reduced down to 50-100 ms so i'm expecting a level of improvement in performance around this factor in my application as well.


Top
 Profile  
 
 Post subject:
PostPosted: Thu Mar 29, 2007 8:02 am 
Expert
Expert

Joined: Tue Jul 11, 2006 10:21 am
Posts: 457
Location: Columbus, Ohio
Look at the Statistics API in the docs for cache hits, etc.


Top
 Profile  
 
 Post subject: Logging statistics
PostPosted: Thu Mar 29, 2007 2:24 pm 
Newbie

Joined: Mon Mar 12, 2007 2:47 pm
Posts: 11
After looking through the log files from the sessionfactory's statistics log summary. It appears the application is loading from cache, however the overall execution time in that java method still makes me wonder why the performance gain is not that much better than expected.

i did a trial run of 4 hits to get my country list through the DAO mentioned in the beginning of this thread and i got the results based on the execution time in the java code.

****** Get Country List exec time: 2562ms -- 236 items ******
****** Get Country List exec time: 2016ms -- 236 items ******
****** Get Country List exec time: 2175ms -- 236 items ******
****** Get Country List exec time: 2259ms -- 236 items ******

the log dump of the session factory gives these numbers below. It appears the countries are loaded into cache, and it appears that the DAO is doing a hit on the cache to load the objects. So it seems all working, however i still don't see how the exectuion time can not change for the DAO call. I'm expecting results differences outlined in the article i read at
http://www.devx.com/dbzone/Article/29685/1954?pf=true. Unless i did something wrong, this doesn't seem like it should be the correct behaviour of retrieving a cached list of simple Country objects. I'm still relatively new to hibernate, so all these stats aren't completely familiar to me, maybe someone can enlighten me as to what i can be missing. Thanks in advance.

Code:
Initial stats on factory
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - Logging statistics....
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - start time: 1175192124093
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - sessions opened: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - sessions closed: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - transactions: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - successful transactions: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - optimistic lock failures: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - flushes: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - connections obtained: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - statements prepared: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - statements closed: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - second level cache puts: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - second level cache hits: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - second level cache misses: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - entities loaded: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - entities updated: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - entities inserted: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - entities deleted: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - entities fetched (minimize this): 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - collections loaded: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - collections updated: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - collections removed: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - collections recreated: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - collections fetched (minimize this): 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - queries executed to database: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - query cache puts: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - query cache hits: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - query cache misses: 0
2007-Mar-29 11:15:35 [StatisticsImpl] INFO   - max query time: 0ms

after 1st hit
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - Logging statistics....
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - start time: 1175192124093
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - sessions opened: 1
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - sessions closed: 1
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - transactions: 1
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - successful transactions: 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - optimistic lock failures: 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - flushes: 1
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - connections obtained: 1
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - statements prepared: 1
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - statements closed: 1
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - second level cache puts: 236
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - second level cache hits: 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - second level cache misses: 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - entities loaded: 236
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - entities updated: 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - entities inserted: 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - entities deleted: 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - entities fetched (minimize this): 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - collections loaded: 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - collections updated: 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - collections removed: 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - collections recreated: 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - collections fetched (minimize this): 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - queries executed to database: 1
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - query cache puts: 1
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - query cache hits: 0
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - query cache misses: 1
2007-Mar-29 11:15:40 [StatisticsImpl] INFO   - max query time: 2000ms

after 2nd hit
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - Logging statistics....
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - start time: 1175192124093
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - sessions opened: 2
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - sessions closed: 2
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - transactions: 1
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - successful transactions: 0
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - optimistic lock failures: 0
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - flushes: 2
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - connections obtained: 1
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - statements prepared: 1
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - statements closed: 1
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - second level cache puts: 236
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - second level cache hits: 236
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - second level cache misses: 0
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - entities loaded: 236
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - entities updated: 0
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - entities inserted: 0
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - entities deleted: 0
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - entities fetched (minimize this): 0
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - collections loaded: 0
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - collections updated: 0
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - collections removed: 0
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - collections recreated: 0
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - collections fetched (minimize this): 0
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - queries executed to database: 1
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - query cache puts: 1
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - query cache hits: 1
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - query cache misses: 1
2007-Mar-29 11:15:44 [StatisticsImpl] INFO   - max query time: 2000ms

after 3rd hit
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - Logging statistics....
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - start time: 1175192124093
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - sessions opened: 3
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - sessions closed: 3
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - transactions: 1
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - successful transactions: 0
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - optimistic lock failures: 0
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - flushes: 3
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - connections obtained: 1
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - statements prepared: 1
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - statements closed: 1
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - second level cache puts: 236
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - second level cache hits: 472
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - second level cache misses: 0
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - entities loaded: 236
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - entities updated: 0
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - entities inserted: 0
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - entities deleted: 0
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - entities fetched (minimize this): 0
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - collections loaded: 0
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - collections updated: 0
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - collections removed: 0
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - collections recreated: 0
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - collections fetched (minimize this): 0
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - queries executed to database: 1
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - query cache puts: 1
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - query cache hits: 2
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - query cache misses: 1
2007-Mar-29 11:15:47 [StatisticsImpl] INFO   - max query time: 2000ms


after 4th hit
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - Logging statistics....
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - start time: 1175192124093
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - sessions opened: 4
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - sessions closed: 4
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - transactions: 1
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - successful transactions: 0
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - optimistic lock failures: 0
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - flushes: 4
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - connections obtained: 1
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - statements prepared: 1
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - statements closed: 1
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - second level cache puts: 236
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - second level cache hits: 708
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - second level cache misses: 0
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - entities loaded: 236
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - entities updated: 0
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - entities inserted: 0
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - entities deleted: 0
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - entities fetched (minimize this): 0
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - collections loaded: 0
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - collections updated: 0
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - collections removed: 0
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - collections recreated: 0
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - collections fetched (minimize this): 0
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - queries executed to database: 1
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - query cache puts: 1
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - query cache hits: 3
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - query cache misses: 1
2007-Mar-29 11:15:50 [StatisticsImpl] INFO   - max query time: 2000ms


Top
 Profile  
 
 Post subject:
PostPosted: Thu Mar 29, 2007 2:40 pm 
Expert
Expert

Joined: Tue Jul 11, 2006 10:21 am
Posts: 457
Location: Columbus, Ohio
To make life easier on both of us, can you reset the statistics between each run so that we don't have to calculate running totals as I analyze the data? It's a bit late in the day and the arithmetic portion of my brain is weary. ;)


Top
 Profile  
 
 Post subject:
PostPosted: Thu Mar 29, 2007 2:44 pm 
Expert
Expert

Joined: Tue Jul 11, 2006 10:21 am
Posts: 457
Location: Columbus, Ohio
From a cursory glance, it appears that after the initial load, all queries and entities are being loaded from the cache. The entity hydration routines should not be taking up so much time to load a mere 236 entities. Very odd. Repost the statistics after the above suggestion. It looks like you are only saving about 500ms due to the cacheing.


Top
 Profile  
 
 Post subject:
PostPosted: Thu Mar 29, 2007 2:52 pm 
Expert
Expert

Joined: Tue Jul 11, 2006 10:21 am
Posts: 457
Location: Columbus, Ohio
One more thing, try turing off the generate_statistics (and comment out your stats gathering code). Maybe that is creating the increase in execution times.


Top
 Profile  
 
 Post subject:
PostPosted: Thu Mar 29, 2007 3:02 pm 
Newbie

Joined: Mon Mar 12, 2007 2:47 pm
Posts: 11
I'm assuming when you say reset statistics between each run you mean for me to something like this between each run right?

getHibernateTemplate().getSessionFactory().getStatistics().logSummary();
getHibernateTemplate().getSessionFactory().getStatistics().clear();

Anyways i've done a trial of 4 hits again this time and here are the log files. And you're right, it seems like the hydration process is taking the bulk of the time, but it seems to not make sense why for such a small collection of simple Country objects. Thanks for your replies and time I really appreciate it.

****** Get Country List exec time: 2765ms -- 236 items ******
****** Get Country List exec time: 2062ms -- 236 items ******
****** Get Country List exec time: 1954ms -- 236 items ******
****** Get Country List exec time: 1969ms -- 236 items ******

Code:
initial stats
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - start time: 1175194729703
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - sessions opened: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - sessions closed: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - transactions: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - successful transactions: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - optimistic lock failures: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - flushes: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - connections obtained: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - statements prepared: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - statements closed: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - second level cache puts: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - second level cache hits: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - second level cache misses: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - entities loaded: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - entities updated: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - entities inserted: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - entities deleted: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - entities fetched (minimize this): 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - collections loaded: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - collections updated: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - collections removed: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - collections recreated: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - collections fetched (minimize this): 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - queries executed to database: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - query cache puts: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - query cache hits: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - query cache misses: 0
2007-Mar-29 11:59:03 [StatisticsImpl] INFO   - max query time: 0ms

after 1st hit
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - Logging statistics....
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - start time: 1175194743953
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - sessions opened: 1
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - sessions closed: 1
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - transactions: 1
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - successful transactions: 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - optimistic lock failures: 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - flushes: 1
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - connections obtained: 1
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - statements prepared: 1
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - statements closed: 1
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - second level cache puts: 236
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - second level cache hits: 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - second level cache misses: 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - entities loaded: 236
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - entities updated: 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - entities inserted: 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - entities deleted: 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - entities fetched (minimize this): 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - collections loaded: 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - collections updated: 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - collections removed: 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - collections recreated: 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - collections fetched (minimize this): 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - queries executed to database: 1
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - query cache puts: 1
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - query cache hits: 0
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - query cache misses: 1
2007-Mar-29 11:59:06 [StatisticsImpl] INFO   - max query time: 1969ms

after 2nd hit
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - Logging statistics....
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - start time: 1175194749359
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - sessions opened: 1
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - sessions closed: 1
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - transactions: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - successful transactions: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - optimistic lock failures: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - flushes: 1
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - connections obtained: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - statements prepared: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - statements closed: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - second level cache puts: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - second level cache hits: 236
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - second level cache misses: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - entities loaded: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - entities updated: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - entities inserted: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - entities deleted: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - entities fetched (minimize this): 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - collections loaded: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - collections updated: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - collections removed: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - collections recreated: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - collections fetched (minimize this): 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - queries executed to database: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - query cache puts: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - query cache hits: 1
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - query cache misses: 0
2007-Mar-29 11:59:11 [StatisticsImpl] INFO   - max query time: 0ms

after 3rd hit
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - Logging statistics....
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - start time: 1175194752921
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - sessions opened: 1
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - sessions closed: 1
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - transactions: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - successful transactions: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - optimistic lock failures: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - flushes: 1
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - connections obtained: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - statements prepared: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - statements closed: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - second level cache puts: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - second level cache hits: 236
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - second level cache misses: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - entities loaded: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - entities updated: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - entities inserted: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - entities deleted: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - entities fetched (minimize this): 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - collections loaded: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - collections updated: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - collections removed: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - collections recreated: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - collections fetched (minimize this): 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - queries executed to database: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - query cache puts: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - query cache hits: 1
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - query cache misses: 0
2007-Mar-29 11:59:14 [StatisticsImpl] INFO   - max query time: 0ms

after 4th hit
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - Logging statistics....
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - start time: 1175194756156
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - sessions opened: 1
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - sessions closed: 1
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - transactions: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - successful transactions: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - optimistic lock failures: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - flushes: 1
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - connections obtained: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - statements prepared: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - statements closed: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - second level cache puts: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - second level cache hits: 236
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - second level cache misses: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - entities loaded: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - entities updated: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - entities inserted: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - entities deleted: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - entities fetched (minimize this): 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - collections loaded: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - collections updated: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - collections removed: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - collections recreated: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - collections fetched (minimize this): 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - queries executed to database: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - query cache puts: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - query cache hits: 1
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - query cache misses: 0
2007-Mar-29 11:59:18 [StatisticsImpl] INFO   - max query time: 0ms



Top
 Profile  
 
 Post subject:
PostPosted: Thu Mar 29, 2007 3:22 pm 
Newbie

Joined: Mon Mar 12, 2007 2:47 pm
Posts: 11
Yeah i've tried turning off generate_statistics flag and also commented out the statistics generation dump, and still getting similar execution times lol


Top
 Profile  
 
 Post subject:
PostPosted: Thu Mar 29, 2007 4:57 pm 
Expert
Expert

Joined: Tue Jul 11, 2006 10:21 am
Posts: 457
Location: Columbus, Ohio
Hmmm...can I see your ehcache configuration file? Your cache region for the Country domain objects might be a bit misconfigured. Should be something like:

Code:
<cache name="com.gdi.core.businessobjects.Country"
   maxElementsInMemory="300"
   eternal="true"
   overflowToDisk="false"
/>


It's the only thing that I can think of right now. If you have overflowToDisk turned on, then it may be a consequence of serialization/deserialization to the file system. The objects are not so complex that they could not be stored entirely in memory.


Top
 Profile  
 
 Post subject:
PostPosted: Thu Mar 29, 2007 5:00 pm 
Newbie

Joined: Mon Mar 12, 2007 2:47 pm
Posts: 11
Hi Ananasi,

Here's my ehcache.xml file...

Code:
<!--
  -  GDI Hibernate ecache definitions
  -->

<ehcache> 

   <diskStore path="java.io.tmpdir"/>

   <defaultCache
       maxElementsInMemory="10"
       eternal="false"
       timeToIdleSeconds="120"
       timeToLiveSeconds="120"
       overflowToDisk="true"
       diskPersistent="false"
       diskExpiryThreadIntervalSeconds="120"
       memoryStoreEvictionPolicy="LRU"/>

   <cache name="org.hibernate.cache.StandardQueryCache"
       maxElementsInMemory="5"
       eternal="false"
       timeToLiveSeconds="120"
       overflowToDisk="true"/>

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

   <cache name="com.gdi.core.businessobjects.Licensee"
       maxElementsInMemory="500"
       eternal="false"
       timeToIdleSeconds="120"
       timeToLiveSeconds="120"
       overflowToDisk="true"/>

   <cache name="com.gdi.core.businessobjects.Country"
       maxElementsInMemory="300"
       eternal="false"
       timeToIdleSeconds="120"
       timeToLiveSeconds="120"
       overflowToDisk="true"/>
                  
   <cache name="com.gdi.core.businessobjects.CountryRegion"
       maxElementsInMemory="100"
       eternal="false"
       timeToIdleSeconds="120"
       timeToLiveSeconds="120"
       overflowToDisk="true"/>      

</ehcache>
[/quote]


Top
 Profile  
 
 Post subject:
PostPosted: Fri Mar 30, 2007 8:57 am 
Expert
Expert

Joined: Tue Jul 11, 2006 10:21 am
Posts: 457
Location: Columbus, Ohio
The configuration looks good to me, although if your country table is relatively static, you can probably change eternal to true and get rid of the timeToIdleSeconds and timeToLiveSeconds. Let's try to eliminate the cacheing as a bottleneck. Let's turn off cacheing and post the execution times.


Top
 Profile  
 
 Post subject:
PostPosted: Tue Apr 03, 2007 10:48 am 
Newbie

Joined: Tue Apr 03, 2007 10:06 am
Posts: 1
I am having the same problem you describe. I enable debug logging and got the following message:

Code:
2007-04-03 07:47:04,500 DEBUG org.hibernate.cache.StandardQueryCache - checking cached query results in region: org.hibernate.cache.StandardQueryCache
2007-04-03 07:47:04,500 DEBUG org.hibernate.cache.StandardQueryCache - Checking query spaces for up-to-dateness: [VERSION]
2007-04-03 07:47:04,500 DEBUG org.hibernate.cache.UpdateTimestampsCache - [VERSION] last update timestamp: 4815290714046464, result set timestamp: 4815290467135488
2007-04-03 07:47:04,500 DEBUG org.hibernate.cache.StandardQueryCache - cached query results were not up to date
2007-04-03 07:47:04,500 DEBUG org.hibernate.cache.StandardQueryCache - caching query results in region: org.hibernate.cache.StandardQueryCache; timestamp=4815290467135488


My items are being cached but the timestamps in the cache make it so it will never get used. I modified the UpdateTimestampsCache class - isUpToDate method and got it to work, but I don't like the solution.


Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 15 posts ] 

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.