7:45 a.m.
Right, in the quest for higher throughput using my cache and the JDBCCacheLoader im
experiencing what to me is strange behaviour.
Here is my config for the record
| <?xml version="1.0" encoding="UTF-8"?>
|
| <!-- ===================================================================== -->
| <!-- -->
| <!-- Sample TreeCache Service Configuration -->
| <!-- -->
| <!-- ===================================================================== -->
|
| <server>
|
| <!-- ====================================================================
-->
| <!-- Defines TreeCache configuration
-->
| <!-- ====================================================================
-->
|
| <mbean code="org.jboss.cache.jmx.CacheJmxWrapper"
| name="jboss.cache:service=CMDSPersistentCache">
|
| <depends>jboss:service=Naming</depends>
| <depends>jboss:service=TransactionManager</depends>
| <depends>
| jboss.jca:service=DataSourceBinding,name=cmdsDB
| </depends>
|
| <!--
| Configure the TransactionManager
| -->
| <attribute
name="TransactionManagerLookupClass">org.jboss.cache.transaction.GenericTransactionManagerLookup
| </attribute>
|
|
|
|
| <!--
| Node locking level : SERIALIZABLE
| REPEATABLE_READ (default)
| READ_COMMITTED
| READ_UNCOMMITTED
| NONE
| -->
| <attribute
name="IsolationLevel">REPEATABLE_READ</attribute>
|
| <!--
| Valid modes are LOCAL
| REPL_ASYNC
| REPL_SYNC
| INVALIDATION_ASYNC
| INVALIDATION_SYNC
| -->
| <attribute name="CacheMode">LOCAL</attribute>
|
| <!-- Name of cluster. Needs to be the same for all clusters, in order
| to find each other
| -->
| <attribute name="ClusterName">CMDS-Cluster</attribute>
|
| <!-- JGroups protocol stack properties NOT NEEDED since CacheMode is LOCAL
-->
|
| <attribute
name="LockAcquisitionTimeout">15000</attribute>
|
| <attribute name="StateRetrievalTimeout">6000</attribute>
| <attribute name="SyncReplTimeout">6000</attribute>
| <!--<attribute
name="NodeLockingScheme">OPTIMISTIC</attribute>
| -->
|
| <!-- Specific eviction policy configurations. This is LRU -->
| <attribute name="EvictionPolicyConfig">
| <config>
| <attribute
name="wakeUpIntervalSeconds">30</attribute>
| <attribute name="eventQueueSize">200000</attribute>
| <attribute
name="policyClass">org.jboss.cache.eviction.LRUPolicy</attribute>
|
| <region name="/_default_">
| <attribute name="maxNodes">5000</attribute>
| <attribute
name="timeToLiveSeconds">1000</attribute>
| </region>
| <region name="/quotes">
| <attribute name="maxNodes">1</attribute>
| <attribute
name="timeToLiveSeconds">10000</attribute>
| </region>
| </config>
| </attribute>
|
| <attribute name="CacheLoaderConfig" replace="false">
| <config>
| <!-- are the cache loaders shared in a cluster? -->
| <shared>false</shared>
| <async>true</async>
| <fetchPersistentState>false</fetchPersistentState>
| <ignoreModifications>false</ignoreModifications>
| <purgeOnStartup>false</purgeOnStartup>
|
| <cacheloader>
| <class>org.jboss.cache.loader.JDBCCacheLoader</class>
|
| <properties>
| cache.jdbc.datasource=java:/cmdsDB
| </properties>
|
| </cacheloader>
|
| </config>
| </attribute>
|
| </mbean>
|
|
| </server>
|
|
The way i was thinking was this, i wanted to see could i get a higher throughput for my
cache and thought maybe if i switched the NodeLockingScheme from the default pessimistic
to optimistic that i might be more throughput. Now here is where the strange thing
happened or maybe it is my mis-understanding along the way. The throughput is higher
alright in OPTIMISTIC mode but the reason its higher is because it aint making any writes
to the DB any more!! There are no entries in the DB at all!! If i look at the jmx-console
i see the record in the caches memory but it aint in the DB. Records are written with
PESSIMISTIC mode but not with OPTIMISTIC, any ideas why im seeing this behaviour?.
Log entries in OPTIMISTIC mode are as follows
| 2008-01-23 14:21:18,690 INFO [STDOUT] 2008-01-23 14:21:18,690 DEBUG
[at.sit.cdms.web.actions.ActionFactory] - Looking for bean addItem
|
| 2008-01-23 14:21:18,690 DEBUG [at.sit.cdms.web.actions.ActionFactory] Looking for bean
addItem
|
| 2008-01-23 14:21:18,690 DEBUG
[org.springframework.beans.factory.support.DefaultListableBeanFactory] Returning cached
instance of singleton bean 'addItem'
|
| 2008-01-23 14:21:18,690 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local
transaction exists - registering global tx if not present for
Thread[http-127.0.0.1-8080-1,5,jboss]
|
| 2008-01-23 14:21:18,690 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql:
select node from jbosscache where fqn=? (/quotes/2)
|
| 2008-01-23 14:21:18,706 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Running
commit phase. One phase? false
|
| 2008-01-23 14:21:18,706 DEBUG
[org.jboss.cache.interceptors.OptimisticValidatorInterceptor] Commiting successfully
validated changes for GlobalTransaction GlobalTransaction:<null>:2
|
| 2008-01-23 14:21:18,706 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished
local commit/rollback method for GlobalTransaction:<null>:2
|
| 2008-01-23 14:21:18,706 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished
commit phase
|
| 2008-01-23 14:21:18,706 INFO [STDOUT] 2008-01-23 14:21:18,706 DEBUG
[at.sit.cdms.web.actions.test.AddItem] - Added item with index of 2
|
| 2008-01-23 14:21:18,706 DEBUG [at.sit.cdms.web.actions.test.AddItem] Added item with
index of 2
|
| 2008-01-23 14:21:19,330 INFO [STDOUT] 2008-01-23 14:21:19,330 DEBUG
[at.sit.cdms.web.actions.ActionFactory] - Looking for bean addItem
|
| 2008-01-23 14:21:19,330 DEBUG [at.sit.cdms.web.actions.ActionFactory] Looking for bean
addItem
|
| 2008-01-23 14:21:19,330 DEBUG
[org.springframework.beans.factory.support.DefaultListableBeanFactory] Returning cached
instance of singleton bean 'addItem'
|
| 2008-01-23 14:21:19,330 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local
transaction exists - registering global tx if not present for
Thread[http-127.0.0.1-8080-1,5,jboss]
|
| 2008-01-23 14:21:19,330 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql:
select node from jbosscache where fqn=? (/quotes/3)
|
| 2008-01-23 14:21:19,330 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Running
commit phase. One phase? false
|
| 2008-01-23 14:21:19,330 DEBUG
[org.jboss.cache.interceptors.OptimisticValidatorInterceptor] Commiting successfully
validated changes for GlobalTransaction GlobalTransaction:<null>:3
|
| 2008-01-23 14:21:19,330 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished
local commit/rollback method for GlobalTransaction:<null>:3
|
| 2008-01-23 14:21:19,330 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished
commit phase
|
| 2008-01-23 14:21:19,330 INFO [STDOUT] 2008-01-23 14:21:19,330 DEBUG
[at.sit.cdms.web.actions.test.AddItem] - Added item with index of 3
|
| 2008-01-23 14:21:19,330 DEBUG [at.sit.cdms.web.actions.test.AddItem] Added item with
index of 3
|
| 2008-01-23 14:21:26,563 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local
transaction exists - registering global tx if not present for
Thread[EvictionTimer-0,5,jboss]
|
| 2008-01-23 14:21:26,563 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Running
commit phase. One phase? false
|
| 2008-01-23 14:21:26,563 DEBUG
[org.jboss.cache.interceptors.OptimisticValidatorInterceptor] Commiting successfully
validated changes for GlobalTransaction GlobalTransaction:<null>:4
|
| 2008-01-23 14:21:26,563 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished
local commit/rollback method for GlobalTransaction:<null>:4
|
| 2008-01-23 14:21:26,563 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished
commit phase
|
| 2008-01-23 14:21:26,563 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local
transaction exists - registering global tx if not present for
Thread[EvictionTimer-0,5,jboss]
|
| 2008-01-23 14:21:26,579 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Running
commit phase. One phase? false
|
| 2008-01-23 14:21:26,579 DEBUG
[org.jboss.cache.interceptors.OptimisticValidatorInterceptor] Commiting successfully
validated changes for GlobalTransaction GlobalTransaction:<null>:5
|
| 2008-01-23 14:21:26,579 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished
local commit/rollback method for GlobalTransaction:<null>:5
|
| 2008-01-23 14:21:26,579 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished
commit phase
|
|
|
I dont see any "inserts" like i normally see when in pessimistic mode!!
Another thing i noticed with the pessimictic log, was the number of selects going on.
Log looks like this for pessimistic
| 2008-01-23 13:43:10,554 DEBUG [at.sit.cdms.web.actions.ActionFactory] Looking for bean
addItem
|
| 2008-01-23 13:43:10,554 DEBUG
[org.springframework.beans.factory.support.DefaultListableBeanFactory] Returning cached
instance of singleton bean 'addItem'
|
| 2008-01-23 13:43:10,554 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql:
select node from jbosscache where fqn=? (/quotes/2)
|
| 2008-01-23 13:43:10,554 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql:
select node from jbosscache where fqn=? (/quotes/2)
|
| 2008-01-23 13:43:10,554 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql:
select node from jbosscache where fqn=? (/quotes/2)
|
| 2008-01-23 13:43:10,554 INFO [STDOUT] 2008-01-23 13:43:10,554 DEBUG
[at.sit.cdms.web.actions.test.AddItem] - Added item with index of 2
|
| 2008-01-23 13:43:10,554 DEBUG [at.sit.cdms.web.actions.test.AddItem] Added item with
index of 2
|
| 2008-01-23 13:43:10,554 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql:
insert into jbosscache (fqn, node, parent) values (?, ?, ?) (/quotes/2)
|
| 2008-01-23 13:43:10,601 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql:
select node from jbosscache where fqn=? (/quotes)
|
| 2008-01-23 13:44:20,226 INFO [STDOUT] 2008-01-23 13:44:20,226 DEBUG
[at.sit.cdms.web.actions.ActionFactory] - Looking for bean addItem
|
| 2008-01-23 13:44:20,226 DEBUG [at.sit.cdms.web.actions.ActionFactory] Looking for bean
addItem
|
| 2008-01-23 13:44:20,226 DEBUG
[org.springframework.beans.factory.support.DefaultListableBeanFactory] Returning cached
instance of singleton bean 'addItem'
|
| 2008-01-23 13:44:20,226 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql:
select node from jbosscache where fqn=? (/quotes/3)
|
| 2008-01-23 13:44:20,226 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql:
select node from jbosscache where fqn=? (/quotes/3)
|
| 2008-01-23 13:44:20,242 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql:
select node from jbosscache where fqn=? (/quotes/3)
|
| 2008-01-23 13:44:20,242 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql:
insert into jbosscache (fqn, node, parent) values (?, ?, ?) (/quotes/3)
|
| 2008-01-23 13:44:20,258 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql:
select node from jbosscache where fqn=? (/quotes)
|
| 2008-01-23 13:44:20,258 INFO [STDOUT] 2008-01-23 13:44:20,242 DEBUG
[at.sit.cdms.web.actions.test.AddItem] - Added item with index of 3
|
| 2008-01-23 13:44:20,242 DEBUG [at.sit.cdms.web.actions.test.AddItem] Added item with
index of 3
|
|
Im seeing 3 selects and then a write, surely thats overhead!! Ok I have now seen
http://jira.jboss.org/jira/browse/JBCACHE-1261. That relates to what im seeing with in
pessimistic mode.
Any thoughts on whats going on with the OPTIMISTIC mode or am i missing the big picture??
Cheers,
LL
View the original post :
http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4122633#...
Reply to the post :
http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&a...