qpid-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Rupert Smith (JIRA)" <qpid-...@incubator.apache.org>
Subject [jira] Commented: (QPID-615) ImmediateMessageTest Hang
Date Mon, 01 Oct 2007 11:32:52 GMT

    [ https://issues.apache.org/jira/browse/QPID-615?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_12531490
] 

Rupert Smith commented on QPID-615:
-----------------------------------

I have run this tests thousands of times and not been able to repoduce this error. Instead,
I sometimes get a live lock on IdentityHashMap.

It look like there might be a bug in IdentityHashMap, because the put method does not check
that the map is full before attempting a put. If the map were full, it would loop forever,
which is what appears to be happening. At the end of the put method, if the map is nearly
full, is resized, so it is not clear how this might happen. The iterator remove method, comes
under suspicion.

After doing a clean re-build on 1.6:

2007-09-28 15:44:23
Full thread dump Java HotSpot(TM) 64-Bit Server VM (1.6.0-b105 mixed mode):

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

"PooledByteBufferExpirer-0" daemon prio=10 tid=0x00002aaaf808f000 nid=0x320 waiting on condition
[0x0000000041038000..0x0000000041038b80]
   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)

"Thread-2" prio=10 tid=0x00002aaaf8004400 nid=0x31f runnable [0x0000000040f36000..0x0000000040f37b00]
   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 <0x00002aaab44a5580> (a java.util.IdentityHashMap)
        at org.apache.mina.transport.vmpipe.support.VmPipeSessionImpl.<init>(VmPipeSessionImpl.java:129)
        at org.apache.mina.transport.vmpipe.support.VmPipeSessionImpl.<init>(VmPipeSessionImpl.java:79)
        at org.apache.mina.transport.vmpipe.VmPipeConnector.connect(VmPipeConnector.java:92)
        at org.apache.mina.transport.vmpipe.VmPipeConnector.connect(VmPipeConnector.java:64)
        at org.apache.mina.common.support.BaseIoConnector.connect(BaseIoConnector.java:42)
        at org.apache.qpid.client.transport.VmPipeTransportConnection.connect(VmPipeTransportConnection.java:59)
        at org.apache.qpid.client.AMQConnection.makeBrokerConnection(AMQConnection.java:398)
        at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:292)
        at org.apache.qpid.client.AMQConnectionFactory.createConnection(AMQConnectionFactory.java:260)
        at org.apache.qpid.test.framework.TestUtils.createConnection(TestUtils.java:101)
        at org.apache.qpid.test.framework.localcircuit.LocalCircuitImpl.createCircuit(LocalCircuitImpl.java:123)
        at org.apache.qpid.test.framework.FrameworkBaseCase$DefaultCircuitFactory.createCircuit(FrameworkBaseCase.java:227)
        at org.apache.qpid.server.exchange.ImmediateMessageTest.test_QPID_517_ImmediateFailsConsumerDisconnectedNoTxPubSub(ImmediateMessageTest.java:220)
        at sun.reflect.GeneratedMethodAccessor9.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at uk.co.thebadgerset.junit.extensions.AsymptoticTestCase.runTest(AsymptoticTestCase.java:255)
        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 uk.co.thebadgerset.junit.extensions.TKTestResult.run(TKTestResult.java:389)
        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.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestDecorator.run(TestDecorator.java:28)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestDecorator.run(TestDecorator.java:28)
        at uk.co.thebadgerset.junit.extensions.AsymptoticTestDecorator.run(AsymptoticTestDecorator.java:167)
        at uk.co.thebadgerset.junit.extensions.ScaledTestDecorator$TestThreadHandler.run(ScaledTestDecorator.java:318)
        at java.lang.Thread.run(Thread.java:619)

"Low Memory Detector" daemon prio=10 tid=0x00002aaaf53bc400 nid=0x31d runnable [0x0000000000000000..0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x00002aaaf53b9c00 nid=0x31c waiting on condition [0x0000000000000000..0x0000000040c33d20]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x00002aaaf53b8000 nid=0x31b waiting on condition [0x0000000000000000..0x0000000040b32cf0]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00002aaaf1cafc00 nid=0x31a runnable [0x0000000000000000..0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x00002aaaf1c98000 nid=0x319 in Object.wait() [0x0000000040931000..0x0000000040931a00]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00002aaab44bef50> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x00002aaab44bef50> (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=0x00002aaaf1c97400 nid=0x318 in Object.wait() [0x0000000040830000..0x0000000040830b80]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00002aaab44bebd8> (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 <0x00002aaab44bebd8> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x0000000040111800 nid=0x312 in Object.wait() [0x000000004022a000..0x000000004022aec0]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00002aaab44a57d8> (a java.lang.Thread)
        at java.lang.Thread.join(Thread.java:1143)
        - locked <0x00002aaab44a57d8> (a java.lang.Thread)
        at java.lang.Thread.join(Thread.java:1196)
        at uk.co.thebadgerset.junit.extensions.ScaledTestDecorator.executeAndWaitForRunnables(ScaledTestDecorator.java:208)
        at uk.co.thebadgerset.junit.extensions.ScaledTestDecorator.run(ScaledTestDecorator.java:146)
        at junit.textui.TestRunner.doRun(TestRunner.java:116)
        at uk.co.thebadgerset.junit.extensions.TKTestRunner.doRun(TKTestRunner.java:290)
        at uk.co.thebadgerset.junit.extensions.TestRunnerImprovedErrorHandling.start(TestRunnerImprovedErrorHandling.java:123)
        at uk.co.thebadgerset.junit.extensions.TKTestRunner.start(TKTestRunner.java:499)
        at uk.co.thebadgerset.junit.extensions.TKTestRunner.main(TKTestRunner.java:254)

"VM Thread" prio=10 tid=0x00002aaaf1c92800 nid=0x317 runnable

"GC task thread#0 (ParallelGC)" prio=10 tid=0x000000004011bc00 nid=0x313 runnable

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

"GC task thread#2 (ParallelGC)" prio=10 tid=0x000000004011e400 nid=0x315 runnable

"GC task thread#3 (ParallelGC)" prio=10 tid=0x000000004011f800 nid=0x316 runnable

"VM Periodic Task Thread" prio=10 tid=0x00002aaaf53be000 nid=0x31e waiting on condition

JNI global references: 1124

Heap
 PSYoungGen      total 107968K, used 65398K [0x00002aaadd000000, 0x00002aaaec590000, 0x00002aaaf1800000)
  eden space 103360K, 58% used [0x00002aaadd000000,0x00002aaae0b6d5c8,0x00002aaae34f0000)
  from space 4608K, 98% used [0x00002aaaec110000,0x00002aaaec580300,0x00002aaaec590000)
  to   space 8256K, 0% used [0x00002aaaeb570000,0x00002aaaeb570000,0x00002aaaebd80000)
 PSOldGen        total 41984K, used 29922K [0x00002aaab4000000, 0x00002aaab6900000, 0x00002aaadd000000)
  object space 41984K, 71% used [0x00002aaab4000000,0x00002aaab5d38918,0x00002aaab6900000)
 PSPermGen       total 21248K, used 13199K [0x00002aaaaec00000, 0x00002aaab00c0000, 0x00002aaab4000000)
  object space 21248K, 62% used [0x00002aaaaec00000,0x00002aaaaf8e3ee8,0x00002aaab00c0000)

> ImmediateMessageTest Hang
> -------------------------
>
>                 Key: QPID-615
>                 URL: https://issues.apache.org/jira/browse/QPID-615
>             Project: Qpid
>          Issue Type: Bug
>    Affects Versions: M2, M2.1
>            Reporter: Martin Ritchie
>            Assignee: Rupert Smith
>             Fix For: M2, M2.1
>
>
> I've seen this test hang twice now on the M2.1 branch. This the stack trace from the
hang. It appears to be waiting for a frame which I would expect to timeout. Thing is it doesn't
timeout. 
> Running org.apache.qpid.server.exchange.ImmediateMessageTest
> Full thread dump Java HotSpot(TM) Client VM (1.5.0_08-b03 mixed mode, sharing):
> "VmPipeIdleStatusChecker" daemon prio=6 tid=0x0320afb8 nid=0xec0 waiting on condition
[0x0330f000..0x0330fb68]
>         at java.lang.Thread.sleep(Native Method)
>         at org.apache.mina.transport.vmpipe.support.VmPipeIdleStatusChecker$Worker.run(VmPipeIdleStatusChecker
> .java:74)
> "PooledByteBufferExpirer-0" daemon prio=6 tid=0x02fa62f0 nid=0x1290 waiting on condition
[0x032cf000..0x032cfb
> e8]
>         at java.lang.Thread.sleep(Native Method)
>         at org.apache.mina.common.PooledByteBufferAllocator$Expirer.run(PooledByteBufferAllocator.java:277)
> "Low Memory Detector" daemon prio=6 tid=0x00a71aa0 nid=0x14dc runnable [0x00000000..0x00000000]
> "CompilerThread0" daemon prio=10 tid=0x00a70688 nid=0xbe4 waiting on condition [0x00000000..0x02c0fa48]
> "Signal Dispatcher" daemon prio=10 tid=0x00a6f9f8 nid=0x69c waiting on condition [0x00000000..0x00000000]
> "Finalizer" daemon prio=8 tid=0x00a42908 nid=0xe44 in Object.wait() [0x02b8f000..0x02b8fa68]
>         at java.lang.Object.wait(Native Method)
>         - waiting on <0x23078668> (a java.lang.ref.ReferenceQueue$Lock)
>         at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
>         - locked <0x23078668> (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=0x0003fb30 nid=0xac0 in Object.wait() [0x02b4f000..0x02b4fae8]
>         at java.lang.Object.wait(Native Method)
>         - waiting on <0x230786e8> (a java.lang.ref.Reference$Lock)
>         at java.lang.Object.wait(Object.java:474)
>         at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
>         - locked <0x230786e8> (a java.lang.ref.Reference$Lock)
> "main" prio=6 tid=0x00036c80 nid=0x1408 in Object.wait() [0x0007e000..0x0007fc3c]
>         at java.lang.Object.wait(Native Method)
>         - waiting on <0x22ba1c20> (a java.lang.Object)
>         at org.apache.qpid.client.protocol.BlockingMethodFrameListener.blockForFrame(BlockingMethodFrameListen
> er.java:175)
>         - locked <0x22ba1c20> (a java.lang.Object)
>         at org.apache.qpid.client.protocol.AMQProtocolHandler.writeCommandFrameAndWaitForReply(AMQProtocolHand
> ler.java:570)
>         at org.apache.qpid.client.protocol.AMQProtocolHandler.syncWrite(AMQProtocolHandler.java:597)
>         at org.apache.qpid.client.AMQSession.close(AMQSession.java:545)
>         - locked <0x23d2a7d8> (a java.lang.Object)
>         - locked <0x22ca0bb0> (a java.lang.Object)
>         at org.apache.qpid.client.AMQConnection.closeAllSessions(AMQConnection.java:883)
>         at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:790)
>         - locked <0x23d2a7d8> (a java.lang.Object)
>         - locked <0x23d2f550> (a java.lang.Object)
>         at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:776)
>         - locked <0x22ca0bb0> (a java.lang.Object)
>         - locked <0x23d2f550> (a java.lang.Object)
>         at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:776)
>         - locked <0x22ca6408> (a java.lang.Object)
>         - locked <0x23d2f550> (a java.lang.Object)
>         at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:764)
>         at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:759)
>         at org.apache.qpid.test.framework.localcircuit.LocalCircuitImpl.close(LocalCircuitImpl.java:341)
>         at org.apache.qpid.test.framework.localcircuit.LocalCircuitImpl.test(LocalCircuitImpl.java:413)
>         at org.apache.qpid.server.exchange.ImmediateMessageTest.test_QPID_517_ImmediateOkTxPubSub(ImmediateMes
> sageTest.java:203)
>         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:585)
>         at uk.co.thebadgerset.junit.extensions.AsymptoticTestCase.runTest(AsymptoticTestCase.java:255)
>         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 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:585)
>         at org.apache.maven.surefire.junit.JUnitTestSet.execute(JUnitTestSet.java:210)
>         at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuit
> e.java:135)
>         at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:
> 122)
>         at org.apache.maven.surefire.Surefire.run(Surefire.java:129)
>         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:585)
>         at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:225)
>         at org.apache.maven.surefire.booter.SurefireBooter.run(SurefireBooter.java:139)
>         at org.apache.maven.plugin.surefire.SurefirePlugin.execute(SurefirePlugin.java:376)
>         at org.apache.maven.plugin.DefaultPluginManager.executeMojo(DefaultPluginManager.java:443)
>         at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoals(DefaultLifecycleExecutor.java:539)
>         at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoalWithLifecycle(DefaultLifecycleExecut
> or.java:480)
>         at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoal(DefaultLifecycleExecutor.java:459)
>         at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoalAndHandleFailures(DefaultLifecycleEx
> ecutor.java:311)
>         at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeTaskSegments(DefaultLifecycleExecutor.ja
> va:278)
>         at org.apache.maven.lifecycle.DefaultLifecycleExecutor.execute(DefaultLifecycleExecutor.java:143)
>         at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:334)
>         at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:125)
>         at org.apache.maven.cli.MavenCli.main(MavenCli.java:280)
>         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:585)
>         at org.codehaus.classworlds.Launcher.launchEnhanced(Launcher.java:315)
>         at org.codehaus.classworlds.Launcher.launch(Launcher.java:255)
>         at org.codehaus.classworlds.Launcher.mainWithExitCode(Launcher.java:430)
>         at org.codehaus.classworlds.Launcher.main(Launcher.java:375)
> "VM Thread" prio=10 tid=0x00a40a98 nid=0x1050 runnable
> "VM Periodic Task Thread" prio=10 tid=0x00a72cf0 nid=0x1698 waiting on condition

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


Mime
View raw message