Hello All,

I am facing a strange issue - help!!

I have 3 Domain objects, say, SMS, Destination and User

public class SMS {
...
...
private Destination destination;
getters/setters
}

public class Destination {
...
...
private User user;
getters/setters
}

public class User{
...
...
private String name;
getters/setters
}



I have applied 2nd level cache (and Query Cache) using EHCacheProvider on classes Destination and User. For the first time, when Destination#1 and User#1 is accessed - DB query is fired and objects are placed in Cache. Note that SMS is not being cached as there are too many inserts/updates on SMS and is rarely read.

Now, if I access Destination#1 and User#1 - they are served from Cache. However, if I fire and INSERT for SMS (destination as Destination#1 loaded via Hibernate) and then access Destination#1 and User#1, DB queries are fired and objects are not served form Cache. Ideally, Destination#1 and User#1 should be served from cache as there has been no UPDATE queries on them.

https://www.hibernate.org/hib_docs/v3/a ... tSource%29 says
performExecutions

protected void performExecutions(EventSource session)
throws HibernateException

Execute all SQL and second-level cache updates, in a special order so that foreign-key constraints cannot be violated:

1. Inserts, in the order they were performed
2. Updates
3. Deletion of collection elements
4. Insertion of collection elements
5. Deletes, in the order they were performed

Throws:
HibernateException


Any pointers would be really helpful!

Thanks,
Rajender

Hi Rajender,

could it be that in meantime the cache simply was expired?
Can you please attach:
- your ehcache.xml file
- a snippet of the source-code showing the sequence of actions
- specify if you declare SMS.destination to be loader LAZY or EAGER

Thanks for your reply! Here is the additional information

No, the cache is definitely not expiring as I am performing the operation within seconds.

<ehcache>

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

<defaultCache maxElementsInMemory="10000" eternal="false"
timeToIdleSeconds="120" timeToLiveSeconds="120" overflowToDisk="false"
maxElementsOnDisk="10000000" diskPersistent="false"
diskExpiryThreadIntervalSeconds="120" memoryStoreEvictionPolicy="LRU" />

<cache name="com.Destination"
maxElementsInMemory="10" eternal="false" timeToIdleSeconds="86400"
timeToLiveSeconds="0" overflowToDisk="false" />

<cache name="com.User"
maxElementsInMemory="5" eternal="false" timeToIdleSeconds="86400"
timeToLiveSeconds="0" overflowToDisk="false" />

</ehcache>

-------------------------

Sequence of Actions

- SELECT Destination#1 (via Query Cache)
- SELECT User#1
- INSERT SMS

----------------

<?xml version="1.0" encoding="utf-8"?>
<!DOCTYPE hibernate-mapping PUBLIC "-//Hibernate/Hibernate Mapping DTD//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping package="com">
<class name="com.SMS" table="sms">
<id name="id" type="long" column="sms_id">
<generator class="native" />
</id>
<property name="dateTime" column="datetime" type="timestamp" not-null="true"/>
<property name="from" column="smsfrom" type="string" length="20"/>
<property name="message" type="text" not-null="true"/>
<many-to-one name="destination" class="com.Destination" column="destination" not-null="true"/>
<property name="to" column="smsto" type="string" not-null="true" length="20"/>
</class>
</hibernate-mapping>

Can you give please more details about how you INSERT the new SMS and then access Destination#1 and User#1.

Please refer to the logs below. Now, if I execute the use case again - this time Destination#1 and User#1 DB queries shouldn't be fired but they do.


19:15:54,000 DEBUG [QueryTranslatorImpl] parse() - HQL: from com.Destination where destination =:destination
19:15:54,016 DEBUG [ErrorCounter] throwQueryException() : no errors
19:15:54,016 DEBUG [HqlSqlBaseWalker] select << begin [level=1, statement=select]
19:15:54,016 DEBUG [FromElement] FromClause{level=1} : com.Destination (no alias) -> destination0_
19:15:54,016 DEBUG [HqlSqlBaseWalker] select : finishing up [level=1, statement=select]
19:15:54,016 DEBUG [HqlSqlWalker] processQuery() : ( SELECT ( FromClause{level=1} destination destination0_ ) ( where ( = destination ? ) ) )
19:15:54,031 DEBUG [HqlSqlWalker] Derived SELECT clause created.
19:15:54,031 DEBUG [JoinProcessor] Using FROM fragment [destination destination0_]
19:15:54,031 DEBUG [HqlSqlBaseWalker] select >> end [level=1, statement=select]
19:15:54,031 DEBUG [ErrorCounter] throwQueryException() : no errors
19:15:54,031 DEBUG [QueryTranslatorImpl] HQL: from com.Destination where destination =:destination
19:15:54,031 DEBUG [QueryTranslatorImpl] SQL: select destination0_.destination_id as destination1_15_, destination0_.destination as destination15_, destination0_.user_id as user3_15_ from destination destination0_ where destination=?
19:15:54,031 DEBUG [ErrorCounter] throwQueryException() : no errors
19:15:54,047 DEBUG [StandardQueryCache] checking cached query results in region: org.hibernate.cache.StandardQueryCache
19:15:54,047 DEBUG [EhCache] key: sql: select destination0_.destination_id as destination1_15_, destination0_.destination as destination15_, destination0_.user_id as user3_15_ from destination destination0_ where destination=?; parameters: ; named parameters: {destination=13013}
19:15:54,047 DEBUG [EhCache] Element for sql: select destination0_.destination_id as destination1_15_, destination0_.destination as destination15_, destination0_.user_id as user3_15_ from destination destination0_ where destination=?; parameters: ; named parameters: {destination=13013} is null
19:15:54,047 DEBUG [StandardQueryCache] query results were not found in cache
19:15:54,063 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
19:15:54,063 DEBUG [ConnectionManager] opening JDBC connection
19:15:54,063 DEBUG [SQL]
select
destination0_.destination_id as destination1_15_,
destination0_.destination as destination15_,
destination0_.user_id as user3_15_
from
destination destination0_
where
destination=?
19:15:54,063 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
19:15:54,063 DEBUG [Loader] result row: EntityKey[com.Destination#1]
19:15:54,078 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
19:15:54,078 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
19:15:54,078 DEBUG [TwoPhaseLoad] resolving associations for [com.Destination#1]
19:15:54,094 DEBUG [TwoPhaseLoad] adding entity to second-level cache: [com.Destination#1]
19:15:54,109 DEBUG [EhCache] key: com.Destination#1
19:15:54,109 DEBUG [EhCache] Element for com.Destination#1 is null
19:15:54,109 DEBUG [TwoPhaseLoad] done materializing entity [com.Destination#1]
19:15:54,109 DEBUG [StatefulPersistenceContext] initializing non-lazy collections
19:15:54,109 DEBUG [StandardQueryCache] caching query results in region: org.hibernate.cache.StandardQueryCache; timestamp=5184755843645440
19:15:54,109 DEBUG [ConnectionManager] transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
19:15:54,109 DEBUG [SessionImpl] initializing proxy: [com.User#1]
19:15:54,109 DEBUG [EhCache] key: com.User#1
19:15:54,109 DEBUG [EhCache] Element for com.User#1 is null
19:15:54,109 DEBUG [Loader] loading entity: [com.User#1]
19:15:54,109 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
19:15:54,109 DEBUG [SQL]
select
user0_.user_id as user1_2_0_,
user0_.name as name2_0_,
user0_.code as code2_0_
from
user user0_
where
user0_.user_id=?
19:15:54,109 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
19:15:54,109 DEBUG [Loader] result row: EntityKey[com.User#1]
19:15:54,109 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
19:15:54,109 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
19:15:54,109 DEBUG [TwoPhaseLoad] resolving associations for [com.User#1]
19:15:54,109 DEBUG [TwoPhaseLoad] adding entity to second-level cache: [com.User#1]
19:15:54,109 DEBUG [EhCache] key: com.User#1
19:15:54,109 DEBUG [EhCache] Element for com.User#1 is null
19:15:54,109 DEBUG [TwoPhaseLoad] done materializing entity [com.User#1]
19:15:54,109 DEBUG [StatefulPersistenceContext] initializing non-lazy collections
19:15:54,109 DEBUG [Loader] done entity load
19:15:54,125 DEBUG [GwKannelServlet] SMS read from request - going to process the sms.
19:15:54,156 DEBUG [JDBCTransaction] begin
19:15:54,156 DEBUG [JDBCTransaction] current autocommit status: true
19:15:54,156 DEBUG [JDBCTransaction] disabling autocommit
19:15:54,203 DEBUG [AbstractSaveEventListener] executing identity-insert immediately
19:15:54,203 DEBUG [UpdateTimestampsCache] Pre-invalidating space [sms]
19:15:54,219 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
19:15:54,219 DEBUG [SQL]
insert
into
sms
(datetime, smsfrom, message, destination, smsto)
values
(?, ?, ?, ?, ?)
19:15:54,219 DEBUG [IdentifierGeneratorFactory] Natively generated identity: 10
19:15:54,219 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
19:15:54,219 DEBUG [AbstractFlushingEventListener] processing flush-time cascades
19:15:54,219 DEBUG [AbstractFlushingEventListener] dirty checking collections
19:15:54,235 DEBUG [AbstractFlushingEventListener] Flushed: 0 insertions, 0 updates, 0 deletions to 3 objects
19:15:54,235 DEBUG [AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
19:15:54,250 DEBUG [Printer] listing entities:
19:15:54,266 DEBUG [Printer] com.SMS{to=13013, message=GKP1X, id=10, destination=com.Destination#1, dateTime=2010-02-10 19:15:54, from=919560326022}
19:15:54,266 DEBUG [Printer] com.Destination{id=1, user=com.User#1, destination=13013}
19:15:54,266 DEBUG [Printer] com.User{id=1, name=Kannel user, code=KANNEL}
19:15:54,266 DEBUG [JDBCTransaction] commit
19:15:54,281 DEBUG [JDBCTransaction] re-enabling autocommit
19:15:54,281 DEBUG [JDBCTransaction] committed JDBC Connection
19:15:54,281 DEBUG [ConnectionManager] transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
19:15:54,281 DEBUG [UpdateTimestampsCache] Invalidating space [smsin], timestamp: 5184755934334976
19:15:54,281 DEBUG [SessionImpl] disconnecting session
19:15:54,281 DEBUG [ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
19:15:54,281 DEBUG [ConnectionManager] transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!

Hi,

please activate the the logging DEBUG also on class
UpdateTimestampsCache
and redo all INCLUSIVE THE re-access attempts to Destination#1 and User#1 and then post the whole logged output.

hi Raj,
Check out the sqls being fired when the insert is called. Check out post the insert of SMS, is there an update being fired on the DESTINATION ?
For the many to one collection, please try putting update=false in case there is the additional update query.

Thanks,
Deepak