You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by Martin Ritchie <ri...@apache.org> on 2008/07/10 17:28:33 UTC

Trunk Java-09-Unit Test Hang

Ok, I'm can't see why this has locked my JVM up.

It appears as though the main thread is having difficulting doing the
put but I can't see why.

Rafi, is there anyway to stop the tests buffering the output until the
test end? or is it just the way that JUnit formatters work?

Cheers

Martin


    [junit] Running
org.apache.qpid.test.unit.client.connection.ConnectionCloseTest
2008-07-10 16:08:25
Full thread dump Java HotSpot(TM) Server VM (10.0-b22 mixed mode):

"pool-6-thread-4" prio=10 tid=0x088b1400 nid=0x19ca waiting on
condition [0x8fa18000..0x8fa19120]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x95ce4d30> (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:1925)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)
	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)

"pool-6-thread-3" prio=10 tid=0x094e4400 nid=0x19c9 waiting on
condition [0x8f960000..0x8f960da0]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x95ce4d30> (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:1925)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)
	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)

"pool-6-thread-2" prio=10 tid=0x8fde0400 nid=0x19c8 waiting on
condition [0x8fa69000..0x8fa69e20]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x95ce4d30> (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:1925)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)
	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)

"pool-6-thread-1" prio=10 tid=0x8fdcb000 nid=0x19c7 waiting on
condition [0x8f7fe000..0x8f7feea0]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x95ce4d30> (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:1925)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)
	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)

"VmPipeIdleStatusChecker" daemon prio=10 tid=0x08378400 nid=0x19ac
waiting for monitor entry [0x8faba000..0x8fabaea0]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.mina.transport.vmpipe.support.VmPipeIdleStatusChecker$Worker.run(VmPipeIdleStatusChecker.java:84)
	- waiting to lock <0x95c69df8> (a java.util.IdentityHashMap)

"PooledByteBufferExpirer-0" daemon prio=10 tid=0x085f7c00 nid=0x19ab
waiting on condition [0x8fffe000..0x8fffef20]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at org.apache.mina.common.PooledByteBufferAllocator$Expirer.run(PooledByteBufferAllocator.java:277)

"Queue-housekeeping-test" daemon prio=10 tid=0x08115000 nid=0x19aa in
Object.wait() [0x8ff9f000..0x8ff9ffa0]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x95c69ea0> (a java.util.TaskQueue)
	at java.util.TimerThread.mainLoop(Timer.java:509)
	- locked <0x95c69ea0> (a java.util.TaskQueue)
	at java.util.TimerThread.run(Timer.java:462)

"PooledByteBufferExpirer-0" daemon prio=10 tid=0x085f9800 nid=0x19a0
waiting on condition [0x901ad000..0x901ae0a0]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at org.apache.mina.common.PooledByteBufferAllocator$Expirer.run(PooledByteBufferAllocator.java:277)

"pool-2-thread-4" prio=10 tid=0x09138c00 nid=0x199f waiting on
condition [0x9015c000..0x9015d120]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x95abe810> (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:1925)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)
	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)

"pool-2-thread-3" prio=10 tid=0x08895c00 nid=0x199e waiting on
condition [0x901fe000..0x901feda0]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x95abe810> (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:1925)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)
	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)

"pool-2-thread-2" prio=10 tid=0x094e1400 nid=0x199d waiting on
condition [0x8fbfe000..0x8fbfee20]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x95abe810> (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:1925)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)
	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)

"pool-2-thread-1" prio=10 tid=0x08190000 nid=0x199c waiting on
condition [0x8fbad000..0x8fbadea0]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x95abe810> (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:1925)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)
	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)

"Queue-housekeeping-test" daemon prio=10 tid=0x08344c00 nid=0x199b in
Object.wait() [0x903fe000..0x903fef20]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x95abf448> (a java.util.TaskQueue)
	at java.util.TimerThread.mainLoop(Timer.java:509)
	- locked <0x95abf448> (a java.util.TaskQueue)
	at java.util.TimerThread.run(Timer.java:462)

"AnonymousIoService-2" daemon prio=10 tid=0x09d16800 nid=0x1993 in
Object.wait() [0x9035c000..0x9035cda0]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x95a3aa28> (a
edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
	at java.lang.Object.wait(Object.java:485)
	at edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:316)
	- locked <0x95a3aa28> (a
edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
	at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:493)
	at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:689)
	at java.lang.Thread.run(Thread.java:619)

"AnonymousIoService-1" daemon prio=10 tid=0x0888cc00 nid=0x1992 in
Object.wait() [0x903ad000..0x903ade20]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x95a3aa28> (a
edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
	at java.lang.Object.wait(Object.java:485)
	at edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:316)
	- locked <0x95a3aa28> (a
edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingQueue$SerializableLock)
	at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:493)
	at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:689)
	at java.lang.Thread.run(Thread.java:619)

"SocketAcceptor-0" prio=10 tid=0x09227000 nid=0x198e runnable
[0x8f9b1000..0x8f9b2020]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:215)
	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
	- locked <0x95a3b408> (a sun.nio.ch.Util$1)
	- locked <0x95a3b3f8> (a java.util.Collections$UnmodifiableSet)
	- locked <0x95a3b1c8> (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.apache.mina.transport.socket.nio.SocketAcceptor$Worker.run(SocketAcceptor.java:256)
	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:43)
	at java.lang.Thread.run(Thread.java:619)

"Thread-5" daemon prio=10 tid=0x9066bc00 nid=0x18ab waiting for
monitor entry [0x8fb0b000..0x8fb0c020]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:308)
	- waiting to lock <0x951435a8> (a java.io.BufferedInputStream)
	at java.io.FilterInputStream.read(FilterInputStream.java:116)
	at java.io.FilterInputStream.read(FilterInputStream.java:90)
	at org.apache.tools.ant.taskdefs.StreamPumper.run(StreamPumper.java:92)
	at java.lang.Thread.run(Thread.java:619)

"Thread-2" daemon prio=10 tid=0x904a4800 nid=0x1894 runnable
[0x8fb5c000..0x8fb5cea0]
   java.lang.Thread.State: RUNNABLE
	at java.io.FileInputStream.readBytes(Native Method)
	at java.io.FileInputStream.read(FileInputStream.java:199)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
	- locked <0x951435a8> (a java.io.BufferedInputStream)
	at java.io.FilterInputStream.read(FilterInputStream.java:116)
	at java.io.FilterInputStream.read(FilterInputStream.java:90)
	at org.apache.tools.ant.taskdefs.StreamPumper.run(StreamPumper.java:92)
	at java.lang.Thread.run(Thread.java:619)

"Low Memory Detector" daemon prio=10 tid=0x080fc000 nid=0x1873
runnable [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x080fa800 nid=0x1872 waiting on
condition [0x00000000..0x909c9268]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x080f8000 nid=0x1871 waiting on
condition [0x00000000..0x90a4a2e8]
   java.lang.Thread.State: RUNNABLE

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

"Finalizer" daemon prio=10 tid=0x080dc400 nid=0x186f in Object.wait()
[0x90aec000..0x90aecf20]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x950d9ac0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
	- locked <0x950d9ac0> (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=0x080db400 nid=0x186e in
Object.wait() [0x90b3d000..0x90b3dfa0]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x950d9ae0> (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 <0x950d9ae0> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x08058000 nid=0x186a runnable [0xb7e69000..0xb7e6b1f8]
   java.lang.Thread.State: RUNNABLE
	at java.util.IdentityHashMap.put(IdentityHashMap.java:421)
	at org.apache.mina.transport.vmpipe.support.VmPipeIdleStatusChecker.addSession(VmPipeIdleStatusChecker.java:56)
	- locked <0x95c69df8> (a java.util.IdentityHashMap)
	at org.apache.mina.transport.vmpipe.QpidVmPipeConnector.connect(QpidVmPipeConnector.java:115)
	at org.apache.mina.transport.vmpipe.QpidVmPipeConnector.connect(QpidVmPipeConnector.java:68)
	at org.apache.mina.common.support.BaseIoConnector.connect(BaseIoConnector.java:42)
	at org.apache.qpid.client.transport.VmPipeTransportConnection.connect(VmPipeTransportConnection.java:56)
	at org.apache.qpid.client.AMQConnectionDelegate_8_0.makeBrokerConnection(AMQConnectionDelegate_8_0.java:87)
	at org.apache.qpid.client.AMQConnection.makeBrokerConnection(AMQConnection.java:622)
	at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:424)
	at org.apache.qpid.client.AMQConnectionFactory.createConnection(AMQConnectionFactory.java:308)
	at org.apache.qpid.testutil.QpidTestCase.getConnection(QpidTestCase.java:437)
	at org.apache.qpid.testutil.QpidTestCase.getConnection(QpidTestCase.java:421)
	at org.apache.qpid.test.unit.client.connection.ConnectionCloseTest.testSendReceiveClose(ConnectionCloseTest.java:57)
	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 org.apache.qpid.testutil.QpidTestCase.runBare(QpidTestCase.java:157)
	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 org.apache.qpid.testutil.QpidTestCase.run(QpidTestCase.java:183)
	at junit.framework.TestSuite.runTest(TestSuite.java:208)
	at junit.framework.TestSuite.run(TestSuite.java:203)
	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:421)
	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.executeInVM(JUnitTask.java:1245)
	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.execute(JUnitTask.java:814)
	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.executeOrQueue(JUnitTask.java:1657)
	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.execute(JUnitTask.java:764)
	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:288)
	at sun.reflect.GeneratedMethodAccessor2.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:105)
	at org.apache.tools.ant.Task.perform(Task.java:348)
	at org.apache.tools.ant.Target.execute(Target.java:357)
	at org.apache.tools.ant.Target.performTasks(Target.java:385)
	at org.apache.tools.ant.Project.executeSortedTargets(Project.java:1329)
	at org.apache.tools.ant.helper.SingleCheckExecutor.executeTargets(SingleCheckExecutor.java:38)
	at org.apache.tools.ant.Project.executeTargets(Project.java:1181)
	at org.apache.tools.ant.taskdefs.Ant.execute(Ant.java:416)
	at org.apache.tools.ant.taskdefs.SubAnt.execute(SubAnt.java:289)
	at org.apache.tools.ant.taskdefs.SubAnt.execute(SubAnt.java:208)
	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:288)
	at sun.reflect.GeneratedMethodAccessor2.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:105)
	at org.apache.tools.ant.Task.perform(Task.java:348)
	at org.apache.tools.ant.taskdefs.Sequential.execute(Sequential.java:62)
	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:288)
	at sun.reflect.GeneratedMethodAccessor2.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:105)
	at org.apache.tools.ant.Task.perform(Task.java:348)
	at org.apache.tools.ant.taskdefs.MacroInstance.execute(MacroInstance.java:391)
	at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:288)
	at sun.reflect.GeneratedMethodAccessor2.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:105)
	at org.apache.tools.ant.Task.perform(Task.java:348)
	at org.apache.tools.ant.Target.execute(Target.java:357)
	at org.apache.tools.ant.Target.performTasks(Target.java:385)
	at org.apache.tools.ant.Project.executeSortedTargets(Project.java:1329)
	at org.apache.tools.ant.Project.executeTarget(Project.java:1298)
	at org.apache.tools.ant.helper.DefaultExecutor.executeTargets(DefaultExecutor.java:41)
	at org.apache.tools.ant.Project.executeTargets(Project.java:1181)
	at org.apache.tools.ant.Main.runBuild(Main.java:698)
	at org.apache.tools.ant.Main.startAnt(Main.java:199)
	at org.apache.tools.ant.launch.Launcher.run(Launcher.java:257)
	at org.apache.tools.ant.launch.Launcher.main(Launcher.java:104)

"VM Thread" prio=10 tid=0x080d8000 nid=0x186d runnable

"GC task thread#0 (ParallelGC)" prio=10 tid=0x0805ec00 nid=0x186b runnable

"GC task thread#1 (ParallelGC)" prio=10 tid=0x08060000 nid=0x186c runnable

"VM Periodic Task Thread" prio=10 tid=0x080fd800 nid=0x1874 waiting on
condition

JNI global references: 1033

Heap
 PSYoungGen      total 43712K, used 5047K [0xb1430000, 0xb4c80000, 0xb4ca0000)
  eden space 31168K, 4% used [0xb1430000,0xb15acec0,0xb32a0000)
  from space 12544K, 28% used [0xb32a0000,0xb3610f40,0xb3ee0000)
  to   space 12672K, 0% used [0xb4020000,0xb4020000,0xb4c80000)
 PSOldGen        total 68032K, used 16074K [0x950a0000, 0x99310000, 0xb1430000)


-- 
Martin Ritchie

Re: Trunk Java-09-Unit Test Hang

Posted by Rafael Schloming <ra...@redhat.com>.
Martin Ritchie wrote:
> 2008/7/16 Rafael Schloming <ra...@redhat.com>:
>> Martin Ritchie wrote:
>>> Ok, I'm can't see why this has locked my JVM up.
>>>
>>> It appears as though the main thread is having difficulting doing the
>>> put but I can't see why.
>> Isn't there a known bug against IdentityHashMap for hanging on Java 1.5?
> 
> I thought that had been fixed in 1.5.0_15. Unfortunately I don't
> recall if this was a 1.5 test run.
> 
>>> Rafi, is there anyway to stop the tests buffering the output until the
>>> test end? or is it just the way that JUnit formatters work?
>> As far as I know this is just the way the JUnit formatters work, however
>> I've never looked into it in detail. I usually just add a file appender to
>> log4j-test.xml if I run into an issue like this.
> 
> In which case we should add a FileAppender as part of our default as
> it is only in the rare race conditions do you want to know what has
> gone on up to that point. Adding the FileAppender after it has
> happened and hoping it will happen again is too late.
> 
> I shall update the log4j-test.xml to have a FileAppender writing to
> our build directory.

I've modified QpidTestCase to redirect stdout and stderr to a file 
during the test run. This allows the output to be incrementally written, 
and avoids bufferring large amounts of log output in memory during the 
test run. (This was becoming a problem on some machines with the 
recently added protocol logging.)

You should be able to get the log output for a test at the following 
location:

build/results/<module>/TEST-<package>.<Class>.<testMethod>.{out,err}

For example:

TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.testBrowsingEmptyQueue.err
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.testBrowsingEmptyQueue.out
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.testBrowsingWithSelector.err
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.testBrowsingWithSelector.out
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.testClosingBrowserMidReceiving.err
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.testClosingBrowserMidReceiving.out
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.testMultipleGetEnum.err
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.testMultipleGetEnum.out
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.testMultipleOverlappingGetEnum.err
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.testMultipleOverlappingGetEnum.out
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.testQueueBrowserMsgsRemainOnQueue.err
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.testQueueBrowserMsgsRemainOnQueue.out
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.txt
TEST-org.apache.qpid.test.client.QueueBrowserAutoAckTest.xml

I did took a look at supplying a custom result formatter to see if I 
could avoid buffering all the output, however the formatter interface 
appears to pass in all the output as one string.

I hope this helps. I think it's nicer than logging everything to one big 
file since it's easier to narrow down to the relevant log output.

--Rafael

Re: Trunk Java-09-Unit Test Hang

Posted by Martin Ritchie <ri...@apache.org>.
2008/7/16 Rafael Schloming <ra...@redhat.com>:
> Martin Ritchie wrote:
>>
>> Ok, I'm can't see why this has locked my JVM up.
>>
>> It appears as though the main thread is having difficulting doing the
>> put but I can't see why.
>
> Isn't there a known bug against IdentityHashMap for hanging on Java 1.5?

I thought that had been fixed in 1.5.0_15. Unfortunately I don't
recall if this was a 1.5 test run.

>> Rafi, is there anyway to stop the tests buffering the output until the
>> test end? or is it just the way that JUnit formatters work?
>
> As far as I know this is just the way the JUnit formatters work, however
> I've never looked into it in detail. I usually just add a file appender to
> log4j-test.xml if I run into an issue like this.

In which case we should add a FileAppender as part of our default as
it is only in the rare race conditions do you want to know what has
gone on up to that point. Adding the FileAppender after it has
happened and hoping it will happen again is too late.

I shall update the log4j-test.xml to have a FileAppender writing to
our build directory.

> --Rafael






-- 
Martin Ritchie

Re: Trunk Java-09-Unit Test Hang

Posted by Rafael Schloming <ra...@redhat.com>.
Martin Ritchie wrote:
> Ok, I'm can't see why this has locked my JVM up.
> 
> It appears as though the main thread is having difficulting doing the
> put but I can't see why.

Isn't there a known bug against IdentityHashMap for hanging on Java 1.5?

> Rafi, is there anyway to stop the tests buffering the output until the
> test end? or is it just the way that JUnit formatters work?

As far as I know this is just the way the JUnit formatters work, however 
I've never looked into it in detail. I usually just add a file appender 
to log4j-test.xml if I run into an issue like this.

--Rafael