BdbjeCacheLoader exception with JTA distributed transactions
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@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
