Hello all,

I'm trying to figure out optimal strategy for using Hibernate (Hibernate 2.1.2 with EHCache in Jboss 3.2.2 with Oracle 9.2.0.4 -) instead of entity beans. My application's architecture is based on message processing. Each message belongs to certain user session. Messages can come one by one or a few in burst. When they came in burst, they have to be processed one by one, order doesn't matter, but no two messages for same session at same time.

What I'm trying to achieve:
- Locking: When an user session is involved in processing of a message, other messages may not acquire this session until processing of first message is over.
- Caching: User session is cached and not extracted from database on every hit. The reason: user session has rather complicated business object graph inside which is expensive to serialize/deserialize.


The following is basic sequence of interactions with Hibernate (actual code is spread over many classes):

-----------------------------------------------------------------------
Session session = factory.openSession();
Transaction transaction = session.beginTransaction();

OperatorSession userSession = session.load(OperatorSession.class, id); // LockMode can be used here also

// do a lot of stuff with userSession

session.flush();
transaction.commit();
session.close();
-----------------------------------------------------------------------


In short, just as Entity beans are supposed to behave with pessimistic locking.

So what I want is that load() blocks if the same id is used from different threads; in the same time load() doesn't cause hit to database if session is already in cache.


What I've tried so far:
-----------------------------------------------------------------------
load() with LockMode.UPGRADE - locking works, but every time 'select ... for update' is executed, thus caching doesn't work, example log below:
-----------------------------------------------------------------------
2004-04-20 12:50:36,114 DEBUG SessionImpl - opened session
2004-04-20 12:50:36,114 DEBUG JDBCTransaction - begin
2004-04-20 12:50:36,114 DEBUG JDBCTransaction - current autocommit status:true
2004-04-20 12:50:36,114 DEBUG JDBCTransaction - disabling autocommit
2004-04-20 12:50:36,114 DEBUG KernelHandlingServiceImpl - Event chain context initialized
2004-04-20 12:50:36,114 DEBUG HandlingServiceImpl - Handling started
2004-04-20 12:50:36,114 DEBUG TalkmanRequestContextManager - Creating context
2004-04-20 12:50:36,114 DEBUG KernelHandlerContext - Kernel handler context initialized; state manager null
2004-04-20 12:50:36,114 DEBUG OperatorSessionFactory - Loading operator session id='VT001'
2004-04-20 12:50:36,114 DEBUG SessionImpl - loading [com.vocognition.kernel.session.OperatorSession#VT001] in lock mode: UPGRADE
2004-04-20 12:50:36,114 DEBUG ReadWriteCache - Invalidating: VT001
2004-04-20 12:50:36,114 DEBUG Plugin - key: VT001
2004-04-20 12:50:36,114 DEBUG MemoryStore - com.vocognition.kernel.session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 12:50:36,114 DEBUG MemoryStore - com.vocognition.kernel.session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 12:50:36,114 DEBUG SessionImpl - attempting to resolve [com.vocognition.kernel.session.OperatorSession#VT001]
2004-04-20 12:50:36,114 DEBUG SessionImpl - object not resolved in any cache [com.vocognition.kernel.session.OperatorSession#VT001]
2004-04-20 12:50:36,114 DEBUG EntityPersister - Materializing entity: [com.vocognition.kernel.session.OperatorSession#VT001]
2004-04-20 12:50:36,114 DEBUG BatcherImpl - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-04-20 12:50:36,114 DEBUG SQL - select id, operatorName as operator2_, terminalSerialNumber as terminal3_, candidateTerminalSerialNumber as candidat4_, created, accessed, justResumed as justResu7_, mainScriptState as mainScri8_, subroutineScriptState as subrouti9_, switchingScriptState as switchi10_, properties, environmentId as environ12_, assignment from OPERATOR_SESSION where id =? for update
2004-04-20 12:50:36,114 DEBUG BatcherImpl - preparing statement
2004-04-20 12:50:36,114 DEBUG StringType - binding 'VT001' to parameter: 1
2004-04-20 12:50:36,129 DEBUG Loader - processing result set
2004-04-20 12:50:36,129 DEBUG Loader - result row: VT001
2004-04-20 12:50:36,129 DEBUG Loader - Initializing object from ResultSet: VT001
2004-04-20 12:50:36,129 DEBUG Loader - Hydrating entity: com.vocognition.kernel.session.OperatorSession#VT001
2004-04-20 12:50:36,129 DEBUG StringType - returning null as column: operator2_
2004-04-20 12:50:36,129 DEBUG StringType - returning '123456' as column: terminal3_
2004-04-20 12:50:36,145 DEBUG StringType - returning null as column: candidat4_
2004-04-20 12:50:36,145 DEBUG TimestampType - returning '20 April 2004 12:48:34' as column: created
2004-04-20 12:50:36,145 DEBUG TimestampType - returning '20 April 2004 12:50:35' as column: accessed
2004-04-20 12:50:36,145 DEBUG BooleanType - returning 'false' as column: justResu7_
2004-04-20 12:50:36,161 DEBUG StringType - returning '01' as column: environ12_
2004-04-20 12:50:36,161 DEBUG SerializableType - returning null as column: assignment
2004-04-20 12:50:36,161 DEBUG Loader - done processing result set (1 rows)
2004-04-20 12:50:36,161 DEBUG BatcherImpl - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-04-20 12:50:36,161 DEBUG BatcherImpl - closing statement
2004-04-20 12:50:36,161 DEBUG Loader - total objects hydrated: 1
2004-04-20 12:50:36,161 DEBUG SessionImpl - resolving associations for [com.vocognition.kernel.session.OperatorSession#VT001]
2004-04-20 12:50:36,161 DEBUG SessionImpl - adding entity to second-level cache [com.vocognition.kernel.session.OperatorSession#VT001]
2004-04-20 12:50:36,161 DEBUG ReadWriteCache - Caching: VT001
2004-04-20 12:50:36,161 DEBUG Plugin - key: VT001
2004-04-20 12:50:36,161 DEBUG MemoryStore - com.vocognition.kernel.session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 12:50:36,161 DEBUG MemoryStore - com.vocognition.kernel.session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 12:50:36,161 DEBUG ReadWriteCache - Item was locked: VT001
2004-04-20 12:50:36,161 DEBUG SessionImpl - done materializing entity [com.vocognition.kernel.session.OperatorSession#VT001]
2004-04-20 12:50:36,161 DEBUG SessionImpl - initializing non-lazy collections
2004-04-20 12:50:36,161 DEBUG ReadWriteCache - Releasing: VT001
2004-04-20 12:50:36,161 DEBUG Plugin - key: VT001
2004-04-20 12:50:36,161 DEBUG MemoryStore - com.vocognition.kernel.session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 12:50:36,161 DEBUG MemoryStore - com.vocognition.kernel.session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 12:50:36,161 DEBUG OperatorSessionFactory - [47 ms] Operator session loaded
2004-04-20 12:50:36,161 DEBUG HandlingServiceImpl - Handling finished
2004-04-20 12:50:36,161 DEBUG SessionImpl - flushing session
2004-04-20 12:50:36,161 DEBUG SessionImpl - Flushing entities and processing referenced collections
2004-04-20 12:50:36,161 DEBUG AbstractEntityPersister - com.vocognition.kernel.session.OperatorSession.accessed is dirty
2004-04-20 12:50:36,161 DEBUG SessionImpl - Updating entity: [com.vocognition.kernel.session.OperatorSession#VT001]
2004-04-20 12:50:36,161 DEBUG SessionImpl - Processing unreferenced collections
2004-04-20 12:50:36,161 DEBUG SessionImpl - Scheduling collection removes/(re)creates/updates
2004-04-20 12:50:36,161 DEBUG SessionImpl - Flushed: 0 insertions, 1 updates, 0 deletions to 1 objects
2004-04-20 12:50:36,161 DEBUG SessionImpl - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2004-04-20 12:50:36,161 DEBUG Printer - listing entities:
2004-04-20 12:50:36,176 DEBUG Printer - com.vocognition.kernel.session.OperatorSession{created=20 April 2004 12:48:34, assignment=null, environmentId=01, subroutineScriptState=2c6d8085f3f280bae3efedaef6efe3efe7eee9f4e9efeeaeebe5f2eee5ecaef3e5f3f3e9efeeaecff0e5f2e1f4eff2d3e5f3f3e9efeea4d3e3f2e9f0f4d3f4e1f4e52485b3a7c96d8568838086da808ff7e1e9f4e9eee7c6eff2d2e5f0ecf9cc808de3eff2f2e5ece1 properties=2c6d8085f3f28091eae1f6e1aef5f4e9ecaec8e1f3e8cde1f085875a414396e051838082c6808aecefe1e4c6e1e3f4eff2c98089f, id=VT001, candidateTerminalSerialNumber=null, accessed=20 April 2004 12:50:36, switchingScriptState=2c6d8085f3f280bae3efedaef6efe3efe7eee9f4e9efeeaeebe5f2eee5ecaef3e5f3f3e9efeeaecff0e5f2e1f4eff2d2e5f2f180fe8081f8f0f78b8080808080808080808080f8, operatorName=null, terminalSerialNumber=123456, justResumed=false, mainScriptState=2c6d8085f3f280bae3efedaef6efe3efe7eee9f4e9efeeaeebe5f2eee5ecaef3e5f3f3e9efeeaecff0e5f2e1f4eff2d3e5f3}
2004-04-20 12:50:36,176 DEBUG SessionImpl - executing flush
2004-04-20 12:50:36,176 DEBUG ReadWriteCache - Invalidating: VT001
2004-04-20 12:50:36,176 DEBUG Plugin - key: VT001
2004-04-20 12:50:36,176 DEBUG MemoryStore - com.vocognition.kernel.session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 12:50:36,176 DEBUG MemoryStore - com.vocognition.kernel.session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 12:50:36,176 DEBUG EntityPersister - Updating entity: [com.vocognition.kernel.session.OperatorSession#VT001]
2004-04-20 12:50:36,176 DEBUG BatcherImpl - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-04-20 12:50:36,176 DEBUG SQL - update OPERATOR_SESSION set operatorName=?, terminalSerialNumber=?, candidateTerminalSerialNumber=?, created=?, accessed=?, justResumed=?, mainScriptState=?, subroutineScriptState=?, switchingScriptState=?, properties=?, environmentId=?, assignment=? where id=?
2004-04-20 12:50:36,176 DEBUG BatcherImpl - preparing statement
2004-04-20 12:50:36,176 DEBUG EntityPersister - Dehydrating entity: [com.vocognition.kernel.session.OperatorSession#VT001]
2004-04-20 12:50:36,176 DEBUG StringType - binding null to parameter: 1
2004-04-20 12:50:36,176 DEBUG StringType - binding '123456' to parameter: 2
2004-04-20 12:50:36,176 DEBUG StringType - binding null to parameter: 3
2004-04-20 12:50:36,176 DEBUG TimestampType - binding '20 April 2004 12:48:34' to parameter: 4
2004-04-20 12:50:36,176 DEBUG TimestampType - binding '20 April 2004 12:50:36' to parameter: 5
2004-04-20 12:50:36,176 DEBUG BooleanType - binding 'false' to parameter: 6
2004-04-20 12:50:36,176 DEBUG StringType - binding '01' to parameter: 11
2004-04-20 12:50:36,176 DEBUG SerializableType - binding null to parameter: 12
2004-04-20 12:50:36,176 DEBUG StringType - binding 'VT001' to parameter: 13
2004-04-20 12:50:36,192 DEBUG BatcherImpl - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-04-20 12:50:36,192 DEBUG BatcherImpl - closing statement
2004-04-20 12:50:36,192 DEBUG SessionImpl - post flush
2004-04-20 12:50:36,192 DEBUG JDBCTransaction - commit
2004-04-20 12:50:36,192 DEBUG SessionImpl - flushing session
2004-04-20 12:50:36,192 DEBUG SessionImpl - Flushing entities and processing referenced collections
2004-04-20 12:50:36,192 DEBUG SessionImpl - Processing unreferenced collections
2004-04-20 12:50:36,192 DEBUG SessionImpl - Scheduling collection removes/(re)creates/updates
2004-04-20 12:50:36,192 DEBUG SessionImpl - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
2004-04-20 12:50:36,192 DEBUG SessionImpl - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2004-04-20 12:50:36,192 DEBUG Printer - listing entities:
2004-04-20 12:50:36,192 DEBUG Printer - com.vocognition.kernel.session.OperatorSession{created=20 April 2004 12:48:34, assignment=null, environmentId=01, subroutineScriptState=2c6d8085f3f280bae3efedaef6efe3efe7eee9f4e9efeeaeebe5f2eee5ecaef3e5f3f3e9efeeaecff0e5f2e1f4eff2e2e5f2f180fe8081f8f0f78b8080808080808080808080f8, properties=2c6d8085f3f28091eae1f6e1aef5f4e9ecaec8e1f3e8cde1f085875a414396e051838082c6808aecefe1e4c6e1e3f4eff2c98089f4e8f2e5f3e8efece4f8f0bfc080808080808cf7888080809080808084f48085d3d4c1d4c5f48085d3c5d4d5d0f4808cd6c5c8c9c3ccc5dfc3cfc8, id=VT001, candidateTerminalSerialNumber=null, accessed=20 April 2004 12:50:36, switchingScriptState=2c6d8085f3f280bae3efedaef6efe3efe7eee9f4e9efeeaeebe5f2eee5ecaef3e5f3f3e9efeeaecff0e5f2e1f4eff2d2e5f2f180fe8081f8f0f78b8080808080808080808080f8, operatorName=null, terminalSerialNumber=123456, justResumed=false, mainScriptState=2c6d8085f3f280bae3efedaef6efe3efe7eee9f4e9efeeaeebe5f2eee5ecaef3e5f3f3e9efeeaecff0e5f2e1f4eff2d3e5f3f180fe8081f8f0f7a38080818098d6d4b0b0b1afb1b2b3b4b5b6afc7e5f4d3e3f2e9f0f4afb0808080808080f8}
2004-04-20 12:50:36,192 DEBUG SessionImpl - executing flush
2004-04-20 12:50:36,192 DEBUG SessionImpl - post flush
2004-04-20 12:50:36,192 DEBUG SessionImpl - transaction completion
2004-04-20 12:50:36,192 DEBUG ReadWriteCache - Updating: VT001
2004-04-20 12:50:36,192 DEBUG Plugin - key: VT001
2004-04-20 12:50:36,192 DEBUG MemoryStore - com.vocognition.kernel.session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 12:50:36,192 DEBUG MemoryStore - com.vocognition.kernel.session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 12:50:36,192 DEBUG JDBCTransaction - re-enabling autocommit
2004-04-20 12:50:36,192 DEBUG SessionImpl - closing session
2004-04-20 12:50:36,192 DEBUG SessionImpl - disconnecting session
2004-04-20 12:50:36,192 DEBUG SessionImpl - transaction completion
2004-04-20 12:50:36,192 DEBUG KernelHandlingServiceImpl - Event chain context finalized
2004-04-20 12:50:36,192 INFO HandlingServiceImpl - [78 ms] Handling done (com.vocognition.kernel.messages.GetScript)
2004-04-20 12:50:36,192 DEBUG HandlingServiceImpl - Event context trace: [47 ms] GetScript handled: [31 ms] Context finalized

-----------------------------------------------------------------------
load() with no LockMode specified - caching works somehow (though not for thread 2), locking doesn't , example log below
-----------------------------------------------------------------------

2004-04-20 13:29:36,680 DEBUG [Thread 1] - SessionImpl - opened session
2004-04-20 13:29:36,680 DEBUG [Thread 1] - JDBCTransaction - begin
2004-04-20 13:29:36,680 DEBUG [Thread 1] - JDBCTransaction - current autocommit status:true
2004-04-20 13:29:36,680 DEBUG [Thread 1] - JDBCTransaction - disabling autocommit
2004-04-20 13:29:36,680 DEBUG [Thread 1] - SessionImpl - loading [session.OperatorSession#VT001]
2004-04-20 13:29:36,680 DEBUG [Thread 1] - SessionImpl - attempting to resolve [session.OperatorSession#VT001]
2004-04-20 13:29:36,680 DEBUG [Thread 1] - ReadWriteCache - Cache lookup: VT001
2004-04-20 13:29:36,680 DEBUG [Thread 1] - Plugin - key: VT001
2004-04-20 13:29:36,680 DEBUG [Thread 1] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:36,680 DEBUG [Thread 1] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:36,680 DEBUG [Thread 1] - ReadWriteCache - Cache hit: VT001
2004-04-20 13:29:36,680 DEBUG [Thread 1] - SessionImpl - resolved object in second-level cache [session.OperatorSession#VT001]
2004-04-20 13:29:36,726 DEBUG [Thread 1] - SessionImpl - Cached Version: null
2004-04-20 13:29:36,742 DEBUG [Thread 1] - SessionImpl - initializing non-lazy collections
2004-04-20 13:29:36,742 DEBUG [Thread 1] - OperatorSessionFactory - [62 ms] Operator session loaded

2004-04-20 13:29:36,742 DEBUG [Thread 2] - SessionImpl - opened session
2004-04-20 13:29:36,742 DEBUG [Thread 2] - JDBCTransaction - begin
2004-04-20 13:29:36,742 DEBUG [Thread 2] - JDBCTransaction - current autocommit status:true
2004-04-20 13:29:36,742 DEBUG [Thread 2] - JDBCTransaction - disabling autocommit
2004-04-20 13:29:36,742 DEBUG [Thread 2] - OperatorSessionFactory - Loading operator session id='VT001'
2004-04-20 13:29:36,742 DEBUG [Thread 2] - SessionImpl - loading [session.OperatorSession#VT001]
2004-04-20 13:29:36,742 DEBUG [Thread 2] - SessionImpl - attempting to resolve [session.OperatorSession#VT001]
2004-04-20 13:29:36,742 DEBUG [Thread 2] - ReadWriteCache - Cache lookup: VT001
2004-04-20 13:29:36,742 DEBUG [Thread 2] - Plugin - key: VT001
2004-04-20 13:29:36,742 DEBUG [Thread 2] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:36,742 DEBUG [Thread 2] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:36,742 DEBUG [Thread 2] - ReadWriteCache - Cache hit: VT001
2004-04-20 13:29:36,742 DEBUG [Thread 2] - SessionImpl - resolved object in second-level cache [session.OperatorSession#VT001]
2004-04-20 13:29:36,758 DEBUG [Thread 2] - SessionImpl - Cached Version: null
2004-04-20 13:29:36,758 DEBUG [Thread 2] - SessionImpl - initializing non-lazy collections
2004-04-20 13:29:36,758 DEBUG [Thread 2] - OperatorSessionFactory - [16 ms] Operator session loaded
2004-04-20 13:29:36,758 DEBUG [Thread 2] - HandlingServiceImpl - Handling finished
2004-04-20 13:29:36,758 DEBUG [Thread 2] - SessionImpl - flushing session
2004-04-20 13:29:36,758 DEBUG [Thread 2] - SessionImpl - Flushing entities and processing referenced collections
2004-04-20 13:29:36,773 DEBUG [Thread 2] - AbstractEntityPersister - session.OperatorSession.assignment is dirty
2004-04-20 13:29:36,773 DEBUG [Thread 2] - SessionImpl - Updating entity: [session.OperatorSession#VT001]

2004-04-20 13:29:36,773 DEBUG [Thread 3] - HandlingServiceImpl - First message in chain, creating new context
2004-04-20 13:29:36,773 DEBUG [Thread 3] - SessionImpl - opened session
2004-04-20 13:29:36,773 DEBUG [Thread 3] - JDBCTransaction - begin

2004-04-20 13:29:36,773 DEBUG [Thread 1] - HandlingServiceImpl - Handling finished
2004-04-20 13:29:36,773 DEBUG [Thread 1] - SessionImpl - flushing session
2004-04-20 13:29:36,773 DEBUG [Thread 1] - SessionImpl - Flushing entities and processing referenced collections
2004-04-20 13:29:36,789 DEBUG [Thread 1] - AbstractEntityPersister - session.OperatorSession.assignment is dirty
2004-04-20 13:29:36,789 DEBUG [Thread 1] - SessionImpl - Updating entity: [session.OperatorSession#VT001]

2004-04-20 13:29:36,805 DEBUG [Thread 2] - SessionImpl - Processing unreferenced collections
2004-04-20 13:29:36,805 DEBUG [Thread 2] - SessionImpl - Scheduling collection removes/(re)creates/updates
2004-04-20 13:29:36,805 DEBUG [Thread 2] - SessionImpl - Flushed: 0 insertions, 1 updates, 0 deletions to 2 objects
2004-04-20 13:29:36,805 DEBUG [Thread 2] - SessionImpl - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2004-04-20 13:29:36,805 DEBUG [Thread 2] - Printer - listing entities:

2004-04-20 13:29:36,820 DEBUG [Thread 1] - SessionImpl - Processing unreferenced collections
2004-04-20 13:29:36,820 DEBUG [Thread 1] - SessionImpl - Scheduling collection removes/(re)creates/updates
2004-04-20 13:29:36,820 DEBUG [Thread 1] - SessionImpl - Flushed: 0 insertions, 1 updates, 0 deletions to 2 objects
2004-04-20 13:29:36,820 DEBUG [Thread 1] - SessionImpl - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2004-04-20 13:29:36,820 DEBUG [Thread 1] - Printer - listing entities:

2004-04-20 13:29:36,851 DEBUG [Thread 2] - SessionImpl - executing flush
2004-04-20 13:29:36,851 DEBUG [Thread 2] - ReadWriteCache - Invalidating: VT001
2004-04-20 13:29:36,851 DEBUG [Thread 2] - Plugin - key: VT001
2004-04-20 13:29:36,851 DEBUG [Thread 2] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:36,851 DEBUG [Thread 2] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:36,851 DEBUG [Thread 2] - EntityPersister - Updating entity: [session.OperatorSession#VT001]
2004-04-20 13:29:36,851 DEBUG [Thread 2] - BatcherImpl - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-04-20 13:29:36,851 DEBUG [Thread 2] - SQL - update OPERATOR_SESSION set operatorName=?, terminalSerialNumber=?, candidateTerminalSerialNumber=?, created=?, accessed=?, justResumed=?, mainScriptState=?, subroutineScriptState=?, switchingScriptState=?, properties=?, environmentId=?, assignment=? where id=?
2004-04-20 13:29:36,851 DEBUG [Thread 2] - BatcherImpl - preparing statement
2004-04-20 13:29:36,851 DEBUG [Thread 2] - EntityPersister - Dehydrating entity: [session.OperatorSession#VT001]
2004-04-20 13:29:36,851 DEBUG [Thread 2] - StringType - binding null to parameter: 1
2004-04-20 13:29:36,851 DEBUG [Thread 2] - StringType - binding '123456' to parameter: 2
2004-04-20 13:29:36,851 DEBUG [Thread 2] - StringType - binding null to parameter: 3
2004-04-20 13:29:36,851 DEBUG [Thread 2] - TimestampType - binding '20 April 2004 12:48:34' to parameter: 4
2004-04-20 13:29:36,851 DEBUG [Thread 2] - TimestampType - binding '20 April 2004 13:29:36' to parameter: 5
2004-04-20 13:29:36,851 DEBUG [Thread 2] - BooleanType - binding 'false' to parameter: 6
2004-04-20 13:29:36,867 DEBUG [Thread 2] - StringType - binding '01' to parameter: 11
2004-04-20 13:29:36,898 DEBUG [Thread 2] - StringType - binding 'VT001' to parameter: 13

2004-04-20 13:29:36,914 DEBUG [Thread 1] - SessionImpl - executing flush
2004-04-20 13:29:36,914 DEBUG [Thread 1] - ReadWriteCache - Invalidating: VT001
2004-04-20 13:29:36,914 DEBUG [Thread 1] - Plugin - key: VT001
2004-04-20 13:29:36,914 DEBUG [Thread 1] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:36,914 DEBUG [Thread 1] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:36,914 DEBUG [Thread 1] - EntityPersister - Updating entity: [session.OperatorSession#VT001]
2004-04-20 13:29:36,914 DEBUG [Thread 1] - BatcherImpl - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-04-20 13:29:36,914 DEBUG [Thread 1] - SQL - update OPERATOR_SESSION set operatorName=?, terminalSerialNumber=?, candidateTerminalSerialNumber=?, created=?, accessed=?, justResumed=?, mainScriptState=?, subroutineScriptState=?, switchingScriptState=?, properties=?, environmentId=?, assignment=? where id=?
2004-04-20 13:29:36,914 DEBUG [Thread 1] - BatcherImpl - preparing statement
2004-04-20 13:29:36,914 DEBUG [Thread 1] - EntityPersister - Dehydrating entity: [session.OperatorSession#VT001]
2004-04-20 13:29:36,914 DEBUG [Thread 1] - StringType - binding null to parameter: 1
2004-04-20 13:29:36,914 DEBUG [Thread 1] - StringType - binding '123456' to parameter: 2
2004-04-20 13:29:36,914 DEBUG [Thread 1] - StringType - binding null to parameter: 3
2004-04-20 13:29:36,914 DEBUG [Thread 1] - TimestampType - binding '20 April 2004 12:48:34' to parameter: 4
2004-04-20 13:29:36,914 DEBUG [Thread 1] - TimestampType - binding '20 April 2004 13:29:36' to parameter: 5
2004-04-20 13:29:36,914 DEBUG [Thread 1] - BooleanType - binding 'false' to parameter: 6

2004-04-20 13:29:36,914 DEBUG [Thread 2] - BatcherImpl - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-04-20 13:29:36,945 DEBUG [Thread 2] - BatcherImpl - closing statement
2004-04-20 13:29:36,945 DEBUG [Thread 2] - SessionImpl - post flush
2004-04-20 13:29:36,945 DEBUG [Thread 2] - JDBCTransaction - commit
2004-04-20 13:29:36,945 DEBUG [Thread 2] - SessionImpl - flushing session
2004-04-20 13:29:36,945 DEBUG [Thread 2] - SessionImpl - Flushing entities and processing referenced collections
2004-04-20 13:29:36,945 DEBUG [Thread 2] - SessionImpl - Processing unreferenced collections
2004-04-20 13:29:36,945 DEBUG [Thread 2] - SessionImpl - Scheduling collection removes/(re)creates/updates
2004-04-20 13:29:36,945 DEBUG [Thread 2] - SessionImpl - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
2004-04-20 13:29:36,945 DEBUG [Thread 2] - SessionImpl - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2004-04-20 13:29:36,945 DEBUG [Thread 2] - Printer - listing entities:

2004-04-20 13:29:36,961 DEBUG [Thread 1] - StringType - binding '01' to parameter: 11
2004-04-20 13:29:36,976 DEBUG [Thread 1] - StringType - binding 'VT001' to parameter: 13

2004-04-20 13:29:36,992 DEBUG [Thread 2] - SessionImpl - executing flush
2004-04-20 13:29:36,992 DEBUG [Thread 2] - SessionImpl - post flush

2004-04-20 13:29:37,023 DEBUG [Thread 1] - BatcherImpl - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-04-20 13:29:37,023 DEBUG [Thread 1] - BatcherImpl - closing statement
2004-04-20 13:29:37,023 DEBUG [Thread 1] - SessionImpl - post flush
2004-04-20 13:29:37,023 DEBUG [Thread 1] - JDBCTransaction - commit
2004-04-20 13:29:37,023 DEBUG [Thread 1] - SessionImpl - flushing session
2004-04-20 13:29:37,023 DEBUG [Thread 1] - SessionImpl - Flushing entities and processing referenced collections
2004-04-20 13:29:37,023 DEBUG [Thread 1] - SessionImpl - Processing unreferenced collections
2004-04-20 13:29:37,023 DEBUG [Thread 1] - SessionImpl - Scheduling collection removes/(re)creates/updates
2004-04-20 13:29:37,023 DEBUG [Thread 1] - SessionImpl - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
2004-04-20 13:29:37,023 DEBUG [Thread 1] - SessionImpl - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2004-04-20 13:29:37,023 DEBUG [Thread 1] - Printer - listing entities:

2004-04-20 13:29:37,055 DEBUG [Thread 2] - SessionImpl - transaction completion
2004-04-20 13:29:37,055 DEBUG [Thread 2] - ReadWriteCache - Updating: VT001
2004-04-20 13:29:37,055 DEBUG [Thread 2] - Plugin - key: VT001
2004-04-20 13:29:37,055 DEBUG [Thread 2] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:37,055 DEBUG [Thread 2] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:37,055 DEBUG [Thread 2] - JDBCTransaction - re-enabling autocommit
2004-04-20 13:29:37,055 DEBUG [Thread 2] - SessionImpl - closing session
2004-04-20 13:29:37,055 DEBUG [Thread 2] - SessionImpl - disconnecting session
2004-04-20 13:29:37,055 DEBUG [Thread 2] - SessionImpl - transaction completion

2004-04-20 13:29:37,055 DEBUG [Thread 1] - SessionImpl - executing flush
2004-04-20 13:29:37,055 DEBUG [Thread 1] - SessionImpl - post flush

2004-04-20 13:29:37,055 DEBUG [Thread 3] - JDBCTransaction - current autocommit status:true
2004-04-20 13:29:37,055 DEBUG [Thread 3] - JDBCTransaction - disabling autocommit
2004-04-20 13:29:37,070 DEBUG [Thread 3] - OperatorSessionFactory - Loading operator session id='VT001'
2004-04-20 13:29:37,070 DEBUG [Thread 3] - SessionImpl - loading [session.OperatorSession#VT001]
2004-04-20 13:29:37,070 DEBUG [Thread 3] - SessionImpl - attempting to resolve [session.OperatorSession#VT001]
2004-04-20 13:29:37,070 DEBUG [Thread 3] - ReadWriteCache - Cache lookup: VT001
2004-04-20 13:29:37,070 DEBUG [Thread 3] - Plugin - key: VT001
2004-04-20 13:29:37,070 DEBUG [Thread 3] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:37,070 DEBUG [Thread 3] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:37,070 DEBUG [Thread 3] - ReadWriteCache - Cached item was locked: VT001
2004-04-20 13:29:37,070 DEBUG [Thread 3] - SessionImpl - object not resolved in any cache [session.OperatorSession#VT001]
2004-04-20 13:29:37,070 DEBUG [Thread 3] - EntityPersister - Materializing entity: [session.OperatorSession#VT001]
2004-04-20 13:29:37,070 DEBUG [Thread 3] - BatcherImpl - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-04-20 13:29:37,070 DEBUG [Thread 3] - SQL - select operatorse0_.id as id0_, operatorse0_.operatorName as operator2_0_, operatorse0_.terminalSerialNumber as terminal3_0_, operatorse0_.candidateTerminalSerialNumber as candidat4_0_, operatorse0_.created as created0_, operatorse0_.accessed as accessed0_, operatorse0_.justResumed as justResu7_0_, operatorse0_.mainScriptState as mainScri8_0_, operatorse0_.subroutineScriptState as subrouti9_0_, operatorse0_.switchingScriptState as switchi10_0_, operatorse0_.properties as properties0_, operatorse0_.environmentId as environ12_0_, operatorse0_.assignment as assignment0_ from OPERATOR_SESSION operatorse0_ where operatorse0_.id=?
2004-04-20 13:29:37,070 DEBUG [Thread 3] - BatcherImpl - preparing statement
2004-04-20 13:29:37,070 DEBUG [Thread 3] - StringType - binding 'VT001' to parameter: 1
2004-04-20 13:29:37,070 DEBUG [Thread 3] - Loader - processing result set
2004-04-20 13:29:37,070 DEBUG [Thread 3] - Loader - result row: VT001
2004-04-20 13:29:37,070 DEBUG [Thread 3] - Loader - Initializing object from ResultSet: VT001
2004-04-20 13:29:37,070 DEBUG [Thread 3] - Loader - Hydrating entity: session.OperatorSession#VT001
2004-04-20 13:29:37,070 DEBUG [Thread 3] - StringType - returning null as column: operator2_0_
2004-04-20 13:29:37,070 DEBUG [Thread 3] - StringType - returning '123456' as column: terminal3_0_
2004-04-20 13:29:37,070 DEBUG [Thread 3] - StringType - returning null as column: candidat4_0_
2004-04-20 13:29:37,070 DEBUG [Thread 3] - TimestampType - returning '20 April 2004 12:48:34' as column: created0_
2004-04-20 13:29:37,070 DEBUG [Thread 3] - TimestampType - returning '20 April 2004 13:29:36' as column: accessed0_
2004-04-20 13:29:37,070 DEBUG [Thread 3] - BooleanType - returning 'false' as column: justResu7_0_

2004-04-20 13:29:37,086 DEBUG [Thread 1] - SessionImpl - transaction completion
2004-04-20 13:29:37,086 DEBUG [Thread 1] - ReadWriteCache - Updating: VT001
2004-04-20 13:29:37,086 DEBUG [Thread 1] - Plugin - key: VT001
2004-04-20 13:29:37,086 DEBUG [Thread 1] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:37,086 DEBUG [Thread 1] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:37,086 DEBUG [Thread 1] - JDBCTransaction - re-enabling autocommit
2004-04-20 13:29:37,086 DEBUG [Thread 1] - SessionImpl - closing session
2004-04-20 13:29:37,086 DEBUG [Thread 1] - SessionImpl - disconnecting session
2004-04-20 13:29:37,086 DEBUG [Thread 1] - SessionImpl - transaction completion

2004-04-20 13:29:37,086 DEBUG [Thread 3] - StringType - returning '01' as column: environ12_0_
2004-04-20 13:29:37,117 DEBUG [Thread 3] - Loader - done processing result set (1 rows)
2004-04-20 13:29:37,117 DEBUG [Thread 3] - BatcherImpl - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-04-20 13:29:37,117 DEBUG [Thread 3] - BatcherImpl - closing statement
2004-04-20 13:29:37,117 DEBUG [Thread 3] - Loader - total objects hydrated: 1
2004-04-20 13:29:37,117 DEBUG [Thread 3] - SessionImpl - resolving associations for [session.OperatorSession#VT001]
2004-04-20 13:29:37,117 DEBUG [Thread 3] - SessionImpl - adding entity to second-level cache [session.OperatorSession#VT001]
2004-04-20 13:29:37,117 DEBUG [Thread 3] - ReadWriteCache - Caching: VT001
2004-04-20 13:29:37,117 DEBUG [Thread 3] - Plugin - key: VT001
2004-04-20 13:29:37,117 DEBUG [Thread 3] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:37,117 DEBUG [Thread 3] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:37,117 DEBUG [Thread 3] - ReadWriteCache - Item was locked: VT001
2004-04-20 13:29:37,133 DEBUG [Thread 3] - SessionImpl - done materializing entity [session.OperatorSession#VT001]
2004-04-20 13:29:37,133 DEBUG [Thread 3] - SessionImpl - initializing non-lazy collections
2004-04-20 13:29:37,133 DEBUG [Thread 3] - OperatorSessionFactory - [63 ms] Operator session loaded
2004-04-20 13:29:37,133 DEBUG [Thread 3] - HandlingServiceImpl - Handling finished
2004-04-20 13:29:37,133 DEBUG [Thread 3] - SessionImpl - flushing session
2004-04-20 13:29:37,133 DEBUG [Thread 3] - SessionImpl - Flushing entities and processing referenced collections
2004-04-20 13:29:37,133 DEBUG [Thread 3] - AbstractEntityPersister - session.OperatorSession.assignment is dirty
2004-04-20 13:29:37,133 DEBUG [Thread 3] - SessionImpl - Updating entity: [session.OperatorSession#VT001]
2004-04-20 13:29:37,148 DEBUG [Thread 3] - SessionImpl - Processing unreferenced collections
2004-04-20 13:29:37,148 DEBUG [Thread 3] - SessionImpl - Scheduling collection removes/(re)creates/updates
2004-04-20 13:29:37,148 DEBUG [Thread 3] - SessionImpl - Flushed: 0 insertions, 1 updates, 0 deletions to 2 objects
2004-04-20 13:29:37,148 DEBUG [Thread 3] - SessionImpl - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2004-04-20 13:29:37,148 DEBUG [Thread 3] - Printer - listing entities:
2004-04-20 13:29:37,180 DEBUG [Thread 3] - SessionImpl - executing flush
2004-04-20 13:29:37,180 DEBUG [Thread 3] - ReadWriteCache - Invalidating: VT001
2004-04-20 13:29:37,180 DEBUG [Thread 3] - Plugin - key: VT001
2004-04-20 13:29:37,180 DEBUG [Thread 3] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:37,180 DEBUG [Thread 3] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:37,180 DEBUG [Thread 3] - EntityPersister - Updating entity: [session.OperatorSession#VT001]
2004-04-20 13:29:37,180 DEBUG [Thread 3] - BatcherImpl - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-04-20 13:29:37,180 DEBUG [Thread 3] - SQL - update OPERATOR_SESSION set operatorName=?, terminalSerialNumber=?, candidateTerminalSerialNumber=?, created=?, accessed=?, justResumed=?, mainScriptState=?, subroutineScriptState=?, switchingScriptState=?, properties=?, environmentId=?, assignment=? where id=?
2004-04-20 13:29:37,180 DEBUG [Thread 3] - BatcherImpl - preparing statement
2004-04-20 13:29:37,180 DEBUG [Thread 3] - EntityPersister - Dehydrating entity: [session.OperatorSession#VT001]
2004-04-20 13:29:37,180 DEBUG [Thread 3] - StringType - binding null to parameter: 1
2004-04-20 13:29:37,180 DEBUG [Thread 3] - StringType - binding '123456' to parameter: 2
2004-04-20 13:29:37,180 DEBUG [Thread 3] - StringType - binding null to parameter: 3
2004-04-20 13:29:37,180 DEBUG [Thread 3] - TimestampType - binding '20 April 2004 12:48:34' to parameter: 4
2004-04-20 13:29:37,180 DEBUG [Thread 3] - TimestampType - binding '20 April 2004 13:29:36' to parameter: 5
2004-04-20 13:29:37,180 DEBUG [Thread 3] - BooleanType - binding 'false' to parameter: 6
2004-04-20 13:29:37,195 DEBUG [Thread 3] - StringType - binding '01' to parameter: 11
2004-04-20 13:29:37,211 DEBUG [Thread 3] - StringType - binding 'VT001' to parameter: 13
2004-04-20 13:29:37,226 DEBUG [Thread 3] - BatcherImpl - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-04-20 13:29:37,226 DEBUG [Thread 3] - BatcherImpl - closing statement
2004-04-20 13:29:37,226 DEBUG [Thread 3] - SessionImpl - post flush
2004-04-20 13:29:37,226 DEBUG [Thread 3] - JDBCTransaction - commit
2004-04-20 13:29:37,226 DEBUG [Thread 3] - SessionImpl - flushing session
2004-04-20 13:29:37,226 DEBUG [Thread 3] - SessionImpl - Flushing entities and processing referenced collections
2004-04-20 13:29:37,242 DEBUG [Thread 3] - SessionImpl - Processing unreferenced collections
2004-04-20 13:29:37,242 DEBUG [Thread 3] - SessionImpl - Scheduling collection removes/(re)creates/updates
2004-04-20 13:29:37,242 DEBUG [Thread 3] - SessionImpl - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
2004-04-20 13:29:37,242 DEBUG [Thread 3] - SessionImpl - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2004-04-20 13:29:37,242 DEBUG [Thread 3] - Printer - listing entities:
2004-04-20 13:29:37,258 DEBUG [Thread 3] - SessionImpl - executing flush
2004-04-20 13:29:37,258 DEBUG [Thread 3] - SessionImpl - post flush
2004-04-20 13:29:37,273 DEBUG [Thread 3] - SessionImpl - transaction completion
2004-04-20 13:29:37,273 DEBUG [Thread 3] - ReadWriteCache - Updating: VT001
2004-04-20 13:29:37,273 DEBUG [Thread 3] - Plugin - key: VT001
2004-04-20 13:29:37,273 DEBUG [Thread 3] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:37,273 DEBUG [Thread 3] - MemoryStore - session.OperatorSessionCache: MemoryStore hit for VT001
2004-04-20 13:29:37,273 DEBUG [Thread 3] - JDBCTransaction - re-enabling autocommit
2004-04-20 13:29:37,273 DEBUG [Thread 3] - SessionImpl - closing session
2004-04-20 13:29:37,273 DEBUG [Thread 3] - SessionImpl - disconnecting session
2004-04-20 13:29:37,273 DEBUG [Thread 3] - SessionImpl - transaction completion





Hibernate mapping file:

<hibernate-mapping>
<class
name="session.OperatorSession"
table="OPERATOR_SESSION"
dynamic-update="false"
dynamic-insert="false"
>
<cache usage="read-write" />

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

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

<!-- ....... other properties ..... -->

</class>

</hibernate-mapping>



Hibernate properties:

hibernate.cache.provider_class net.sf.ehcache.hibernate.Provider
hibernate.cglib.use_reflection_optimizer true
hibernate.connection.isolation 2
hibernate.transaction.manager_lookup_class net.sf.hibernate.transaction.JBossTransactionManagerLookup

I've done some additional research

as far as I've understood, EHCache doesn't do any locking internally

but net.sf.hibernate.cache.ReadWriteCache does

so without explicit database locking i.e. without LockMode.UPGRADE it looks like this

1. thread 1 wants to acquire OperatorSession, hits cache and successfully gets an object without hitting database

2. in the same time thread 2 wants to acquire same instance of OperatorSession, and then the following happens:

ReadWriteCache - Cached item was locked: ID
SessionImpl - object not resolved in any cache
EntityPersister - Materializing entity: ...
BatcherImpl - about to open: 0 open PreparedSta...
SQL - select operatorse0_.id as id0_, o ...
BatcherImpl - preparing statement ...

How can I make ReadWriteCache to block on locked cache item until it's going to be unlocked by concurrent thread? This seems to be the way to achieve what I want, doesn't it?