1 2 Previous Next 18 Replies Latest reply on Mar 21, 2007 4:59 PM by Clebert Suconic

    Test cases take a long time

    Sergey Koshcheyev Newbie

      I'm trying to get into JBoss Messaging and I decided to start by retrieving SVN trunk and running its test cases. I am able to start the tests according to the instructions on the Wiki and see them run, but they take a very long time to execute.

      The Wiki page says they should finish in about half an hour, however I've left them running all night twice and found they haven't finished in the morning. Right now it doesn't look like any single test case is the problem.

      Is this normal, given that my machine is a Dell Latitude D810, 2GHz CPU with 2Gb of RAM?

        • 1. Re: Test cases take a long time
          Sergey Koshcheyev Newbie

          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
            Tim Fox Master

            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
              Sergey Koshcheyev Newbie

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

              • 4. Re: Test cases take a long time
                Tim Fox Master

                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
                  Sergey Koshcheyev Newbie

                  The ConnectionTest timed out, the rest are fine.

                  • 6. Re: Test cases take a long time
                    Sergey Koshcheyev Newbie

                    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 Master

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

                      • 8. Re: Test cases take a long time
                        Tim Fox Master

                        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
                          Sergey Koshcheyev Newbie

                          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
                            Sergey Koshcheyev Newbie

                            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.
                            


                            • 11. Re: Test cases take a long time
                              Tim Fox Master

                              Can you post the kill -3 output?

                              What you posted just looks like exception logging from the logs.

                              • 12. Re: Test cases take a long time
                                Tim Fox Master

                                Ok I see you posted it just as a posted the last message! :)

                                • 13. Re: Test cases take a long time
                                  Clebert Suconic Master

                                  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.

                                  • 14. Re: Test cases take a long time
                                    Clebert Suconic Master

                                     

                                    "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.

                                    1 2 Previous Next