I am trying to setup the Hibernate L2 cache in my application and I believe I have everything properly configured, however what I am finding is that most of the time Hibernate won't attempt to read data from the cache. After combing through the debug logs it appears that most of the time Hibernate will execute a query in sql and then place the results in the L2 cache, but it will never try and query the L2 cache beforehand.

Hibernate version: 3.0.5

Mapping documents:

<hibernate-mapping>

<class name="org.roller.pojos.RollerPropertyData" table="roller_properties" lazy="false">

<cache usage="read-write" />

<id name="name" column="name" type="java.lang.String">
<generator class="assigned" />
</id>

<property
name="value"
type="java.lang.String"
update="true"
insert="true"
column="value"
unique="false"
/>

</class>
</hibernate-mapping>

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

Session session = ((HibernateStrategy) mStrategy).getSession();
Criteria criteria = session.createCriteria(RollerPropertyData.class);
criteria.add(Expression.eq("name", name));
criteria.setMaxResults(1);
List list = criteria.list();
return (list.size()!= 0) ? (RollerPropertyData)list.get(0) : null;


Full stack trace of any exception that occurs:

Name and version of the database you are using:

The generated SQL (show_sql=true):

Debug level Hibernate log excerpt:

Based on the messages from my logs, why is Hibernate executing the sql statement below when it plainly shows that when it tries to do a ReadWriteCache.put() the object was already cached ...

DEBUG 2006-03-01 11:05:46,867 PersistenceSessionFilter:doFilter - Entered PersistenceSessionFilter
DEBUG 2006-03-01 11:05:49,260 SessionImpl:<init> - opened session at timestamp: 4674518832168960
DEBUG 2006-03-01 11:05:49,284 AbstractBatcher:logOpenPreparedStatement - about to open
PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG 2006-03-01 11:05:49,284 ConnectionManager:openConnection - opening JDBC connection
DEBUG 2006-03-01 11:05:49,285 AbstractBatcher:log - select this_.name as name0_, this_.value as value18_0_ from roller_properties this_ where this_.name=? limit ?
DEBUG 2006-03-01 11:05:49,286 AbstractBatcher:getPreparedStatement - preparing statement
DEBUG 2006-03-01 11:05:49,286 NullableType:nullSafeSet - binding 'pings.suspendPingProcessing' to parameter: 1
DEBUG 2006-03-01 11:05:49,287 AbstractBatcher:logOpenResults - about to open ResultSet
(open ResultSets: 0, globally: 0)
DEBUG 2006-03-01 11:05:49,287 Loader:doQuery - processing result set
DEBUG 2006-03-01 11:05:49,288 Loader:doQuery - result set row: 0
DEBUG 2006-03-01 11:05:49,288 NullableType:nullSafeGet - returning 'pings.suspendPingProcessing' as column: name0_
DEBUG 2006-03-01 11:05:49,288 Loader:getRow - result row: EntityKey[org.roller.pojos.RollerPropertyData#pings.suspendPingProcessing]
DEBUG 2006-03-01 11:05:49,289 Loader:loadFromResultSet - Initializing object from ResultSet: [org.roller.pojos.RollerPropertyData#pings.suspendPingProcessing]
DEBUG 2006-03-01 11:05:49,289 BasicEntityPersister:hydrate - Hydrating entity: [org.roller.pojos.RollerPropertyData#pings.suspendPingProcessing]
DEBUG 2006-03-01 11:05:49,289 NullableType:nullSafeGet - returning 'true' as column: value18_0_
DEBUG 2006-03-01 11:05:49,290 Loader:doQuery - done processing result set (1 rows)
DEBUG 2006-03-01 11:05:49,290 AbstractBatcher:logCloseResults - about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG 2006-03-01 11:05:49,291 AbstractBatcher:logClosePreparedStatement - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG 2006-03-01 11:05:49,291 AbstractBatcher:closePreparedStatement - closing statement
DEBUG 2006-03-01 11:05:49,291 Loader:initializeEntitiesAndCollections - total objects hydrated: 1
DEBUG 2006-03-01 11:05:49,292 TwoPhaseLoad:initializeEntity - resolving associations for [org.roller.pojos.RollerPropertyData#pings.suspendPingProcessing]
DEBUG 2006-03-01 11:05:49,293 TwoPhaseLoad:initializeEntity - adding entity to second-level cache: [org.roller.pojos.RollerPropertyData#pings.suspendPingProcessing]
DEBUG 2006-03-01 11:05:49,293 ReadWriteCache:put - Caching: org.roller.pojos.RollerPropertyData#pings.suspendPingProcessing
DEBUG 2006-03-01 11:05:49,293 EhCache:get - key: org.roller.pojos.RollerPropertyData#pings.suspendPingProcessing
DEBUG 2006-03-01 11:05:49,294 ReadWriteCache:put - Item was already cached: org.roller.pojos.RollerPropertyData#pings.suspendPingProcessing
DEBUG 2006-03-01 11:05:49,295 TwoPhaseLoad:initializeEntity - done materializing entity [org.roller.pojos.RollerPropertyData#pings.suspendPingProcessing]
DEBUG 2006-03-01 11:05:49,295 PersistenceContext:initializeNonLazyCollections - initializing non-lazy collections
DEBUG 2006-03-01 11:05:49,296 JDBCContext:afterNontransactionalQuery - after autocommitDEBUG 2006-03-01 11:05:49,296 SessionImpl:afterTransactionCompletion - after transaction completion
DEBUG 2006-03-01 11:05:49,297 RollerRuntimeConfig:getProperty - fetched property [pings.suspendPingProcessing=true]


the first and last lines are from my application and the last line is just reporting that it successfully retrieved the object it wanted. the problem is that it had to go the database despite the fact that the object was already in the L2 cache.

i am still somewhat new to hibernate and i have read over the docs about caching a few times but can't see any reason why my code is not working. the cache *is* working, it's just that hibernate doesn't seem to want to read from the cache.

any help is appreciated.

see:
http://forum.hibernate.org/viewtopic.php?t=956099&highlight=

basically tell your criteria to cache it...

Criteria setCacheMode(CacheMode cacheMode)
Override the cache mode
Criteria setCacheRegion(String cacheRegion)
Set the name of the cache region.

nope, still no dice.

I had already checked that the session CacheMode was NORMAL before creating the criteria or running the query, so I was pretty sure that wasn't the problem. I would also be very disappointed if you had to manually set the "cachable" flag for every query you run.

In any case, that didn't resolve the situation. I still only see calls to ReadWriteCache.put() and never a call to ReadWriteCache.get()

In my recent app I got it working by:
1) setting up hibernate.properties to turn on L2
2) setting the class files & the collections (as needed) w/cache="read-only"
3) and doing the query cache settings as I showed

I also ran statistics to see that it was all working properly.

okay, but like I said, I have done all of those things and it still isn't working for me, so something else must be causing the problem which you didn't encounter in your setup.

i don't believe there is any problem with the L2 cache itself. my logs clearly show that Hibernate detected the proper L2 cache settings, enabled the cache, and it has started up correctly. the problem, AFAIK, is originating because Hibernate doesn't seem to issue a ReadWriteCache.get() call *before* actually fetching data from the db. After the data has been fetched it seems to be writing it to the L2 cache quite happily.

this is from my Hibernate initialization ...

INFO 2006-03-01 15:34:18,196 Configuration:configure - configuring from resource: /hibernate.cfg.xml
INFO 2006-03-01 15:34:18,197 Configuration:getConfigurationInputStream - Configuration resource: /hibernate.cfg.xml
DEBUG 2006-03-01 15:34:18,258 DTDEntityResolver:resolveEntity - trying to locate http://hibernate.sourceforge.net/hibern ... on-3.0.dtd in classpath under org/hibernate/
DEBUG 2006-03-01 15:34:18,271 DTDEntityResolver:resolveEntity - found http://hibernate.sourceforge.net/hibern ... on-3.0.dtd in classpath
DEBUG 2006-03-01 15:34:18,355 Configuration:addProperties - show_sql=false
DEBUG 2006-03-01 15:34:18,359 Configuration:addProperties - connection.datasource=java:comp/env/jdbc/rollerdb
DEBUG 2006-03-01 15:34:18,360 Configuration:addProperties - dialect=org.hibernate.dialect.MySQLDialect
DEBUG 2006-03-01 15:34:18,361 Configuration:addProperties - hibernate.cache.provider_class=org.hibernate.cache.EhCacheProvider
DEBUG 2006-03-01 15:34:18,361 Configuration:addProperties - hibernate.generate_statistics=true
DEBUG 2006-03-01 15:34:18,362 Configuration:addProperties - hibernate.cache.use_structured_entries=true

... lots of mapping lines ...

DEBUG 2006-03-01 15:34:20,065 Configuration:parseMappingElement - null<-org.dom4j.tree.DefaultAttribute@10e434d [Attribute: name resource value "org/roller/pojos/RollerPropertyData.hbm.xml"]
INFO 2006-03-01 15:34:20,066 Configuration:addResource - Mapping resource: org/roller/pojos/RollerPropertyData.hbm.xml
DEBUG 2006-03-01 15:34:20,068 DTDEntityResolver:resolveEntity - trying to locate http://hibernate.sourceforge.net/hibern ... ng-3.0.dtd in classpath under org/hibernate/
DEBUG 2006-03-01 15:34:20,069 DTDEntityResolver:resolveEntity - found http://hibernate.sourceforge.net/hibern ... ng-3.0.dtd in classpath
INFO 2006-03-01 15:34:20,078 HbmBinder:bindRootPersistentClassCommonValues - Mapping class: org.roller.pojos.RollerPropertyData -> roller_properties
DEBUG 2006-03-01 15:34:20,079 HbmBinder:bindProperty - Mapped property: name -> name
DEBUG 2006-03-01 15:34:20,080 HbmBinder:bindProperty - Mapped property: value -> value

... etc, etc ...

INFO 2006-03-01 15:34:20,400 SettingsFactory:buildSettings - Second-level cache: enabled
INFO 2006-03-01 15:34:20,401 SettingsFactory:buildSettings - Query cache: disabled
INFO 2006-03-01 15:34:20,404 SettingsFactory:createCacheProvider - Cache provider: org.hibernate.cache.EhCacheProvider
INFO 2006-03-01 15:34:20,408 SettingsFactory:buildSettings - Optimize cache for minimal puts: disabled
INFO 2006-03-01 15:34:20,409 SettingsFactory:buildSettings - Structured second-level cache entries: enabled
DEBUG 2006-03-01 15:34:20,412 SQLExceptionConverterFactory:buildSQLExceptionConverter - Using dialect defined converter
INFO 2006-03-01 15:34:20,421 SettingsFactory:buildSettings - Statistics: enabled
INFO 2006-03-01 15:34:20,422 SettingsFactory:buildSettings - Deleted entity synthetic
identifier rollback: disabled
INFO 2006-03-01 15:34:20,424 SettingsFactory:buildSettings - Default entity-mode: pojoINFO 2006-03-01 15:34:20,542 SessionFactoryImpl:<init> - building session factory
DEBUG 2006-03-01 15:34:20,543 SessionFactoryImpl:<init> - Session factory constructed with filter configurations : {}

... more and more ...

DEBUG 2006-03-01 15:34:21,161 CacheFactory:createCache - instantiating cache region: org.roller.pojos.RollerPropertyData usage strategy: read-write
DEBUG 2006-03-01 15:34:21,169 BasicEntityPersister:logStaticSQL - Static SQL for entity: org.roller.pojos.RollerPropertyData
DEBUG 2006-03-01 15:34:21,172 BasicEntityPersister:logStaticSQL - Version select: select name from roller_properties where name =?
DEBUG 2006-03-01 15:34:21,173 BasicEntityPersister:logStaticSQL - Snapshot select: select rollerprop_.name, rollerprop_.value as value18_ from roller_properties rollerprop_
where rollerprop_.name=?
DEBUG 2006-03-01 15:34:21,174 BasicEntityPersister:logStaticSQL - Insert 0: insert into roller_properties (value, name) values (?, ?)
DEBUG 2006-03-01 15:34:21,174 BasicEntityPersister:logStaticSQL - Update 0: update roller_properties set value=? where name=?
DEBUG 2006-03-01 15:34:21,175 BasicEntityPersister:logStaticSQL - Delete 0: delete from roller_properties where name=?

... again ...

DEBUG 2006-03-01 15:34:22,068 SessionFactoryObjectFactory:<clinit> - initializing class SessionFactoryObjectFactory
DEBUG 2006-03-01 15:34:22,072 SessionFactoryObjectFactory:addInstance - registered: 0112f2dd09b8297e0109b82984720000 (unnamed)
INFO 2006-03-01 15:34:22,073 SessionFactoryObjectFactory:addInstance - Not binding factory to JNDI, no JNDI name configured
DEBUG 2006-03-01 15:34:22,073 SessionFactoryImpl:<init> - instantiated session factory
INFO 2006-03-01 15:34:22,074 SessionFactoryImpl:checkNamedQueries - Checking 0 named queries
INFO 2006-03-01 15:34:22,082 RollerFactory:setRoller - Using Roller Impl: org.roller.business.hibernate.HibernateRollerImpl
DEBUG 2006-03-01 15:34:22,148 SessionImpl:<init> - opened session at timestamp: 4674584830291968
DEBUG 2006-03-01 15:34:22,175 AbstractBatcher:logOpenPreparedStatement - about to open
PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG 2006-03-01 15:34:22,176 ConnectionManager:openConnection - opening JDBC connection
DEBUG 2006-03-01 15:34:22,177 AbstractBatcher:log - select this_.name as name0_, this_.value as value18_0_ from roller_properties this_
DEBUG 2006-03-01 15:34:22,178 AbstractBatcher:getPreparedStatement - preparing statement
DEBUG 2006-03-01 15:34:22,205 AbstractBatcher:logOpenResults - about to open ResultSet
(open ResultSets: 0, globally: 0)
DEBUG 2006-03-01 15:34:22,207 Loader:doQuery - processing result set
DEBUG 2006-03-01 15:34:22,208 Loader:doQuery - result set row: 0
DEBUG 2006-03-01 15:34:22,209 NullableType:nullSafeGet - returning 'pings.suspendPingProcessing' as column: name0_
DEBUG 2006-03-01 15:34:22,212 Loader:getRow - result row: EntityKey[org.roller.pojos.RollerPropertyData#pings.suspendPingProcessing]
DEBUG 2006-03-01 15:34:22,213 Loader:loadFromResultSet - Initializing object from ResultSet: [org.roller.pojos.RollerPropertyData#pings.suspendPingProcessing]
DEBUG 2006-03-01 15:34:22,223 BasicEntityPersister:hydrate - Hydrating entity: [org.roller.pojos.RollerPropertyData#pings.suspendPingProcessing]
DEBUG 2006-03-01 15:34:22,224 NullableType:nullSafeGet - returning 'true' as column: value18_0_


maybe i'm not reading the log files correctly, but it looks like everything initializes properly to me. then as you can see, immediately after the session factory is finished initializing it does a query without ever consulting the L2 cache. why?

doesn't look like the query cache is setup... put this in your hibernate.properties.

hibernate.cache.use_query_cache=true

well, i didn't have the query cache enabled because i didn't believe that would help things. the query cache works separately from the object cache. From the hibernate docs ...

"Most queries do not benefit from caching, so by default queries are not cached. To enable caching, call Query.setCacheable(true). This call allows the query to look for existing cache results or add its results to the cache when it is executed."

in any case i tried enabling the query cache, but it didn't change things.

DEBUG 2006-03-01 20:09:39,165 SessionImpl:<init> - opened session at timestamp:
4674652484255744
DEBUG 2006-03-01 20:09:39,166 StandardQueryCache:get - checking cached query res
ults in region: org.hibernate.cache.StandardQueryCache
DEBUG 2006-03-01 20:09:39,168 EhCache:get - key: sql: select this_.name as name0
_, this_.value as value18_0_ from roller_properties this_ where this_.name=?; pa
rameters: site.shortName, ; max rows: 1
DEBUG 2006-03-01 20:09:39,169 EhCache:get - Element for sql: select this_.name a
s name0_, this_.value as value18_0_ from roller_properties this_ where this_.nam
e=?; parameters: site.shortName, ; max rows: 1 is null
DEBUG 2006-03-01 20:09:39,170 StandardQueryCache:get - query results were not fo
und in cache
DEBUG 2006-03-01 20:09:39,171 AbstractBatcher:logOpenPreparedStatement - about t
o open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG 2006-03-01 20:09:39,173 ConnectionManager:openConnection - opening JDBC co
nnection
DEBUG 2006-03-01 20:09:39,175 AbstractBatcher:log - select this_.name as name0_,
this_.value as value18_0_ from roller_properties this_ where this_.name=? limit
?

at least the query cache tried to lookup the cache entry before going to the database. now if only the ReadWriteCache would do the same thing I would be in great shape.

Yes it is separate, but query cache works hand-in-hand with 2nd level. I do read-only caching of objects and then use a 'select' strategy to join up my data which works great!

I guess at this point I would ask a few questions of you:

1) what is your desired caching strategy (briefly for one of your classes)
2) please explain your architectural reasons for your caching strategy
3) post the appropriate portions of your caching configs
& post your java code to store and load/read the cached items.

And I'll see what I can do... to help.

ok, well maybe you can tell me exactly how you did that and i can see if using the same settings accomplishes what i need.




1. I want to cache all of the actual pojo objects which my application uses, the same objects which are persisted by hibernate. I don't run the same exact query very often at all, however I reuse the same objects over and over again.

2. huh? The reason is for speed. Rather than fetching objects from the database all the time I want them kept in memory.

3. i don't understand this at all, i have already covered my caching configs earlier in the thread. i don't have caching specific code, hibernate is supposed to handle the details of the object level caching itself.

fairly dangerous if you ask me... your JVM will become the database itself.
Hibernate caching is really meant for relatively small data sets (relative to the overall footprint of your dataset and machine/memory size, I'd suspect).


usually, different kinds of data require different caching policies. And if you are using "caching" for everything it may slow you down if not configured properly or used properly in your application


second level cache is configurable at the granularity of class or collection.

Well, I have worked on many applications in the past which do object level caching and it makes a big improvement. I am not at all scared of using up my jvm memory, I have tons of memory that I can access.

What is far more dangerous is the amount of database traffic that Hibernate generates. This is still the first project I am using with Hibernate and I have inherited most of the code, so I am still learning about Hibernate, but if it can't do a reasonable job at object level caching then I will happily ditch it.

I understand quite a lot about caching and feel plenty confident about my desire for object level caching. In any case, challenging my desire for caching is not really helping me solve my problem. I have a techincal problem with Hibernate where the L2 cache does not seem to be working properly and I am asking for help on how to solve that issue.

Greets,

Have you tried plain hql queries like Query q = session.createQuery("select xyz from abc as ced where etc..")

We are using Jboss jndi bound Hibernate sessionfactory and let sessionfactory to obtain jdbc connection to db (our stupid coder error first was that we supplied jdbc connection for sessionfactory.opensession() and second level cache was invalidated)

No problems w/ 2nd cache (ehcache), and we are using agressive caching strategy w/tens of thousands objects (4gig per virtual machine to use as memory is cheap nowadays)

--PO

alleng, you have only given the caching that you are doing for the entity itself? are you accessing the entities with Load? or by Query? or are you looking for caching with the collections? These are all separate issues.
This is why I was asking for a test case...

Putting <cache usage="read-write"> in your entity simply lets hibernate know that you'd like to cache and access by load (by id) or by navigation to that entity. if you put <cache usage="read-write"> in your collection tags, then you are now caching the relationship. If you are trying to to Queries then you should work with the Query cache.

Realize that using a read-only strategy is the fastest for query/access performance - you should not cache for OLTP apps, since that will probably kill your performance. Not trying to challenge your skills with caching architectures, but rather help w/ hibernate...

I hope this helps.

drooler: we currently use the Criteria class because that's how the original authors wanted to do it. i don't know know, using hql looks fine to me, but that's how they did it. i can try using hql to see if that helps.

question though, did you have to do anything more than add <cache usage="read-write"> to you class elements to get what you wanted? i am certainly wondering if my hbm files aren't properly setup.


jt_1000: well, i would think that caching the entity itself would have worked in my above examples considering i am looking up the object by id. in truth, i'm not sure i understand how caching entities versus collections is different at this point.

So how about this, lets reset things and try starting from the beginning because my current application was a hand me down and has quite a bit of code/config which may be clouding the issue. I tried creating a new test application so that I can figure this out and I still can't get any L2 caching to work in that app. I just want to work on a single object at first, then build from there. Here's what I have ...

Hibernate version: 3.0.5

Mapping documents:
<hibernate-configuration>

<session-factory>

<property name="connection.datasource">java:comp/env/jdbc/test</property>
<property name="show_sql">true</property>
<property name="dialect">org.hibernate.dialect.MySQLDialect</property>

<property name="hibernate.cache.provider_class">org.hibernate.cache.HashtableCacheProvider</property>
<property name="hibernate.generate_statistics">true</property>
<property name="hibernate.cache.use_structured_entries">true</property>

<!-- Mapping files -->
<mapping resource="com/sun/wpe/test/Pojo.hbm.xml"/>

</session-factory>

</hibernate-configuration>

<hibernate-mapping>
<class name="com.sun.wpe.test.Pojo" table="pojo">

<cache usage="read-write" />

<id name="field1" column="field1" type="java.lang.String" unsaved-value="undefined">
<generator class="assigned"/>
</id>

<property name="field2" type="java.lang.String"
update="true" insert="true" column="field2" unique="true"/>

<property name="field3" type="java.lang.String"
update="true" insert="true" column="field3" unique="true"/>

</class>
</hibernate-mapping>


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

Transaction tx = session.beginTransaction();
Pojo pojo = (Pojo) session.load(Pojo.class, id);
tx.commit();

note, this is wrapped in a simple method called getPojo(id) which is called when i do my test.


Full stack trace of any exception that occurs:

Name and version of the database you are using:

The generated SQL (show_sql=true):

Debug level Hibernate log excerpt:

INFO 2006-03-02 16:24:44,705 Environment:<clinit> - Hibernate 3.0.5
INFO 2006-03-02 16:24:44,711 Environment:<clinit> - hibernate.properties not found
INFO 2006-03-02 16:24:44,714 Environment:<clinit> - using CGLIB reflection optimizer
INFO 2006-03-02 16:24:44,719 Environment:<clinit> - using JDK 1.4 java.sql.Timestamp handling
INFO 2006-03-02 16:24:44,799 Configuration:configure - configuring from resource: /hibernate.cfg.xml
INFO 2006-03-02 16:24:44,801 Configuration:getConfigurationInputStream - Configuration resource: /hibernate.cfg.xml
DEBUG 2006-03-02 16:24:44,852 DTDEntityResolver:resolveEntity - trying to locate http://hibernate.sourceforge.net/hibern ... on-3.0.dtd in classpath under org/hibernate/
DEBUG 2006-03-02 16:24:44,870 DTDEntityResolver:resolveEntity - found http://hibernate.sourceforge.net/hibern ... on-3.0.dtd in classpath
DEBUG 2006-03-02 16:24:44,918 Configuration:addProperties - connection.datasource=java:comp/env/jdbc/test
DEBUG 2006-03-02 16:24:44,919 Configuration:addProperties - show_sql=true
DEBUG 2006-03-02 16:24:44,923 Configuration:addProperties - dialect=org.hibernate.dialect.MySQLDialect
DEBUG 2006-03-02 16:24:44,924 Configuration:addProperties - hibernate.cache.provider_class=org.hibernate.cache.HashtableCacheProvider
DEBUG 2006-03-02 16:24:44,925 Configuration:addProperties - hibernate.generate_statistics=true
DEBUG 2006-03-02 16:24:44,926 Configuration:addProperties - hibernate.cache.use_structured_entries=true
DEBUG 2006-03-02 16:24:44,928 Configuration:parseMappingElement - null<-org.dom4j.tree.DefaultAttribute@827968 [Attribute: name resource value "com/sun/wpe/test/Pojo.hbm.xml"]
INFO 2006-03-02 16:24:44,929 Configuration:addResource - Mapping resource: com/sun/wpe/test/Pojo.hbm.xml
DEBUG 2006-03-02 16:24:44,931 DTDEntityResolver:resolveEntity - trying to locate http://hibernate.sourceforge.net/hibern ... ng-3.0.dtd in classpath under org/hibernate/
DEBUG 2006-03-02 16:24:44,935 DTDEntityResolver:resolveEntity - found http://hibernate.sourceforge.net/hibern ... ng-3.0.dtd in classpath
INFO 2006-03-02 16:24:45,074 HbmBinder:bindRootPersistentClassCommonValues - Mapping class: com.sun.wpe.test.Pojo -> pojo
DEBUG 2006-03-02 16:24:45,082 HbmBinder:bindProperty - Mapped property: field1 -> field1
DEBUG 2006-03-02 16:24:45,097 HbmBinder:bindProperty - Mapped property: field2 -> field2
DEBUG 2006-03-02 16:24:45,099 HbmBinder:bindProperty - Mapped property: field3 -> field3
INFO 2006-03-02 16:24:45,100 Configuration:doConfigure - Configured SessionFactory: null
DEBUG 2006-03-02 16:24:45,104 Configuration:buildSessionFactory - Preparing to build session factory with filters : {}
INFO 2006-03-02 16:24:45,160 Configuration:secondPassCompile - processing extends queue
INFO 2006-03-02 16:24:45,170 Configuration:secondPassCompile - processing collection mappings
INFO 2006-03-02 16:24:45,171 Configuration:secondPassCompile - processing association property references
INFO 2006-03-02 16:24:45,172 Configuration:secondPassCompile - processing foreign key constraints
INFO 2006-03-02 16:24:45,318 NamingHelper:getInitialContext - JNDI InitialContext properties:{}
INFO 2006-03-02 16:24:45,338 DatasourceConnectionProvider:configure - Using datasource: java:comp/env/jdbc/test
INFO 2006-03-02 16:24:45,566 SettingsFactory:buildSettings - RDBMS: MySQL, version: 4.1.10-standard
INFO 2006-03-02 16:24:45,568 SettingsFactory:buildSettings - JDBC driver: MySQL-AB JDBC Driver, version: mysql-connector-java-3.0.14-production ( $Date: 2004/04/24 15:49:43 $, $Revision: 1.27.2.39 $ )
INFO 2006-03-02 16:24:45,597 Dialect:<init> - Using dialect: org.hibernate.dialect.MySQLDialect
INFO 2006-03-02 16:24:45,609 TransactionFactoryFactory:buildTransactionFactory - Using default transaction strategy (direct JDBC transactions)
INFO 2006-03-02 16:24:45,613 TransactionManagerLookupFactory:getTransactionManagerLookup - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
INFO 2006-03-02 16:24:45,625 SettingsFactory:buildSettings - Automatic flush during beforeCompletion(): disabled
INFO 2006-03-02 16:24:45,626 SettingsFactory:buildSettings - Automatic session close at end of transaction: disabled
INFO 2006-03-02 16:24:45,627 SettingsFactory:buildSettings - JDBC batch size: 15
INFO 2006-03-02 16:24:45,628 SettingsFactory:buildSettings - JDBC batch updates for versioned data: disabled
INFO 2006-03-02 16:24:45,632 SettingsFactory:buildSettings - Scrollable result sets: enabled
DEBUG 2006-03-02 16:24:45,632 SettingsFactory:buildSettings - Wrap result sets: disabled
INFO 2006-03-02 16:24:45,633 SettingsFactory:buildSettings - JDBC3 getGeneratedKeys(): enabled
INFO 2006-03-02 16:24:45,634 SettingsFactory:buildSettings - Connection release mode: null
INFO 2006-03-02 16:24:45,636 SettingsFactory:buildSettings - Maximum outer join fetch depth: 2
INFO 2006-03-02 16:24:45,637 SettingsFactory:buildSettings - Default batch fetch size: 1
INFO 2006-03-02 16:24:45,639 SettingsFactory:buildSettings - Generate SQL with comments: disabled
INFO 2006-03-02 16:24:45,640 SettingsFactory:buildSettings - Order SQL updates by primary key: disabled
INFO 2006-03-02 16:24:45,641 SettingsFactory:createQueryTranslatorFactory - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
INFO 2006-03-02 16:24:45,645 ASTQueryTranslatorFactory:<init> - Using ASTQueryTranslatorFactory
INFO 2006-03-02 16:24:45,646 SettingsFactory:buildSettings - Query language substitutions: {}
INFO 2006-03-02 16:24:45,646 SettingsFactory:buildSettings - Second-level cache: enabled
INFO 2006-03-02 16:24:45,649 SettingsFactory:buildSettings - Query cache: disabled
INFO 2006-03-02 16:24:45,650 SettingsFactory:createCacheProvider - Cache provider: org.hibernate.cache.HashtableCacheProvider
INFO 2006-03-02 16:24:45,652 SettingsFactory:buildSettings - Optimize cache for minimal puts: disabled
INFO 2006-03-02 16:24:45,653 SettingsFactory:buildSettings - Structured second-level cache entries: enabled
DEBUG 2006-03-02 16:24:45,655 SQLExceptionConverterFactory:buildSQLExceptionConverter - Using dialect defined converter
INFO 2006-03-02 16:24:45,673 SettingsFactory:buildSettings - Echoing all SQL to stdoutINFO 2006-03-02 16:24:45,674 SettingsFactory:buildSettings - Statistics: enabled
INFO 2006-03-02 16:24:45,675 SettingsFactory:buildSettings - Deleted entity synthetic identifier rollback: disabled
INFO 2006-03-02 16:24:45,677 SettingsFactory:buildSettings - Default entity-mode: pojoINFO 2006-03-02 16:24:45,826 SessionFactoryImpl:<init> - building session factory
DEBUG 2006-03-02 16:24:45,830 SessionFactoryImpl:<init> - Session factory constructed with filter configurations : {}
DEBUG 2006-03-02 16:24:45,864 CacheFactory:createCache - instantiating cache region: com.sun.wpe.test.Pojo usage strategy: read-write
DEBUG 2006-03-02 16:24:46,246 BasicEntityPersister:logStaticSQL - Static SQL for entity: com.sun.wpe.test.Pojo
DEBUG 2006-03-02 16:24:46,247 BasicEntityPersister:logStaticSQL - Version select: select field1 from pojo where field1 =?
DEBUG 2006-03-02 16:24:46,251 BasicEntityPersister:logStaticSQL - Snapshot select: select pojo_.field1, pojo_.field2 as field2_0_, pojo_.field3 as field3_0_ from pojo pojo_ where pojo_.field1=?
DEBUG 2006-03-02 16:24:46,252 BasicEntityPersister:logStaticSQL - Insert 0: insert into pojo (field2, field3, field1) values (?, ?, ?)
DEBUG 2006-03-02 16:24:46,253 BasicEntityPersister:logStaticSQL - Update 0: update pojo set field2=?, field3=? where field1=?
DEBUG 2006-03-02 16:24:46,254 BasicEntityPersister:logStaticSQL - Delete 0: delete from pojo where field1=?
DEBUG 2006-03-02 16:24:46,279 EntityLoader:<init> - Static select for entity com.sun.wpe.test.Pojo: select pojo0_.field1 as field1_0_, pojo0_.field2 as field2_0_0_, pojo0_.field3 as field3_0_0_ from pojo pojo0_ where pojo0_.field1=?
DEBUG 2006-03-02 16:24:46,280 EntityLoader:<init> - Static select for entity com.sun.wpe.test.Pojo: select pojo0_.field1 as field1_0_, pojo0_.field2 as field2_0_0_, pojo0_.field3 as field3_0_0_ from pojo pojo0_ where pojo0_.field1=?
DEBUG 2006-03-02 16:24:46,281 EntityLoader:<init> - Static select for entity com.sun.wpe.test.Pojo: select pojo0_.field1 as field1_0_, pojo0_.field2 as field2_0_0_, pojo0_.field3 as field3_0_0_ from pojo pojo0_ where pojo0_.field1=? for update
DEBUG 2006-03-02 16:24:46,282 EntityLoader:<init> - Static select for entity com.sun.wpe.test.Pojo: select pojo0_.field1 as field1_0_, pojo0_.field2 as field2_0_0_, pojo0_.field3 as field3_0_0_ from pojo pojo0_ where pojo0_.field1=? for update
DEBUG 2006-03-02 16:24:46,287 SessionFactoryObjectFactory:<clinit> - initializing class SessionFactoryObjectFactory
DEBUG 2006-03-02 16:24:46,309 SessionFactoryObjectFactory:addInstance - registered: 0112f2dd09bd7e030109bd7e05cd0000 (unnamed)
INFO 2006-03-02 16:24:46,310 SessionFactoryObjectFactory:addInstance - Not binding factory to JNDI, no JNDI name configured
DEBUG 2006-03-02 16:24:46,311 SessionFactoryImpl:<init> - instantiated session factory
INFO 2006-03-02 16:24:46,312 SessionFactoryImpl:checkNamedQueries - Checking 0 named queries




DEBUG 2006-03-02 16:33:18,306 SessionImpl:<init> - opened session at timestamp: 4674953209057280
DEBUG 2006-03-02 16:33:18,307 JDBCTransaction:begin - begin
DEBUG 2006-03-02 16:33:18,307 ConnectionManager:openConnection - opening JDBC connection
DEBUG 2006-03-02 16:33:18,308 JDBCTransaction:begin - current autocommit status: true
DEBUG 2006-03-02 16:33:18,312 JDBCTransaction:begin - disabling autocommit
DEBUG 2006-03-02 16:33:18,313 DefaultLoadEventListener:proxyOrLoad - loading entity: [com.sun.wpe.test.Pojo#abc]
DEBUG 2006-03-02 16:33:18,314 DefaultLoadEventListener:createProxyIfNecessary - creating new proxy for entity
DEBUG 2006-03-02 16:33:18,315 JDBCTransaction:commit - commit
DEBUG 2006-03-02 16:33:18,316 SessionImpl:managedFlush - automatically flushing sessionDEBUG 2006-03-02 16:33:18,317 JDBCContext:beforeTransactionCompletion - before transaction completion
DEBUG 2006-03-02 16:33:18,320 SessionImpl:beforeTransactionCompletion - before transaction completion
DEBUG 2006-03-02 16:33:18,321 JDBCTransaction:toggleAutoCommit - re-enabling autocommitDEBUG 2006-03-02 16:33:18,322 JDBCTransaction:commit - committed JDBC Connection
DEBUG 2006-03-02 16:33:18,322 JDBCContext:afterTransactionCompletion - after transaction completion
DEBUG 2006-03-02 16:33:18,323 SessionImpl:afterTransactionCompletion - after transaction completion
DEBUG 2006-03-02 16:33:18,324 SessionImpl:close - closing session
DEBUG 2006-03-02 16:33:18,325 ConnectionManager:closeConnection - closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
DEBUG 2006-03-02 16:33:18,328 JDBCContext:afterTransactionCompletion - after transaction completion
DEBUG 2006-03-02 16:33:18,329 SessionImpl:afterTransactionCompletion - after transaction completion



this application is dead simple. it contains only only a few classes, and just 1 object which i am trying to retrieve. so why isn't the caching working?

first of all, according to the docs, HashtableCache provider is not intended for production use... so there may be something there... Use ehCache

Next - from the logs it shows you are just startup up a fresh jvm (with SF, Session..etc.). So code like this doesn't make any sense - it will only load the object from db if it doesn't exist in your session and next 2nd level cache.



Also commit is not needed on loads.

Do something like this: