Test cases take a long time| JBoss.org Content Archive (Read Only)

1. Re: Test cases take a long time

sergeypk Mar 15, 2007 10:11 AM (in response to sergeypk)

I found a test that seems to take a lot of time: ConnectionTest.testManyConnections (running as remote test). It has been running for about half an hour for me already. Given that it doesn't do much, I'm puzzled as to why it runs so slow.

2. Re: Test cases take a long time

timfox Mar 15, 2007 10:33 AM (in response to sergeypk)

IIRC the full test run takes about 3.5 hours for me on a D810.

What database are you running against?

3. Re: Test cases take a long time

sergeypk Mar 15, 2007 10:45 AM (in response to sergeypk)

MySQL 5.0. Should I try a different one? HSQL seemed to be about as slow.

4. Re: Test cases take a long time

timfox Mar 15, 2007 11:02 AM (in response to sergeypk)

MySQL is fine.

Sounds like something is wrong - are you sure your tests aren't timing out?

The ones that you have run so far - are they passing or failing?

5. Re: Test cases take a long time

sergeypk Mar 15, 2007 11:33 AM (in response to sergeypk)

The ConnectionTest timed out, the rest are fine.

6. Re: Test cases take a long time

sergeypk Mar 15, 2007 2:30 PM (in response to sergeypk)

Latest update:
Thanks to Clebert, I managed to run ConnectionTest.testManyConnections by itself. The test is simply createConnection()/close() in a loop, 1000 times.

I then looked at the logs it produces, and from there it looks like the client makes 300 connections successfully, and blocks on the 301st indefinitely. What could be the reason? I already tried applying the modification Kevin Conner described in http://www.jboss.com/index.html?module=bb&op=viewtopic&t=103695 but it didn't help.

7. Re: Test cases take a long time

clebert.suconic Mar 15, 2007 2:49 PM (in response to sergeypk)

I have moved this thread to "Design of Messaging on JBoss (Messaging/JBoss)".

8. Re: Test cases take a long time

timfox Mar 15, 2007 2:51 PM (in response to sergeypk)

Can you do a kill -3 (or CTRL-BREAK) and post the stacks dump when the test hangs?

9. Re: Test cases take a long time

sergeypk Mar 15, 2007 3:07 PM (in response to sergeypk)

Here it is:

19:57:08,296 DEBUG @WorkerThread#0[127.0.0.1:1946] [ServerSocketWrapper] cannot write CLOSING byte
java.net.SocketException: Connection reset by peer: socket write error
 at java.net.SocketOutputStream.socketWrite0(Native Method)
 at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
 at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
 at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
 at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
 at java.io.DataOutputStream.flush(DataOutputStream.java:106)
 at org.jboss.jms.server.remoting.ServerSocketWrapper.close(ServerSocketWrapper.java:74)
 at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:475)
 at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:159)
19:57:08,296 DEBUG @WorkerThread#0[127.0.0.1:1946] [SocketWrapper] ServerSocketWrapper[Socket[addr=/127.0.0.1,port=1946,localport=3996].63ae08] closing

(repeated 301 times with different port numbers)

there's also this slightly different stack trace in there:

19:57:08,296 ERROR @WorkerThread#0[127.0.0.1:2846] [ServerThread] Worker thread initialization failure
java.net.SocketException: Connection reset
 at java.net.SocketInputStream.read(SocketInputStream.java:168)
 at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
 at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
 at java.io.FilterInputStream.read(FilterInputStream.java:66)
 at org.jboss.remoting.transport.socket.ServerThread.readVersion(ServerThread.java:795)
 at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:500)
 at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:363)
 at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:159)

10. Re: Test cases take a long time

sergeypk Mar 15, 2007 3:10 PM (in response to sergeypk)

Ok that was apparently the wrong thing (thanks Clebert), here's what you actually want:

2007-03-15 20:09:22
Full thread dump Java HotSpot(TM) Client VM (1.6.0-b105 mixed mode):

"Timer-2" daemon prio=6 tid=0x49009c00 nid=0x1188 in Object.wait() [0x496bf000..0x496bfd94]
 java.lang.Thread.State: WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <0x079e7650> (a java.util.TaskQueue)
 at java.lang.Object.wait(Object.java:485)
 at java.util.TimerThread.mainLoop(Timer.java:483)
 - locked <0x079e7650> (a java.util.TaskQueue)
 at java.util.TimerThread.run(Timer.java:462)

"Timer-1" daemon prio=6 tid=0x49068c00 nid=0x1150 in Object.wait() [0x4966f000..0x4966fa14]
 java.lang.Thread.State: WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <0x079af8a8> (a java.util.TaskQueue)
 at java.lang.Object.wait(Object.java:485)
 at java.util.TimerThread.mainLoop(Timer.java:483)
 - locked <0x079af8a8> (a java.util.TaskQueue)
 at java.util.TimerThread.run(Timer.java:462)

"Timer-0" daemon prio=6 tid=0x48fd5c00 nid=0x1cdc in Object.wait() [0x495cf000..0x495cfb14]
 java.lang.Thread.State: WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <0x079a3420> (a java.util.TaskQueue)
 at java.lang.Object.wait(Object.java:485)
 at java.util.TimerThread.mainLoop(Timer.java:483)
 - locked <0x079a3420> (a java.util.TaskQueue)
 at java.util.TimerThread.run(Timer.java:462)

"GC Daemon" daemon prio=2 tid=0x4921fc00 nid=0x174c in Object.wait() [0x4956f000..0x4956fb94]
 java.lang.Thread.State: TIMED_WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <0x0790eb50> (a sun.misc.GC$LatencyLock)
 at sun.misc.GC$Daemon.run(GC.java:100)
 - locked <0x0790eb50> (a sun.misc.GC$LatencyLock)

"RMI RenewClean-[10.32.4.81:3795]" daemon prio=6 tid=0x49239400 nid=0x1d34 in Object.wait() [0x4951f000..0x4951fc14]
 java.lang.Thread.State: TIMED_WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <0x078f5310> (a java.lang.ref.ReferenceQueue$Lock)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
 - locked <0x078f5310> (a java.lang.ref.ReferenceQueue$Lock)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:516)
 at java.lang.Thread.run(Thread.java:619)

"RMI Scheduler(0)" daemon prio=6 tid=0x4920a400 nid=0x93c waiting on condition [0x494cf000..0x494cfc94]
 java.lang.Thread.State: WAITING (parking)
 at sun.misc.Unsafe.park(Native Method)
 - parking to wait for <0x078d8440> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
 at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1889)
 at java.util.concurrent.DelayQueue.take(DelayQueue.java:160)
 at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:582)
 at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:575)
 at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:946)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:906)
 at java.lang.Thread.run(Thread.java:619)

"Server 0 STDERR reader thread" prio=6 tid=0x491ec400 nid=0x12f0 runnable [0x4947f000..0x4947fd14]
 java.lang.Thread.State: RUNNABLE
 at java.io.FileInputStream.readBytes(Native Method)
 at java.io.FileInputStream.read(FileInputStream.java:199)
 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 <0x0790a818> (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 <0x0790a818> (a java.io.InputStreamReader)
 at java.io.BufferedReader.readLine(BufferedReader.java:362)
 at org.jboss.test.messaging.tools.ServerManagement$2.run(ServerManagement.java:500)
 at java.lang.Thread.run(Thread.java:619)

"Server 0 STDOUT reader thread" prio=6 tid=0x491ebc00 nid=0x13fc runnable [0x4942f000..0x4942fd94]
 java.lang.Thread.State: RUNNABLE
 at java.io.FileInputStream.readBytes(Native Method)
 at java.io.FileInputStream.read(FileInputStream.java:199)
 at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
 at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
 - locked <0x078ee2e0> (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 <0x078ee328> (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 <0x078ee328> (a java.io.InputStreamReader)
 at java.io.BufferedReader.readLine(BufferedReader.java:362)
 at org.jboss.test.messaging.tools.ServerManagement$1.run(ServerManagement.java:476)
 at java.lang.Thread.run(Thread.java:619)

"Low Memory Detector" daemon prio=6 tid=0x48a81c00 nid=0x1a14 runnable [0x00000000..0x00000000]
 java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x48a7d000 nid=0x9e8 waiting on condition [0x00000000..0x48ccf898]
 java.lang.Thread.State: RUNNABLE

"Attach Listener" daemon prio=10 tid=0x48a7c000 nid=0x5d4 runnable [0x00000000..0x00000000]
 java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x48a7b000 nid=0x1364 waiting on condition [0x00000000..0x00000000]
 java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=8 tid=0x48a6b800 nid=0x18a8 in Object.wait() [0x48bdf000..0x48bdfc94]
 java.lang.Thread.State: WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <0x07894f60> (a java.lang.ref.ReferenceQueue$Lock)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
 - locked <0x07894f60> (a java.lang.ref.ReferenceQueue$Lock)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
 at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x48a67400 nid=0x6c4 in Object.wait() [0x48b8f000..0x48b8fd14]
 java.lang.Thread.State: WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <0x07894ff0> (a java.lang.ref.Reference$Lock)
 at java.lang.Object.wait(Object.java:485)
 at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
 - locked <0x07894ff0> (a java.lang.ref.Reference$Lock)

"main" prio=6 tid=0x002eb400 nid=0x1864 runnable [0x0091e000..0x0091fe54]
 java.lang.Thread.State: RUNNABLE
 at java.net.SocketInputStream.socketRead0(Native Method)
 at java.net.SocketInputStream.read(SocketInputStream.java:129)
 at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
 at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
 - locked <0x02d54a18> (a java.io.BufferedInputStream)
 at java.io.FilterInputStream.read(FilterInputStream.java:66)
 at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.readVersion(MicroSocketClientInvoker.java:973)
 at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:567)
 at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:269)
 at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:122)
 at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.getSecondaryLocator(BisocketClientInvoker.java:393)
 at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.handleConnect(BisocketClientInvoker.java:200)
 at org.jboss.remoting.MicroRemoteClientInvoker.connect(MicroRemoteClientInvoker.java:242)
 - locked <0x02d22330> (a org.jboss.remoting.transport.bisocket.BisocketClientInvoker)
 at org.jboss.remoting.Client.connect(Client.java:1401)
 at org.jboss.remoting.Client.connect(Client.java:441)
 at org.jboss.jms.client.remoting.JMSRemotingConnection.start(JMSRemotingConnection.java:271)
 at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate.org$jboss$jms$client$delegate$ClientConnectionFactoryDelegate$createConnectionDelegate$aop(ClientConnectionFactoryDelegate.java:146)
 at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate$createConnectionDelegate_4579211046834694258.invokeNext(ClientConnectionFactoryDelegate$createConnectionDelegate_4579211046834694258.java)
 at org.jboss.jms.client.container.StateCreationAspect.handleCreateConnectionDelegate(StateCreationAspect.java:83)
 at org.jboss.aop.advice.org.jboss.jms.client.container.StateCreationAspect0.invoke(StateCreationAspect0.java)
 at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate$createConnectionDelegate_4579211046834694258.invokeNext(ClientConnectionFactoryDelegate$createConnectionDelegate_4579211046834694258.java)
 at org.jboss.jms.client.container.ExceptionInterceptor.invoke(ExceptionInterceptor.java:71)
 at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate$createConnectionDelegate_4579211046834694258.invokeNext(ClientConnectionFactoryDelegate$createConnectionDelegate_4579211046834694258.java)
 at org.jboss.jms.client.container.ClientLogInterceptor.invoke(ClientLogInterceptor.java:107)
 at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate$createConnectionDelegate_4579211046834694258.invokeNext(ClientConnectionFactoryDelegate$createConnectionDelegate_4579211046834694258.java)
 at org.jboss.jms.client.delegate.ClientConnectionFactoryDelegate.createConnectionDelegate(ClientConnectionFactoryDelegate.java)
 at org.jboss.jms.client.JBossConnectionFactory.createConnectionInternal(JBossConnectionFactory.java:212)
 at org.jboss.jms.client.JBossConnectionFactory.createConnection(JBossConnectionFactory.java:88)
 at org.jboss.jms.client.JBossConnectionFactory.createConnection(JBossConnectionFactory.java:83)
 at org.jboss.test.messaging.jms.ConnectionTest.testManyConnections(ConnectionTest.java:198)
 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 junit.framework.TestCase.runTest(TestCase.java:154)
 at junit.framework.TestCase.runBare(TestCase.java:127)
 at junit.framework.TestResult$1.protect(TestResult.java:106)
 at junit.framework.TestResult.runProtected(TestResult.java:124)
 at junit.framework.TestResult.run(TestResult.java:109)
 at junit.framework.TestCase.run(TestCase.java:118)
 at junit.framework.TestSuite.runTest(TestSuite.java:208)
 at junit.framework.TestSuite.run(TestSuite.java:203)
 at junit.textui.TestRunner.doRun(TestRunner.java:116)
 at junit.textui.TestRunner.start(TestRunner.java:172)
 at org.jboss.test.messaging.tools.junit.SelectiveTestRunner.main(SelectiveTestRunner.java:58)

"VM Thread" prio=10 tid=0x48a64400 nid=0x18cc runnable

"VM Periodic Task Thread" prio=10 tid=0x48aa4800 nid=0x1518 waiting on condition

JNI global references: 1063

Heap
 def new generation total 5184K, used 4423K [0x029b0000, 0x02f40000, 0x07870000)
 eden space 4672K, 83% used [0x029b0000, 0x02d81e68, 0x02e40000)
 from space 512K, 100% used [0x02ec0000, 0x02f40000, 0x02f40000)
 to space 512K, 0% used [0x02e40000, 0x02e40000, 0x02ec0000)
 tenured generation total 68184K, used 50115K [0x07870000, 0x0bb06000, 0x429b0000)
 the space 68184K, 73% used [0x07870000, 0x0a960c48, 0x0a960e00, 0x0bb06000)
 compacting perm gen total 12288K, used 9227K [0x429b0000, 0x435b0000, 0x469b0000)
 the space 12288K, 75% used [0x429b0000, 0x432b2ef8, 0x432b3000, 0x435b0000)
No shared spaces configured.

"clebert.suconic@jboss.com" wrote:
Welcome to the team Sergey... You have definitely stepped into something stinky :-) (Good way to start with the right foot)

The test takes a long time to me too... probably associated with the leakage (close/open) pointed out on the other thread.

It takes about 5 minutes to complete the test on my computer. It's slow but it doesn't hang forever.

JBossDeveloper

Test cases take a long time