1 Reply Latest reply: Jul 6, 2012 10:31 AM by Galder Zamarreño RSS

Multithreaded access to remote ejb on initial invocation in clustered environment fails with TimeoutException

saifeldeen X Newbie

Hi all,

 

We have experienced a strange problem using Infinispan 4.2.0-FINAL under JBoss 6.1.0-FINAL with the following setup:

  • 2 JBoss 6.1.0-FINAL instances in a clustered environment
  • Clustered JBoss instances run a single EJB (see below)
  • A remote client accessing the single EJB (see below)

 

We run the remote client so that it creates 15 instances of itself.  Each instance will make an invocation to get the remote EJB.  When each remote client accesses the EJB for the first time (using 15 instances of the remote client), the following error occurs both at client and server side:

 

jvm 1    | 17:03:44,532 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] Execution error: : org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [15 seconds] on key [NodeKey{contents=DATA, fqn=/testEjb/TestEjb}] for requestor [Thread[RMI TCP Connection(35)-192.168.1.35,5,RMI Runtime]]! Lock held by [Thread[RMI TCP Connection(34)-192.168.1.35,5,RMI Runtime]]

jvm 1    |      at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:228) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:155) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:107) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.LockingInterceptor.visitPutKeyValueCommand(LockingInterceptor.java:296) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:58) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:182) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.TxInterceptor.visitPutKeyValueCommand(TxInterceptor.java:130) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.CacheMgmtInterceptor.visitPutKeyValueCommand(CacheMgmtInterceptor.java:113) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:87) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:58) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:58) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:76) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:58) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.CacheDelegate.putIfAbsent(CacheDelegate.java:453) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.CacheSupport.putIfAbsent(CacheSupport.java:40) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.atomic.AtomicHashMap.newInstance(AtomicHashMap.java:75) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.atomic.AtomicMapLookup.getAtomicMap(AtomicMapLookup.java:53) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.atomic.AtomicMapLookup.getAtomicMap(AtomicMapLookup.java:34) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.tree.TreeStructureSupport.getAtomicMap(TreeStructureSupport.java:125) [:4.2.0.FINAL]

jvm 1    |      at org.infinispan.tree.TreeCacheImpl.get(TreeCacheImpl.java:177) [:4.2.0.FINAL]

jvm 1    |      at org.jboss.ha.jndi.ispn.DistributedTreeManager.lookup(DistributedTreeManager.java:307) [:1.0.0.Final]

jvm 1    |      at org.jboss.ha.jndi.HAJNDI.lookup(HAJNDI.java:130) [:6.1.0.Final]

jvm 1    |      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [:1.6.0_29]

jvm 1    |      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [:1.6.0_29]

jvm 1    |      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [:1.6.0_29]

jvm 1    |      at java.lang.reflect.Method.invoke(Method.java:597) [:1.6.0_29]

jvm 1    |      at org.jboss.ha.framework.server.HARMIServerImpl.invoke(HARMIServerImpl.java:210) [:2.0.0.Final]

jvm 1    |      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [:1.6.0_29]

jvm 1    |      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [:1.6.0_29]

jvm 1    |      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [:1.6.0_29]

jvm 1    |      at java.lang.reflect.Method.invoke(Method.java:597) [:1.6.0_29]

jvm 1    |      at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:303) [:1.6.0_29]

jvm 1    |      at sun.rmi.transport.Transport$1.run(Transport.java:159) [:1.6.0_29]

jvm 1    |      at java.security.AccessController.doPrivileged(Native Method) [:1.6.0_29]

jvm 1    |      at sun.rmi.transport.Transport.serviceCall(Transport.java:155) [:1.6.0_29]

jvm 1    |      at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535) [:1.6.0_29]

jvm 1    |      at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790) [:1.6.0_29]

jvm 1    |      at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649) [:1.6.0_29]

jvm 1    |      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [:1.6.0_29]

jvm 1    |      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [:1.6.0_29]

jvm 1    |      at java.lang.Thread.run(Thread.java:662) [:1.6.0_29]

 

Here is the test case that generate the same problem

 

public class MultiThreadedAccessToRemoteEJBTest

{

    private final Properties jndiProps = new Properties();

    private static final int NUMBER_OF_THREADS = 15;

 

    @Test

    public void testMultithreadedAccessToRemoteEJB() throws Exception

    {

        jndiProps.put("java.naming.factory.initial","org.jnp.interfaces.NamingContextFactory");

        jndiProps.put("java.naming.factory.url.pkgs","org.jboss.naming:org.jnp.interfaces");

        jndiProps.put("jnp.partitionName","DocsPartition");

        jndiProps.put("jnp.discoveryGroup","239.1.35.1");

        for (int i = 0; i < NUMBER_OF_THREADS; i++)

        {

            ICThread t = new ICThread();

            t.start();

        }

        Thread.sleep(30 * 1000);

    }

    private class ICThread extends Thread

    {

        public void run()

        {

            try

            {

                InitialContext ic = new InitialContext(jndiProps);

                TestEjbRemote r = (TestEjbRemote) ic.lookup("testEjb/TestEjb/remote");

                System.out.println("Thread: "+this.getName() + " has remote bean! " + r);

            } catch (Exception e)

            {

                e.printStackTrace();

            }

        }

    }

}

 

The EJB (impl and remote below)

 

@Stateless

@Clustered(partition = "DocsPartition", loadBalancePolicy = "org.jboss.ha.client.loadbalance.RoundRobin")

public class TestEjb implements TestEjbLocal, TestEjbRemote

{

    public void sayHello()

    {

        System.out.println("Hello, world!");

    }

}

 

@Remote

public interface TestEjbRemote

{

    public void sayHello();

}

 

So, if we use:

  • Discovery groups (as the above shows), we get the exception above
  • HA JNDI, we also get the exception above
  • Regular JNDI ports, we do not get the problem

 

Can anyone please shed some light on this matter, e.g. is it a bug that our code needs to work around (i.e. by using regular JNDI ports)?  Can a configuration change in the infinispan xml prevent the above issue from occurring?

 

Regards,

Saifeldeen