Lucene - Core
  1. Lucene - Core
  2. LUCENE-3428

trunk tests hang/deadlock TestIndexWriterWithThreads

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 4.0-ALPHA
    • Component/s: None
    • Labels:
      None
    • Lucene Fields:
      New, Patch Available

      Description

      trunk tests have been hanging often lately in hudson, this time i was careful to kill and get a good stacktrace:

      1. LUCENE-3428.patch
        2 kB
        Simon Willnauer

        Activity

        Uwe Schindler made changes -
        Status Resolved [ 5 ] Closed [ 6 ]
        Simon Willnauer made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Lucene Fields New [ 10121 ] New,Patch Available [ 10121,10120 ]
        Fix Version/s 4.0 [ 12314025 ]
        Resolution Fixed [ 1 ]
        Hide
        Simon Willnauer added a comment -

        fixed

        Show
        Simon Willnauer added a comment - fixed
        Hide
        Simon Willnauer added a comment -

        I committed the patch. I will keep this open for a while...

        Show
        Simon Willnauer added a comment - I committed the patch. I will keep this open for a while...
        Simon Willnauer made changes -
        Attachment LUCENE-3428.patch [ 12493963 ]
        Hide
        Simon Willnauer added a comment -

        I think I found the reason or one possible reason for this. there is one place where we don't release a DWPT lock in the case of a failure. Here is a patch.

        Show
        Simon Willnauer added a comment - I think I found the reason or one possible reason for this. there is one place where we don't release a DWPT lock in the case of a failure. Here is a patch.
        Simon Willnauer made changes -
        Field Original Value New Value
        Assignee Simon Willnauer [ simonw ]
        Hide
        Robert Muir added a comment -

        https://builds.apache.org/view/G-L/view/Lucene/job/Lucene-Solr-tests-only-trunk/10500

            [junit] 2011-09-11 16:32:39
            [junit] Full thread dump OpenJDK 64-Bit Server VM (20.0-b11 mixed mode):
            [junit] 
            [junit] "Low Memory Detector" daemon prio=5 tid=0x0000000801eee800 nid=0x19642 runnable [0x0000000000000000]
            [junit]    java.lang.Thread.State: RUNNABLE
            [junit] 
            [junit] "C2 CompilerThread1" daemon prio=5 tid=0x0000000801eef000 nid=0x19640 waiting on condition [0x0000000000000000]
            [junit]    java.lang.Thread.State: RUNNABLE
            [junit] 
            [junit] "C2 CompilerThread0" daemon prio=5 tid=0x0000000801ef0000 nid=0x1963d waiting on condition [0x0000000000000000]
            [junit]    java.lang.Thread.State: RUNNABLE
            [junit] 
            [junit] "Signal Dispatcher" daemon prio=5 tid=0x0000000801ef0800 nid=0x19630 waiting on condition [0x0000000000000000]
            [junit]    java.lang.Thread.State: RUNNABLE
            [junit] 
            [junit] "Finalizer" daemon prio=5 tid=0x0000000801ef1800 nid=0x19581 in Object.wait() [0x00007ffffebee000]
            [junit]    java.lang.Thread.State: WAITING (on object monitor)
            [junit] 	at java.lang.Object.wait(Native Method)
            [junit] 	- waiting on <0x0000000828cb0370> (a java.lang.ref.ReferenceQueue$Lock)
            [junit] 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:133)
            [junit] 	- locked <0x0000000828cb0370> (a java.lang.ref.ReferenceQueue$Lock)
            [junit] 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:149)
            [junit] 	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)
            [junit] 
            [junit] "Reference Handler" daemon prio=5 tid=0x0000000801ef3000 nid=0x1957f in Object.wait() [0x00007ffffecef000]
            [junit]    java.lang.Thread.State: WAITING (on object monitor)
            [junit] 	at java.lang.Object.wait(Native Method)
            [junit] 	- waiting on <0x0000000828cb0410> (a java.lang.ref.Reference$Lock)
            [junit] 	at java.lang.Object.wait(Object.java:502)
            [junit] 	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
            [junit] 	- locked <0x0000000828cb0410> (a java.lang.ref.Reference$Lock)
            [junit] 
            [junit] "main" prio=5 tid=0x0000000801ef3800 nid=0x19432 waiting on condition [0x00007fffffbfd000]
            [junit]    java.lang.Thread.State: WAITING (parking)
            [junit] 	at sun.misc.Unsafe.park(Native Method)
            [junit] 	- parking to wait for  <0x0000000827a440c0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
            [junit] 	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
            [junit] 	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:838)
            [junit] 	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:871)
            [junit] 	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1201)
            [junit] 	at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:214)
            [junit] 	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290)
            [junit] 	at org.apache.lucene.index.DocumentsWriterFlushControl.assertActiveDeleteQueue(DocumentsWriterFlushControl.java:435)
            [junit] 	at org.apache.lucene.index.DocumentsWriterFlushControl.markForFullFlush(DocumentsWriterFlushControl.java:428)
            [junit] 	at org.apache.lucene.index.DocumentsWriter.flushAllThreads(DocumentsWriter.java:557)
            [junit] 	- locked <0x0000000827a417c0> (a org.apache.lucene.index.DocumentsWriter)
            [junit] 	at org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:2973)
            [junit] 	- locked <0x0000000827a3d738> (a java.lang.Object)
            [junit] 	at org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:2950)
            [junit] 	at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1133)
            [junit] 	at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1097)
            [junit] 	at org.apache.lucene.index.TestIndexWriterWithThreads.testCloseWithThreads(TestIndexWriterWithThreads.java:200)
            [junit] 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
            [junit] 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
            [junit] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
            [junit] 	at java.lang.reflect.Method.invoke(Method.java:616)
            [junit] 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
            [junit] 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
            [junit] 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
            [junit] 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
            [junit] 	at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
            [junit] 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
            [junit] 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
            [junit] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:148)
            [junit] 	at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:50)
            [junit] 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
            [junit] 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
            [junit] 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
            [junit] 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
            [junit] 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
            [junit] 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
            [junit] 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
            [junit] 	at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
            [junit] 	at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
            [junit] 	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:420)
            [junit] 	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:911)
            [junit] 	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:743)
            [junit] 
            [junit] "VM Thread" prio=5 tid=0x0000000801f29000 nid=0x19516 runnable 
            [junit] 
            [junit] "GC task thread#0 (ParallelGC)" prio=5 tid=0x0000000801f32000 nid=0x1944f runnable 
            [junit] 
            [junit] "GC task thread#1 (ParallelGC)" prio=5 tid=0x0000000801f31000 nid=0x19451 runnable 
            [junit] 
            [junit] "GC task thread#2 (ParallelGC)" prio=5 tid=0x0000000801f30800 nid=0x19458 runnable 
            [junit] 
            [junit] "GC task thread#3 (ParallelGC)" prio=5 tid=0x0000000801f30000 nid=0x1945b runnable 
            [junit] 
            [junit] "GC task thread#4 (ParallelGC)" prio=5 tid=0x0000000801f2f800 nid=0x19463 runnable 
            [junit] 
            [junit] "GC task thread#5 (ParallelGC)" prio=5 tid=0x0000000801f2e800 nid=0x19468 runnable 
            [junit] 
            [junit] "GC task thread#6 (ParallelGC)" prio=5 tid=0x0000000801f2e000 nid=0x1946c runnable 
            [junit] 
            [junit] "GC task thread#7 (ParallelGC)" prio=5 tid=0x0000000801f2d800 nid=0x1947a runnable 
            [junit] 
            [junit] "GC task thread#8 (ParallelGC)" prio=5 tid=0x0000000801f2c800 nid=0x19495 runnable 
            [junit] 
            [junit] "GC task thread#9 (ParallelGC)" prio=5 tid=0x0000000801f2c000 nid=0x19496 runnable 
            [junit] 
            [junit] "GC task thread#10 (ParallelGC)" prio=5 tid=0x0000000801f2b800 nid=0x194a8 runnable 
            [junit] 
            [junit] "GC task thread#11 (ParallelGC)" prio=5 tid=0x0000000801f2b000 nid=0x194ba runnable 
            [junit] 
            [junit] "GC task thread#12 (ParallelGC)" prio=5 tid=0x0000000801f2a000 nid=0x194be runnable 
            [junit] 
            [junit] "VM Periodic Task Thread" prio=5 tid=0x0000000801f28800 nid=0x19646 waiting on condition 
            [junit] 
            [junit] JNI global references: 945
            [junit] 
            [junit] Heap
            [junit]  PSYoungGen      total 156800K, used 136506K [0x000000081f9b0000, 0x0000000829d10000, 0x000000082a450000)
            [junit]   eden space 150528K, 89% used [0x000000081f9b0000,0x0000000827d24378,0x0000000828cb0000)
            [junit]   from space 6272K, 30% used [0x0000000828cb0000,0x0000000828e8a6e8,0x00000008292d0000)
            [junit]   to   space 2560K, 0% used [0x0000000829a90000,0x0000000829a90000,0x0000000829d10000)
            [junit]  PSOldGen        total 100480K, used 0K [0x000000080a450000, 0x0000000810670000, 0x000000081f9b0000)
            [junit]   object space 100480K, 0% used [0x000000080a450000,0x000000080a450000,0x0000000810670000)
            [junit]  PSPermGen       total 21248K, used 13150K [0x0000000805250000, 0x0000000806710000, 0x000000080a450000)
            [junit]   object space 21248K, 61% used [0x0000000805250000,0x0000000805f27880,0x0000000806710000)
            [junit] 
        
        Show
        Robert Muir added a comment - https://builds.apache.org/view/G-L/view/Lucene/job/Lucene-Solr-tests-only-trunk/10500 [junit] 2011-09-11 16:32:39 [junit] Full thread dump OpenJDK 64-Bit Server VM (20.0-b11 mixed mode): [junit] [junit] "Low Memory Detector" daemon prio=5 tid=0x0000000801eee800 nid=0x19642 runnable [0x0000000000000000] [junit] java.lang.Thread.State: RUNNABLE [junit] [junit] "C2 CompilerThread1" daemon prio=5 tid=0x0000000801eef000 nid=0x19640 waiting on condition [0x0000000000000000] [junit] java.lang.Thread.State: RUNNABLE [junit] [junit] "C2 CompilerThread0" daemon prio=5 tid=0x0000000801ef0000 nid=0x1963d waiting on condition [0x0000000000000000] [junit] java.lang.Thread.State: RUNNABLE [junit] [junit] "Signal Dispatcher" daemon prio=5 tid=0x0000000801ef0800 nid=0x19630 waiting on condition [0x0000000000000000] [junit] java.lang.Thread.State: RUNNABLE [junit] [junit] "Finalizer" daemon prio=5 tid=0x0000000801ef1800 nid=0x19581 in Object.wait() [0x00007ffffebee000] [junit] java.lang.Thread.State: WAITING (on object monitor) [junit] at java.lang.Object.wait(Native Method) [junit] - waiting on <0x0000000828cb0370> (a java.lang.ref.ReferenceQueue$Lock) [junit] at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:133) [junit] - locked <0x0000000828cb0370> (a java.lang.ref.ReferenceQueue$Lock) [junit] at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:149) [junit] at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177) [junit] [junit] "Reference Handler" daemon prio=5 tid=0x0000000801ef3000 nid=0x1957f in Object.wait() [0x00007ffffecef000] [junit] java.lang.Thread.State: WAITING (on object monitor) [junit] at java.lang.Object.wait(Native Method) [junit] - waiting on <0x0000000828cb0410> (a java.lang.ref.Reference$Lock) [junit] at java.lang.Object.wait(Object.java:502) [junit] at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133) [junit] - locked <0x0000000828cb0410> (a java.lang.ref.Reference$Lock) [junit] [junit] "main" prio=5 tid=0x0000000801ef3800 nid=0x19432 waiting on condition [0x00007fffffbfd000] [junit] java.lang.Thread.State: WAITING (parking) [junit] at sun.misc.Unsafe.park(Native Method) [junit] - parking to wait for <0x0000000827a440c0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) [junit] at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186) [junit] at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:838) [junit] at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:871) [junit] at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1201) [junit] at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:214) [junit] at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290) [junit] at org.apache.lucene.index.DocumentsWriterFlushControl.assertActiveDeleteQueue(DocumentsWriterFlushControl.java:435) [junit] at org.apache.lucene.index.DocumentsWriterFlushControl.markForFullFlush(DocumentsWriterFlushControl.java:428) [junit] at org.apache.lucene.index.DocumentsWriter.flushAllThreads(DocumentsWriter.java:557) [junit] - locked <0x0000000827a417c0> (a org.apache.lucene.index.DocumentsWriter) [junit] at org.apache.lucene.index.IndexWriter.doFlush(IndexWriter.java:2973) [junit] - locked <0x0000000827a3d738> (a java.lang.Object) [junit] at org.apache.lucene.index.IndexWriter.flush(IndexWriter.java:2950) [junit] at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:1133) [junit] at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1097) [junit] at org.apache.lucene.index.TestIndexWriterWithThreads.testCloseWithThreads(TestIndexWriterWithThreads.java:200) [junit] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [junit] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [junit] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [junit] at java.lang.reflect.Method.invoke(Method.java:616) [junit] at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44) [junit] at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15) [junit] at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41) [junit] at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20) [junit] at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48) [junit] at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28) [junit] at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31) [junit] at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:148) [junit] at org.apache.lucene.util.LuceneTestCaseRunner.runChild(LuceneTestCaseRunner.java:50) [junit] at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193) [junit] at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52) [junit] at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191) [junit] at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42) [junit] at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184) [junit] at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28) [junit] at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31) [junit] at org.junit.runners.ParentRunner.run(ParentRunner.java:236) [junit] at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39) [junit] at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:420) [junit] at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:911) [junit] at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:743) [junit] [junit] "VM Thread" prio=5 tid=0x0000000801f29000 nid=0x19516 runnable [junit] [junit] "GC task thread#0 (ParallelGC)" prio=5 tid=0x0000000801f32000 nid=0x1944f runnable [junit] [junit] "GC task thread#1 (ParallelGC)" prio=5 tid=0x0000000801f31000 nid=0x19451 runnable [junit] [junit] "GC task thread#2 (ParallelGC)" prio=5 tid=0x0000000801f30800 nid=0x19458 runnable [junit] [junit] "GC task thread#3 (ParallelGC)" prio=5 tid=0x0000000801f30000 nid=0x1945b runnable [junit] [junit] "GC task thread#4 (ParallelGC)" prio=5 tid=0x0000000801f2f800 nid=0x19463 runnable [junit] [junit] "GC task thread#5 (ParallelGC)" prio=5 tid=0x0000000801f2e800 nid=0x19468 runnable [junit] [junit] "GC task thread#6 (ParallelGC)" prio=5 tid=0x0000000801f2e000 nid=0x1946c runnable [junit] [junit] "GC task thread#7 (ParallelGC)" prio=5 tid=0x0000000801f2d800 nid=0x1947a runnable [junit] [junit] "GC task thread#8 (ParallelGC)" prio=5 tid=0x0000000801f2c800 nid=0x19495 runnable [junit] [junit] "GC task thread#9 (ParallelGC)" prio=5 tid=0x0000000801f2c000 nid=0x19496 runnable [junit] [junit] "GC task thread#10 (ParallelGC)" prio=5 tid=0x0000000801f2b800 nid=0x194a8 runnable [junit] [junit] "GC task thread#11 (ParallelGC)" prio=5 tid=0x0000000801f2b000 nid=0x194ba runnable [junit] [junit] "GC task thread#12 (ParallelGC)" prio=5 tid=0x0000000801f2a000 nid=0x194be runnable [junit] [junit] "VM Periodic Task Thread" prio=5 tid=0x0000000801f28800 nid=0x19646 waiting on condition [junit] [junit] JNI global references: 945 [junit] [junit] Heap [junit] PSYoungGen total 156800K, used 136506K [0x000000081f9b0000, 0x0000000829d10000, 0x000000082a450000) [junit] eden space 150528K, 89% used [0x000000081f9b0000,0x0000000827d24378,0x0000000828cb0000) [junit] from space 6272K, 30% used [0x0000000828cb0000,0x0000000828e8a6e8,0x00000008292d0000) [junit] to space 2560K, 0% used [0x0000000829a90000,0x0000000829a90000,0x0000000829d10000) [junit] PSOldGen total 100480K, used 0K [0x000000080a450000, 0x0000000810670000, 0x000000081f9b0000) [junit] object space 100480K, 0% used [0x000000080a450000,0x000000080a450000,0x0000000810670000) [junit] PSPermGen total 21248K, used 13150K [0x0000000805250000, 0x0000000806710000, 0x000000080a450000) [junit] object space 21248K, 61% used [0x0000000805250000,0x0000000805f27880,0x0000000806710000) [junit]
        Robert Muir created issue -

          People

          • Assignee:
            Simon Willnauer
            Reporter:
            Robert Muir
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development