[jboss-jira] [JBoss JIRA] (AS7-3638) EJB client threads waiting at EJBClientInvocationContext.awaitResponse

EJB client threads waiting at EJBClientInvocationContext.awaitResponse ---------------------------------------------------------------------- Key: AS7-3638 URL: https://issues.jboss.org/browse/AS7-3638 Project: Application Server 7 Issue Type: Feature Request Components: EJB Affects Versions: 7.1.0.Final Reporter: Radoslav Husar Assignee: jaikiran pai See threads named "Runner - 70". A timeout doesnt kick in? Maybe related to seeing ChannelBusyException: Too many open outbound writes before? {noformat} 2012-02-06 10:24:55 Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.5-b03 mixed mode): "Attach Listener" daemon prio=10 tid=0x00007fd160025000 nid=0x56e8 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "RMI TCP Connection(10)-10.16.90.52" daemon prio=10 tid=0x00007fd148002800 nid=0x4caf in Object.wait() [0x00007fd176ca7000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) at java.lang.Object.wait(Object.java:485) at org.jboss.smartfrog.loaddriver.LoadDriverImpl.stop(LoadDriverImpl.java:359) - locked <0x00000006bfeb2fc0> (a org.jboss.smartfrog.loaddriver.LoadDriverImpl) at org.jboss.smartfrog.loaddriver.LoadDriverImpl.setState(LoadDriverImpl.java:341) - locked <0x00000006bfeb2fc0> (a org.jboss.smartfrog.loaddriver.LoadDriverImpl) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:303) at sun.rmi.transport.Transport$1.run(Transport.java:159) at java.security.AccessController.doPrivileged(Native Method) at sun.rmi.transport.Transport.serviceCall(Transport.java:155) at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) "Remoting "config-based-ejb-client-endpoint" task-4" daemon prio=10 tid=0x00007fd0ac0a4000 nid=0x4675 waiting on condition [0x00007fd0959d1000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006bfeb2bf0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:399) at org.xnio.LimitedBlockingQueue.take(LimitedBlockingQueue.java:95) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) at java.lang.Thread.run(Thread.java:662) "Remoting "config-based-ejb-client-endpoint" task-3" daemon prio=10 tid=0x00007fd0ac07a800 nid=0x4674 waiting on condition [0x00007fd095ad2000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006bfeb2bf0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:399) at org.xnio.LimitedBlockingQueue.take(LimitedBlockingQueue.java:95) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) at java.lang.Thread.run(Thread.java:662) "Remoting "config-based-ejb-client-endpoint" task-2" daemon prio=10 tid=0x00007fd0ac04e800 nid=0x4673 waiting on condition [0x00007fd095bd3000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006bfeb2bf0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:399) at org.xnio.LimitedBlockingQueue.take(LimitedBlockingQueue.java:95) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) at java.lang.Thread.run(Thread.java:662) "Remoting "config-based-ejb-client-endpoint" task-1" daemon prio=10 tid=0x00007fd0ac04d000 nid=0x4672 waiting on condition [0x00007fd095cd4000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006bfeb2bf0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:399) at org.xnio.LimitedBlockingQueue.take(LimitedBlockingQueue.java:95) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) at java.lang.Thread.run(Thread.java:662) "Remoting "config-based-ejb-client-endpoint" write-1" daemon prio=10 tid=0x00007fd0d40cb000 nid=0x4671 runnable [0x00007fd095dd5000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method) at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210) at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69) - locked <0x00000006bfeb0d20> (a sun.nio.ch.Util$2) - locked <0x00000006bfeb0d30> (a java.util.Collections$UnmodifiableSet) - locked <0x00000006bfeb0cd8> (a sun.nio.ch.EPollSelectorImpl) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80) at org.xnio.nio.WorkerThread.run(WorkerThread.java:157) "Remoting "config-based-ejb-client-endpoint" read-1" daemon prio=10 tid=0x00007fd0d4096800 nid=0x4670 runnable [0x00007fd095ed6000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method) at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210) at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69) - locked <0x00000006bfeace78> (a sun.nio.ch.Util$2) - locked <0x00000006bfeace88> (a java.util.Collections$UnmodifiableSet) - locked <0x00000006bfeace30> (a sun.nio.ch.EPollSelectorImpl) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84) at org.xnio.nio.WorkerThread.run(WorkerThread.java:153) "Runner - 70" daemon prio=10 tid=0x00007fd13005e800 nid=0x4652 in Object.wait() [0x00007fd097dfc000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) at java.lang.Object.wait(Object.java:485) at org.jboss.ejb.client.EJBClientInvocationContext.awaitResponse(EJBClientInvocationContext.java:330) - locked <0x00000006c2944170> (a java.lang.Object) at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:126) at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:107) at org.jboss.ejb.client.EJBInvocationHandler.invoke(EJBInvocationHandler.java:90) at $Proxy0.getSerialAndIncrement(Unknown Source) at org.jboss.smartfrog.clustering.ejb3.StatefulSBProcessorFactoryImpl$EJB3RequestProcessor.processRequest(StatefulSBProcessorFactoryImpl.java:68) at org.jboss.smartfrog.loaddriver.CompoundRequestProcessorFactoryImpl$CompoundRequestProcessor.processRequest(CompoundRequestProcessorFactoryImpl.java:51) at org.jboss.smartfrog.loaddriver.Runner.run(Runner.java:87) at java.lang.Thread.run(Thread.java:662) "Runner - 42" daemon prio=10 tid=0x00007fd1300bc800 nid=0x4636 in Object.wait() [0x00007fd165a66000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) at java.lang.Object.wait(Object.java:485) at org.jboss.ejb.client.EJBClientInvocationContext.awaitResponse(EJBClientInvocationContext.java:330) - locked <0x00000006c2952170> (a java.lang.Object) at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:126) at org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:107) at org.jboss.ejb.client.EJBInvocationHandler.invoke(EJBInvocationHandler.java:90) at $Proxy0.getSerialAndIncrement(Unknown Source) at org.jboss.smartfrog.clustering.ejb3.StatefulSBProcessorFactoryImpl$EJB3RequestProcessor.processRequest(StatefulSBProcessorFactoryImpl.java:68) at org.jboss.smartfrog.loaddriver.CompoundRequestProcessorFactoryImpl$CompoundRequestProcessor.processRequest(CompoundRequestProcessorFactoryImpl.java:51) at org.jboss.smartfrog.loaddriver.Runner.run(Runner.java:87) at java.lang.Thread.run(Thread.java:662) "process reaper" daemon prio=10 tid=0x00007fd11c001000 nid=0x3aec runnable [0x00007fd17629e000] java.lang.Thread.State: RUNNABLE at java.lang.UNIXProcess.waitForProcessExit(Native Method) at java.lang.UNIXProcess.access$900(UNIXProcess.java:20) at java.lang.UNIXProcess$1$1.run(UNIXProcess.java:132) "Thread-9" daemon prio=10 tid=0x00007fd13006d000 nid=0x3aea waiting on condition [0x00007fd1764a0000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.jboss.smartfrog.stats.collector.JVMMemoryStatsCollector.run(JVMMemoryStatsCollector.java:223) at java.lang.Thread.run(Thread.java:662) "Thread-8" daemon prio=10 tid=0x00007fd13009b800 nid=0x3ae9 runnable [0x00007fd1765a1000] java.lang.Thread.State: RUNNABLE at java.io.FileInputStream.readBytes(Native Method) at java.io.FileInputStream.read(FileInputStream.java:220) at java.io.BufferedInputStream.read1(BufferedInputStream.java:256) at java.io.BufferedInputStream.read(BufferedInputStream.java:317) - locked <0x00000006bfed9978> (a java.io.BufferedInputStream) at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264) at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158) - locked <0x00000006bfed9a30> (a java.io.InputStreamReader) at java.io.InputStreamReader.read(InputStreamReader.java:167) at java.io.BufferedReader.fill(BufferedReader.java:136) at java.io.BufferedReader.readLine(BufferedReader.java:299) - locked <0x00000006bfed9a30> (a java.io.InputStreamReader) at java.io.BufferedReader.readLine(BufferedReader.java:362) at org.jboss.smartfrog.stats.collector.CPUStatsCollector.run(CPUStatsCollector.java:120) at java.lang.Thread.run(Thread.java:662) "RMI RenewClean-[10.16.90.52:58690]" daemon prio=10 tid=0x00007fd13001e000 nid=0x3ab5 in Object.wait() [0x00007fd176ba7000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) - locked <0x00000006bff744b8> (a java.lang.ref.ReferenceQueue$Lock) at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:516) at java.lang.Thread.run(Thread.java:662) "RMI Scheduler(0)" daemon prio=10 tid=0x00007fd138021800 nid=0x3ab2 waiting on condition [0x00007fd176da9000] java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006bfe94480> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:196) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025) at java.util.concurrent.DelayQueue.take(DelayQueue.java:164) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) at java.lang.Thread.run(Thread.java:662) "DestroyJavaVM" prio=10 tid=0x00007fd1a0008000 nid=0x3930 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "RMI TCP Accept-3800" daemon prio=10 tid=0x00007fd1a00ab800 nid=0x3946 runnable [0x00007fd177381000] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:408) - locked <0x00000006bfec6db0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:462) at java.net.ServerSocket.accept(ServerSocket.java:430) at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:369) at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:341) at java.lang.Thread.run(Thread.java:662) "GC Daemon" daemon prio=10 tid=0x00007fd1a0480800 nid=0x3945 in Object.wait() [0x00007fd177482000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00000006bfe0c798> (a sun.misc.GC$LatencyLock) at sun.misc.GC$Daemon.run(GC.java:100) - locked <0x00000006bfe0c798> (a sun.misc.GC$LatencyLock) "RMI Reaper" prio=10 tid=0x00007fd1a0465800 nid=0x3944 in Object.wait() [0x00007fd177583000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00000006bfe00100> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) - locked <0x00000006bfe00100> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134) at sun.rmi.transport.ObjectTable$Reaper.run(ObjectTable.java:333) at java.lang.Thread.run(Thread.java:662) "RMI TCP Accept-0" daemon prio=10 tid=0x00007fd1a03f3800 nid=0x3943 runnable [0x00007fd177684000] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:408) - locked <0x00000006bfe067c0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:462) at java.net.ServerSocket.accept(ServerSocket.java:430) at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:369) at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:341) at java.lang.Thread.run(Thread.java:662) "Low Memory Detector" daemon prio=10 tid=0x00007fd1a033f000 nid=0x393f runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C2 CompilerThread1" daemon prio=10 tid=0x00007fd1a033c800 nid=0x393e waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C2 CompilerThread0" daemon prio=10 tid=0x00007fd1a0339800 nid=0x393d waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x00007fd1a0337800 nid=0x393c runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=10 tid=0x00007fd1a0076000 nid=0x393b in Object.wait() [0x00007fd177ffe000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) - locked <0x00000006bfe0c9d8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x00007fd1a0074000 nid=0x393a in Object.wait() [0x00007fd19c154000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x00000006bfe0c778> (a java.lang.ref.Reference$Lock) "VM Thread" prio=10 tid=0x00007fd1a006d800 nid=0x3939 runnable "GC task thread#0 (ParallelGC)" prio=10 tid=0x00007fd1a001b000 nid=0x3931 runnable "GC task thread#1 (ParallelGC)" prio=10 tid=0x00007fd1a001d000 nid=0x3932 runnable "GC task thread#2 (ParallelGC)" prio=10 tid=0x00007fd1a001e800 nid=0x3933 runnable "GC task thread#3 (ParallelGC)" prio=10 tid=0x00007fd1a0020800 nid=0x3934 runnable "GC task thread#4 (ParallelGC)" prio=10 tid=0x00007fd1a0022800 nid=0x3935 runnable "GC task thread#5 (ParallelGC)" prio=10 tid=0x00007fd1a0024000 nid=0x3936 runnable "GC task thread#6 (ParallelGC)" prio=10 tid=0x00007fd1a0026000 nid=0x3937 runnable "GC task thread#7 (ParallelGC)" prio=10 tid=0x00007fd1a0027800 nid=0x3938 runnable "VM Periodic Task Thread" prio=10 tid=0x00007fd1a0351800 nid=0x3940 waiting on condition JNI global references: 1774 {noformat} Maybe relates to? {noformat} 2012/02/06 10:07:33:064 EST [WARN ][Runner - 78] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error sampling data: org.jboss.smartfrog.loaddriver.RequestProcessingException: Could not lookup session bean. at org.jboss.smartfrog.clustering.ejb3.StatefulSBProcessorFactoryImpl$EJB3RequestProcessor.initSession(StatefulSBProcessorFactoryImpl.java:157) at org.jboss.smartfrog.clustering.ejb3.StatefulSBProcessorFactoryImpl$EJB3RequestProcessor.processRequest(StatefulSBProcessorFactoryImpl.java:58) at org.jboss.smartfrog.loaddriver.CompoundRequestProcessorFactoryImpl$CompoundRequestProcessor.processRequest(CompoundRequestProcessorFactoryImpl.java:51) at org.jboss.smartfrog.loaddriver.Runner.run(Runner.java:87) at java.lang.Thread.run(Thread.java:662) Caused by: javax.naming.NamingException: Failed to create proxy [Root exception is java.lang.RuntimeException: org.jboss.remoting3.ChannelBusyException: Too many open outbound writes] at org.jboss.ejb.client.naming.ejb.EjbNamingContext.createEjbProxy(EjbNamingContext.java:115) at org.jboss.ejb.client.naming.ejb.EjbNamingContext.lookup(EjbNamingContext.java:96) at javax.naming.InitialContext.lookup(InitialContext.java:392) at org.jboss.smartfrog.clustering.ejb3.StatefulSBProcessorFactoryImpl$EJB3RequestProcessor.initSession(StatefulSBProcessorFactoryImpl.java:148) ... 4 more Caused by: java.lang.RuntimeException: org.jboss.remoting3.ChannelBusyException: Too many open outbound writes at org.jboss.ejb.client.remoting.RemotingConnectionEJBReceiver.openSession(RemotingConnectionEJBReceiver.java:197) at org.jboss.ejb.client.EJBClient.createSession(EJBClient.java:163) at org.jboss.ejb.client.naming.ejb.EjbNamingContext.doCreateProxy(EjbNamingContext.java:135) at org.jboss.ejb.client.naming.ejb.EjbNamingContext.createEjbProxy(EjbNamingContext.java:113) ... 7 more Caused by: org.jboss.remoting3.ChannelBusyException: Too many open outbound writes at org.jboss.remoting3.remote.RemoteConnectionChannel.openOutboundMessage(RemoteConnectionChannel.java:108) at org.jboss.remoting3.remote.RemoteConnectionChannel.writeMessage(RemoteConnectionChannel.java:293) at org.jboss.ejb.client.remoting.RemotingConnectionEJBReceiver.openSession(RemotingConnectionEJBReceiver.java:195) ... 10 more {noformat}