[jboss-user] [JBossCache] - BdbjeCacheLoader exception with JTA distributed transactions

nanreh do-not-reply at jboss.com
Wed May 23 13:35:27 EDT 2007


I have a simple cache configuration that specifies a single BdbjeCacheLoader.  I'm using JBoss Transactions and specifying transaction boundaries in my code using JTA.  Here's one of the two transactional methods in my application:


  |     public byte[] loadData(byte[] key) throws ShardStoreException {
  |         
  |         Validate.notNull(key,"key is null");
  |         
  |         UserTransaction tx = null;
  |         try {
  | 
  |             String keyStr = HexUtil.toHexString(key);
  |         
  |             String fqn = new StringBuilder("/shard_").append(shardId).append("/").append(keyStr).toString();
  |             Fqn nodeFqn = Fqn.fromString(fqn);
  | 
  |             tx = com.arjuna.ats.jta.UserTransaction.userTransaction();
  |             logger.info("-------- About to begin TX");
  |             tx.begin();
  |             logger.info("-------- Transaction details: " + tx);
  |             logger.info("-------- Transaction started");
  |     
  |             Object value = cache.get(nodeFqn, KEY_PAYLOAD);
  |             
  |             logger.info("-------- About to commit tx.");
  |             tx.commit();
  |             logger.info("-------- TX committed.");
  |     
  |             if(null==value) {
  |                 return null;
  |             }
  | 
  |             if( !(value instanceof byte[]) ) {
  |                 throw new IllegalArgumentException("Invalid payload found in cache.");
  |             }
  |             return (byte[])value;
  |             
  |         } catch(Exception e) {
  |             try {
  |                 logger.error("Error encountered. Rolling back transaction.",e);
  |                 tx.rollback();
  |             } catch(Exception re) {
  |                 logger.error("Error in rollback.",re);
  |             }
  |             throw new ShardStoreException(e);
  |         }
  |     }
  | 

Pretty basic usage of JBoss cache with lots of logger calls.  With my current cache configuration I can call this method once and it appears to succeed normally.  When I call it again, however, I get this exception:


  | jvm 1    | INFO  10:11.03 [AnonymousIoService-4] JBossCacheShardStore - -------- About to begin TX
  | jvm 1    | INFO  10:11.03 [AnonymousIoService-4] JBossCacheShardStore - -------- Transaction details: com.arjuna.ats.internal.jta.transaction.jts.UserTransactionImple at 1b2d7df
  | jvm 1    | INFO  10:11.03 [AnonymousIoService-4] JBossCacheShardStore - -------- Transaction started
  | jvm 1    | [23-05-2007 10:11:03:651] jacorb.poa:INFO: oid:
  | jvm 1    | 05 15 0C 47 48 3F 29 14 36 40                               ...GH?).6@
  | jvm 1    | object is activated
  | jvm 1    | ERROR 10:11.04 [AnonymousIoService-4] JBossCacheShardStore - Error encountered. Rolling back transaction.
  | jvm 1    | java.lang.RuntimeException: com.sleepycat.je.DeadlockException: (JE 3.2.23) Lock expired. Locker -1_AnonymousIoService-4_ThreadLocker: waited for lock on database=SHARD_CLUSTER node=28 type=READ grant=WAIT_NEW timeoutMillis=500 startTime=1179940263653 endTime=1179940264155
  | jvm 1    | Owners: [<LockInfo locker="6_RequestProcessor-5_Txn" type="WRITE"/>]
  | jvm 1    | Waiters: []
  | jvm 1    |
  | jvm 1    |      at org.jboss.cache.CacheImpl.invokeMethod(CacheImpl.java:3764)
  | jvm 1    |      at org.jboss.cache.CacheImpl.get(CacheImpl.java:1323)
  | jvm 1    |      at org.jboss.cache.CacheImpl.get(CacheImpl.java:1298)
  | jvm 1    |      at com.scea.scne.acs.shard.cache.JBossCacheShardStore.loadData(JBossCacheShardStore.java:110)
  | jvm 1    |      at com.scea.scne.acs.shard.server.ShardFetchHandler.handleLoadRequest(ShardFetchHandler.java:72)
  | jvm 1    |      at com.scea.scne.acs.shard.server.ShardFetchHandler.messageReceived(ShardFetchHandler.java:55)
  | jvm 1    |      at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived(AbstractIoFilterChain.java:703)
  | jvm 1    |      at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
  | jvm 1    |      at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:54)
  | jvm 1    |      at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:800)
  | jvm 1    |      at org.apache.mina.filter.LoggingFilter.messageReceived(LoggingFilter.java:97)
  | jvm 1    |      at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
  | jvm 1    |      at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:54)
  | jvm 1    |      at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:800)
  | jvm 1    |      at org.apache.mina.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimpleProtocolDecoderOutput.java:62)
  | jvm 1    |      at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:200)
  | jvm 1    |      at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
  | jvm 1    |      at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:54)
  | jvm 1    |      at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:800)
  | jvm 1    |      at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:247)
  | jvm 1    |      at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:307)
  | jvm 1    |      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
  | jvm 1    |      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
  | jvm 1    |      at java.lang.Thread.run(Thread.java:595)
  | jvm 1    | Caused by: com.sleepycat.je.DeadlockException: (JE 3.2.23) Lock expired. Locker -1_AnonymousIoService-4_ThreadLocker: waited for lock on database=SHARD_CLUSTER node=28 type=READ grant=WAIT_NEW timeoutMillis=500 startTime=1179940263653 endTime=1179940264155
  | jvm 1    | Owners: [<LockInfo locker="6_RequestProcessor-5_Txn" type="WRITE"/>]
  | jvm 1    | Waiters: []
  | jvm 1    |
  | jvm 1    |      at com.sleepycat.je.txn.LockManager.lock(LockManager.java:266)
  | jvm 1    |      at com.sleepycat.je.txn.BasicLocker.lockInternal(BasicLocker.java:90)
  | jvm 1    |      at com.sleepycat.je.txn.Locker.lock(Locker.java:257)
  | jvm 1    |      at com.sleepycat.je.dbi.CursorImpl.lockLNDeletedAllowed(CursorImpl.java:2349)
  | jvm 1    |      at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:2271)
  | jvm 1    |      at com.sleepycat.je.dbi.CursorImpl.searchAndPosition(CursorImpl.java:1963)
  | jvm 1    |      at com.sleepycat.je.Cursor.searchInternal(Cursor.java:1178)
  | jvm 1    |      at com.sleepycat.je.Cursor.searchAllowPhantoms(Cursor.java:1148)
  | jvm 1    |      at com.sleepycat.je.Cursor.search(Cursor.java:1014)
  | jvm 1    |      at com.sleepycat.je.Database.get(Database.java:547)
  | jvm 1    |      at org.jboss.cache.loader.bdbje.BdbjeCacheLoader.get(BdbjeCacheLoader.java:380)
  | jvm 1    |      at org.jboss.cache.interceptors.CacheLoaderInterceptor.loadData(CacheLoaderInterceptor.java:515)
  | jvm 1    |      at org.jboss.cache.interceptors.CacheLoaderInterceptor.loadNode(CacheLoaderInterceptor.java:395)
  | jvm 1    |      at org.jboss.cache.interceptors.CacheLoaderInterceptor.loadIfNeeded(CacheLoaderInterceptor.java:181)
  | jvm 1    |      at org.jboss.cache.interceptors.CacheLoaderInterceptor.invoke(CacheLoaderInterceptor.java:152)
  | jvm 1    |      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
  | jvm 1    |      at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:33)
  | jvm 1    |      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
  | jvm 1    |      at org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:202)
  | jvm 1    |      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
  | jvm 1    |      at org.jboss.cache.interceptors.ReplicationInterceptor.invoke(ReplicationInterceptor.java:34)
  | jvm 1    |      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
  | jvm 1    |      at org.jboss.cache.interceptors.NotificationInterceptor.invoke(NotificationInterceptor.java:22)
  | jvm 1    |      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
  | jvm 1    |      at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:294)
  | jvm 1    |      at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:128)
  | jvm 1    |      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
  | jvm 1    |      at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:126)
  | jvm 1    |      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
  | jvm 1    |      at org.jboss.cache.interceptors.InvocationContextInterceptor.invoke(InvocationContextInterceptor.java:66)
  | jvm 1    |      at org.jboss.cache.CacheImpl.invokeMethod(CacheImpl.java:3752)
  | jvm 1    |      ... 23 more
  | 

I'm not sure how to interpret this stack trace but it looks like the BerkleyDB is holding onto a lock from the first transaction and the second transaction fails to acquire it and fails.

When I tell the transaction manager to do local transactions the error goes away.  I'm wondering if I need to send the Berkley DB a few properties to set up its transactional behavior but I thought I'd post in case anyone out there recognizes the issue.

Here's my cache configuration file:


  | <?xml version="1.0" encoding="UTF-8"?>
  | 
  | <server>
  |    <classpath codebase="./lib" archives="jboss-cache.jar, jgroups.jar"/>
  | 
  |    <mbean code="org.jboss.cache.CacheImpl" name="jboss.cache:service=Cache">
  |       <depends>jboss:service=Naming</depends>
  |       <depends>jboss:service=TransactionManager</depends>
  | 
  |       <!-- Use our custom TxManagerLookup class -->
  |       <attribute name="TransactionManagerLookupClass">org.defy.tx.CustomTxManagerLookup</attribute>
  | 
  |       <!--
  |           Node locking level : SERIALIZABLE
  |                                REPEATABLE_READ (default)
  |                                READ_COMMITTED
  |                                READ_UNCOMMITTED
  |                                NONE
  |       -->
  |       <attribute name="IsolationLevel">REPEATABLE_READ</attribute>
  | 
  |       <!-- Lock parent before doing node additions/removes -->
  |       <attribute name="LockParentForChildInsertRemove">true</attribute>
  | 
  |       <!--
  |            Valid modes are LOCAL
  |                            REPL_ASYNC
  |                            REPL_SYNC
  |                            INVALIDATION_ASYNC
  |                            INVALIDATION_SYNC
  |       -->
  | 
  | 	<attribute name="CacheMode">REPL_SYNC</attribute>
  | 	<!--<attribute name="CacheMode">LOCAL</attribute>-->
  | 
  |       <!-- Name of cluster. Needs to be the same for all JBoss Cache nodes in a
  |            cluster in order to find each other. -->
  |       <attribute name="ClusterName">SHARD_CLUSTER</attribute>
  | 
  |       <!--Uncomment next three statements to enable JGroups multiplexer.
  |          This configuration is dependent on the JGroups multiplexer being
  |          registered in an MBean server such as JBossAS.  -->
  |       <!--
  |       <depends>jgroups.mux:name=Multiplexer</depends>
  |       <attribute name="MultiplexerService">jgroups.mux:name=Multiplexer</attribute>
  |       <attribute name="MultiplexerStack">fc-fast-minimalthreads</attribute>
  |       -->
  | 
  |       <!-- JGroups protocol stack properties.
  |          ClusterConfig isn't used if the multiplexer is enabled and successfully initialized.
  |       -->
  |       <attribute name="ClusterConfig">
  |          <config>
  |             <!-- UDP: if you have a multihomed machine,
  |   set the bind_addr attribute to the appropriate NIC IP address -->
  |             <!-- UDP: On Windows machines, because of the media sense feature
  |       being broken with multicast (even after disabling media sense)
  |       set the loopback attribute to true -->
  |             <UDP mcast_addr="228.1.2.3" mcast_port="48866"
  |                  ip_ttl="64" ip_mcast="true"
  |                  mcast_send_buf_size="150000" mcast_recv_buf_size="80000"
  |                  ucast_send_buf_size="150000" ucast_recv_buf_size="80000"
  |                  loopback="true"/>
  |             <PING timeout="2000" num_initial_members="3"
  |                   up_thread="false" down_thread="false"/>
  |             <MERGE2 min_interval="10000" max_interval="20000"/>
  |             <FD shun="true" up_thread="true" down_thread="true"/>
  |             <VERIFY_SUSPECT timeout="1500"
  |                             up_thread="false" down_thread="false"/>
  |             <pbcast.NAKACK gc_lag="50" retransmit_timeout="600,1200,2400,4800"
  |                            max_xmit_size="8192" up_thread="false" down_thread="false"/>
  |             <UNICAST timeout="600,1200,2400" down_thread="false"/>
  |             <pbcast.STABLE desired_avg_gossip="20000"
  |                            up_thread="false" down_thread="false"/>
  |             <FRAG frag_size="8192"
  |                   down_thread="false" up_thread="false"/>
  |             <pbcast.GMS join_timeout="5000" join_retry_timeout="2000"
  |                         shun="true" print_local_addr="true"/>
  |             <pbcast.STATE_TRANSFER up_thread="false" down_thread="false"/>
  |          </config>
  |       </attribute>
  | 
  | 
  |       <!--
  |           The max amount of time (in milliseconds) we wait until the
  |           initial state (ie. the contents of the cache) are retrieved from
  |           existing members in a clustered environment
  |       -->
  |       <attribute name="InitialStateRetrievalTimeout">20000</attribute>
  |       <attribute name="FetchInMemoryState">true</attribute>
  | 
  |       <!--
  |           Number of milliseconds to wait until all responses for a
  |           synchronous call have been received.
  |       -->
  |       <attribute name="SyncReplTimeout">20000</attribute>
  | 
  |       <!-- Max number of milliseconds to wait for a lock acquisition -->
  |       <attribute name="LockAcquisitionTimeout">15000</attribute>
  | 
  |       <attribute name="EvictionPolicyConfig">
  |          <config>
  |             <attribute name="wakeUpIntervalSeconds">5</attribute>
  |             <!-- This defaults to 200000 if not specified -->
  |             <attribute name="eventQueueSize">200000</attribute>
  |             <attribute name="policyClass">org.jboss.cache.eviction.FIFOPolicy</attribute>
  | 
  |             <!-- Cache wide default -->
  |             <region name="/_default_">
  |             	<!-- We're allowing an unlimited number of nodes for now. -->
  |                <attribute name="maxNodes">0</attribute>
  |             </region>
  |             
  |          </config>
  |       </attribute>
  | 
  | 	<attribute name="CacheLoaderConfiguration">
  | 	<config>
  | 		<!-- comma delimited FQNs to preload -->
  | 		<passivation>false</passivation>
  | 		<preload>/</preload>
  | 		<shared>false</shared>
  | 
  | 		<cacheloader>
  | 			<class>org.jboss.cache.loader.bdbje.BdbjeCacheLoader</class>
  | 
  | 			<properties>
  | 			location=/tmp/filestore
  | 			transactional=false
  | 			</properties>
  | 			<async>false</async>
  | 			<fetchPersistentState>false</fetchPersistentState>
  | 			<ignoreModifications>false</ignoreModifications>
  | 			<purgeOnStartup>true</purgeOnStartup>
  | 		</cacheloader>
  |       </config>
  |       </attribute>
  | 
  |    </mbean>
  | </server>
  | 

thanks in advance,
frank

View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4047995#4047995

Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=4047995



More information about the jboss-user mailing list