Cache Logging

wanton · **Joined:** Mon Oct 11, 2004 2:22 am **Posts:** 41

Hibernate version: 3.1.3 using ehcache

how can i debug what is being retrieved from cache and what is coming from the database? i'm trying to assertain that cache is working as i expect it to.

I've tried setting log4j category 'org.hibernate.cache' to DEBUG but it only tells me what key it uses for particular classes, not when something is loaded out of the cache, inserted into the cache or expired from cache.

thanks for any links to docos or suggestions.

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

Try using the net.sf.ehcache logger, instead of org.hibernate.cache.

wanton · **Joined:** Mon Oct 11, 2004 2:22 am **Posts:** 41

with 'org.hibernate.cache'=debug and 'net.sf.ehcache'=debug i get the following 3 log entries and only the first time i load the object.

Code:

19-06-2006 14:57:25,359 [http-8080-Processor23] DEBUG org.hibernate.cache.EhCache - key: MyObject#MyObject@5c1e7c7
19-06-2006 14:57:25,359 [http-8080-Processor23] DEBUG org.hibernate.cache.EhCache - Element for MyObject#MyObject@5c1e7c7 is null
19-06-2006 14:57:25,359 [http-8080-Processor23] DEBUG net.sf.ehcache.Cache - MyObject: Is element with key MyObject#MyObject@5c1e7c7 expired?: false

on subsequent loads i get no log messages.

i could assume that this means on subsequent loads another course of action is being taken (probably load from cache) but there is no log entry to confirm this.

is there any way to produce a log message such as "MyObject@5c1e7c7 loaded from cache"??

thanks for the help.

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

I do this the other way around: I turn on org.hibernate.type logging: that produces output when it goes to the DB, and not when it gets the object from the cache. Not exactly what you wanted..

wanton · **Joined:** Mon Oct 11, 2004 2:22 am **Posts:** 41

fair'nuff .. i suppose that eases my mind a little, for now i will assume caching is working based on absence of log entries. i give you one credit.

if anyone knows of a method to track loads from cache there are 2 credits availible.

thanks again.

wanton · **Joined:** Mon Oct 11, 2004 2:22 am **Posts:** 41

one other thing that worries me is that i do get the following log entry each time

Code:

DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
DEBUG org.hibernate.SQL - select *0_.* as *10_, *0_.* as *10_ from * *0_ where *0_.*=?
DEBUG org.hibernate.loader.hql.QueryLoader - bindNamedParameters() * -> * [1]
DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG org.hibernate.engine.StatefulPersistenceContext - initializing non-lazy collections
DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]

now, why would hibernate need to open a jdbc connection, statement and resultset if it is going to cache?

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

Are you doing this from a load/get, or from a query? If this is from a query, then there will be an SQL select issued. The session cache stored objects, indexed by mapping/entity name and id; it doesn't store query results. There's a separate query cache for that, and you have to enable that separately.

The objects that are constructed from the results of the query are put into the session cache, so further references to those objects (via load/get, or via assocications from other entities) will get the objects from the cache. If you also have the query cache turned on, then rerunning the same query with the same parameters will grab the cached entity IDs from the query cache, then go fetch the cached objects from the session cache. If either cache is disabled, then there will be a query to the DB.

wanton · **Joined:** Mon Oct 11, 2004 2:22 am **Posts:** 41

i use a query in this case because the query generally returns a list. i can't use load or get to return a list right?

does that mean i cannot take advantage of the session cache?

does that mean i have to explicitly enable the query cache (to enhance this request) .. how is that done?

i appologise for my lack of knowlege.

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

Yes, you can't use load or get to get a list.

You can take advantage of the session cache: you're doing it all the time. For example, if your list returns 100 entities, and each of those entities contains a reference to another entity, that other entity is loaded only once.

The query cache is explained in section 19 of the ref docs, it's just one extra line in your hibernate.cfg.xml or hibernate.properties file.

wanton · **Joined:** Mon Oct 11, 2004 2:22 am **Posts:** 41

thanks mate. i haven't given you all 3 credits just incase someone knows how to get the log entries for the cache insert, retrieve and expire events (if indeed that is possible).

wanton · **Joined:** Mon Oct 11, 2004 2:22 am **Posts:** 41

one last question for you tenwit: i've enabled the query cache as directed (i use many queries repeatedly) and now on startup i get the following log entries:

Code:

WARN  org.hibernate.cache.EhCacheProvider - Could not find configuration [org.hibernate.cache.UpdateTimestampsCache]; using defaults.
WARN  org.hibernate.cache.EhCacheProvider - Could not find configuration [org.hibernate.cache.StandardQueryCache]; using defaults.

I cannot find documentation regarding these configuration settings/files. Help is appreciated.

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

Those two caches are being checked at start up for customized configurations. There aren't any, so the default configuration is being used.

You can configure them, if you want, by creating ehcache.xml and putting it in your classpath (if you don't already have one). There's a sample one in the etc directory of the hibernate distribution. The full class names for those two classes are the cache names you'd use: you probably want the UpdateTimestampsCache to be write-through (maxElementsInMemory="1".. or even 0?), and the query cache to be large and fairly long-lived.

scarface · **Joined:** Sun Jun 04, 2006 1:58 am **Posts:** 136

May be you can try using statistics API to check for cache hits and misses

SessionFactory sessionFactory = getSessionFactoryForApplication();
Statistics stats = sessionFactory.getStatistics();
stats.setStatisticsEnabled(true);

http://www.hibernate.org/275.html

Quote:

http://www.hibernate.org/hib_docs/v3/api/org/hibernate/stat/Statistics.html

wanton · **Joined:** Mon Oct 11, 2004 2:22 am **Posts:** 41

thanks tenwit. i found details to solve my WARN log entry problem here.

the cache elements i've added to my ehcache.xml file:

Code:

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

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

Note that i have replaced net.sf.hibernate (in documentation) with org.hibernate.

I'm not 100% sure i have my size/age ratios correct. The document recommends a younger/smaller setting for timestamps but i've basically guessed that what it refers to as an underlying cache is my StandardQueryCache.

in the documentation (14.4.9) it suggests setting query.setCacheable(true) on queries .. is this necissary for the query cache to be used? if i don't set cacheable=true are queries never cached?

scarface, thanks for the suggestion. i will look into using the hibernate statistics.

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

Yes, to use the query cache you must both enable the cache in your config (hibernate.cache.use_query_cache=true), and turn it on for each query. For in-code queries, you do that using setCacheable(true). For named queries, you can do that, or use the cacheable="true" attribute of the <query> and <sql-query> elements.