1 Reply Latest reply on Jul 6, 2012 10:31 AM by galder.zamarreno

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

    saifeldeen

      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