Lucene - Core
  1. Lucene - Core
  2. LUCENE-2118

Intermittent failure in TestIndexWriterMergePolicy.testMaxBufferedDocsChange

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 3.1
    • Fix Version/s: 3.1, 4.0-ALPHA
    • Component/s: core/index
    • Labels:
      None
    • Lucene Fields:
      New

      Description

      Last night's build failed from it: http://hudson.zones.apache.org/hudson/job/Lucene-trunk/1019/changes

      Here's the exc:

          [junit] Testcase: testMaxBufferedDocsChange(org.apache.lucene.index.TestIndexWriterMergePolicy):	FAILED
          [junit] maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10
          [junit] junit.framework.AssertionFailedError: maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10
          [junit] 	at org.apache.lucene.index.TestIndexWriterMergePolicy.checkInvariants(TestIndexWriterMergePolicy.java:234)
          [junit] 	at org.apache.lucene.index.TestIndexWriterMergePolicy.testMaxBufferedDocsChange(TestIndexWriterMergePolicy.java:164)
          [junit] 	at org.apache.lucene.util.LuceneTestCase.runBare(LuceneTestCase.java:208)
      

      Test doesn't fail if I run on opensolaris nor os X machines...

      1. LUCENE-2118.patch
        0.6 kB
        Michael McCandless

        Activity

        Hide
        Michael McCandless added a comment -

        Robert hit this:

           [junit] Testsuite: org.apache.lucene.index.TestIndexWriterMergePolicy
           [junit] Tests run: 6, Failures: 1, Errors: 0, Time elapsed: 0.731 sec
           [junit]
           [junit] Testcase:
        testMaxBufferedDocsChange(org.apache.lucene.index.TestIndexWriterMergePolicy):
        FAILED
           [junit] maxMergeDocs=2147483647; numSegments=11; upperBound=10;
        mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32
        _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32
        _61:c10->_32 62:c8->_32 _64:c2->_62
           [junit] junit.framework.AssertionFailedError:
        maxMergeDocs=2147483647; numSegments=11; upperBound=10;
        mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32
        _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32
        _61:c10->_32 _62:c8->_32 _64:c2->_62
           [junit]     at
        org.apache.lucene.index.TestIndexWriterMergePolicy.checkInvariants(TestIndexWriterMergePolicy.java:234)
           [junit]     at
        org.apache.lucene.index.TestIndexWriterMergePolicy.testMaxBufferedDocsChange(TestIndexWriterMergePolicy.java:164)
           [junit]     at
        org.apache.lucene.util.LuceneTestCase.runBare(LuceneTestCase.java:212)
        
        Show
        Michael McCandless added a comment - Robert hit this: [junit] Testsuite: org.apache.lucene.index.TestIndexWriterMergePolicy [junit] Tests run: 6, Failures: 1, Errors: 0, Time elapsed: 0.731 sec [junit] [junit] Testcase: testMaxBufferedDocsChange(org.apache.lucene.index.TestIndexWriterMergePolicy): FAILED [junit] maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32 _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32 _61:c10->_32 62:c8->_32 _64:c2->_62 [junit] junit.framework.AssertionFailedError: maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32 _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32 _61:c10->_32 _62:c8->_32 _64:c2->_62 [junit] at org.apache.lucene.index.TestIndexWriterMergePolicy.checkInvariants(TestIndexWriterMergePolicy.java:234) [junit] at org.apache.lucene.index.TestIndexWriterMergePolicy.testMaxBufferedDocsChange(TestIndexWriterMergePolicy.java:164) [junit] at org.apache.lucene.util.LuceneTestCase.runBare(LuceneTestCase.java:212)
        Hide
        Michael McCandless added a comment -

        I found the root cause here; it's a rare case, due to shared doc stores. Whenever the merge must merge doc stores and at least 1 segment is referencing the currently open shared doc stores, IW must flush. It's an "unusual" flush because it's triggered by the right merge and not maxBuffereDocs/RAM being consumed.

        When this happens we fail to check for newly required merges, which can then leave the index in a state where it needs a merge, causing this failure.

        I can't repro this failure, but I think very likely this is the cause. The fix is to call updatePendingMerges in the two places where we do these "unusual" flushes. I'll commit shortly.

        Show
        Michael McCandless added a comment - I found the root cause here; it's a rare case, due to shared doc stores. Whenever the merge must merge doc stores and at least 1 segment is referencing the currently open shared doc stores, IW must flush. It's an "unusual" flush because it's triggered by the right merge and not maxBuffereDocs/RAM being consumed. When this happens we fail to check for newly required merges, which can then leave the index in a state where it needs a merge, causing this failure. I can't repro this failure, but I think very likely this is the cause. The fix is to call updatePendingMerges in the two places where we do these "unusual" flushes. I'll commit shortly.
        Hide
        Michael McCandless added a comment -

        Alas this issue still happens. I just hit this on trunk:

            [junit] Testsuite: org.apache.lucene.index.TestIndexWriterMergePolicy
            [junit] Testcase: testMaxBufferedDocsChange(org.apache.lucene.index.TestIndexWriterMergePolicy):	FAILED
            [junit] maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32 _5w:c10->_32
              _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32 _61:c10->_32 _62:c1->_32 _63:c9->_62
            [junit] junit.framework.AssertionFailedError: maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10; segs=_65:c5950 _5t:c10->_32
              _5u:c10->_32 _5v:c10->_32 _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32 _61:c10->_32 _62:c1->_32 _63:c9->_62
            [junit] 	at org.apache.lucene.index.TestIndexWriterMergePolicy.checkInvariants(TestIndexWriterMergePolicy.java:251)
            [junit] 	at org.apache.lucene.index.TestIndexWriterMergePolicy.testMaxBufferedDocsChange(TestIndexWriterMergePolicy.java:177)
            [junit] 	at org.apache.lucene.util.LuceneTestCase.runBare(LuceneTestCase.java:385)
            [junit] 	at org.apache.lucene.util.LuceneTestCase.run(LuceneTestCase.java:377)
        
        Show
        Michael McCandless added a comment - Alas this issue still happens. I just hit this on trunk: [junit] Testsuite: org.apache.lucene.index.TestIndexWriterMergePolicy [junit] Testcase: testMaxBufferedDocsChange(org.apache.lucene.index.TestIndexWriterMergePolicy): FAILED [junit] maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32 _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32 _61:c10->_32 _62:c1->_32 _63:c9->_62 [junit] junit.framework.AssertionFailedError: maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32 _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32 _61:c10->_32 _62:c1->_32 _63:c9->_62 [junit] at org.apache.lucene.index.TestIndexWriterMergePolicy.checkInvariants(TestIndexWriterMergePolicy.java:251) [junit] at org.apache.lucene.index.TestIndexWriterMergePolicy.testMaxBufferedDocsChange(TestIndexWriterMergePolicy.java:177) [junit] at org.apache.lucene.util.LuceneTestCase.runBare(LuceneTestCase.java:385) [junit] at org.apache.lucene.util.LuceneTestCase.run(LuceneTestCase.java:377)
        Hide
        Michael McCandless added a comment -

        Steven A Rowe just hit this again, on trunk:

        NOTE: random codec of testcase 'testMaxBufferedDocsChange' was: MockSep
        NOTE: random locale of testcase 'testMaxBufferedDocsChange' was: en_PH
        NOTE: random timezone of testcase 'testMaxBufferedDocsChange' was: America/Indianapolis
        NOTE: random seed of testcase 'testMaxBufferedDocsChange' was: 4118460220441676374
        
        junit.framework.AssertionFailedError: maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32 _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32 _61:c10->_32 _62:c1->_32 _63:c9->_62
               at org.apache.lucene.index.TestIndexWriterMergePolicy.checkInvariants(TestIndexWriterMergePolicy.java:251)
               at org.apache.lucene.index.TestIndexWriterMergePolicy.testMaxBufferedDocsChange(TestIndexWriterMergePolicy.java:177)
               at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
               at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
               at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
               at org.apache.lucene.util.LuceneTestCase.runBare(LuceneTestCase.java:395)
               at org.apache.lucene.util.LuceneTestCase.run(LuceneTestCase.java:387)
               at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:83)
               at org.junit.runners.Suite.runChild(Suite.java:128)
               at org.junit.runners.Suite.runChild(Suite.java:24)
               at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
               at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
               at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
               at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
               at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
               at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
               at org.junit.runner.JUnitCore.run(JUnitCore.java:157)
               at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:94)
               at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:192)
               at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:64)
               at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
               at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
               at com.intellij.rt.execution.application.AppMain.main(AppMain.java:115)
        
        Show
        Michael McCandless added a comment - Steven A Rowe just hit this again, on trunk: NOTE: random codec of testcase 'testMaxBufferedDocsChange' was: MockSep NOTE: random locale of testcase 'testMaxBufferedDocsChange' was: en_PH NOTE: random timezone of testcase 'testMaxBufferedDocsChange' was: America/Indianapolis NOTE: random seed of testcase 'testMaxBufferedDocsChange' was: 4118460220441676374 junit.framework.AssertionFailedError: maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32 _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32 _61:c10->_32 _62:c1->_32 _63:c9->_62 at org.apache.lucene.index.TestIndexWriterMergePolicy.checkInvariants(TestIndexWriterMergePolicy.java:251) at org.apache.lucene.index.TestIndexWriterMergePolicy.testMaxBufferedDocsChange(TestIndexWriterMergePolicy.java:177) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at org.apache.lucene.util.LuceneTestCase.runBare(LuceneTestCase.java:395) at org.apache.lucene.util.LuceneTestCase.run(LuceneTestCase.java:387) at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:83) at org.junit.runners.Suite.runChild(Suite.java:128) at org.junit.runners.Suite.runChild(Suite.java:24) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184) at org.junit.runners.ParentRunner.run(ParentRunner.java:236) at org.junit.runner.JUnitCore.run(JUnitCore.java:157) at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:94) at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:192) at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:64) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at com.intellij.rt.execution.application.AppMain.main(AppMain.java:115)
        Hide
        Robert Muir added a comment -

        Hudson hit this last night (brancH_3x)

            [junit] Testsuite: org.apache.lucene.index.TestIndexWriterMergePolicy
            [junit] Testcase: testMaxBufferedDocsChange(org.apache.lucene.index.TestIndexWriterMergePolicy):	FAILED
            [junit] maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32 _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32 _61:c10->_32 _62:c5->_32 _63:c5->_62
            [junit] junit.framework.AssertionFailedError: maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32 _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32 _61:c10->_32 _62:c5->_32 _63:c5->_62
            [junit] 	at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:770)
            [junit] 	at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:737)
            [junit] 	at org.apache.lucene.index.TestIndexWriterMergePolicy.checkInvariants(TestIndexWriterMergePolicy.java:243)
            [junit] 	at org.apache.lucene.index.TestIndexWriterMergePolicy.testMaxBufferedDocsChange(TestIndexWriterMergePolicy.java:169)
            [junit] 
            [junit] 
            [junit] Tests run: 6, Failures: 1, Errors: 0, Time elapsed: 2.31 sec
            [junit] 
            [junit] ------------- Standard Output ---------------
            [junit] NOTE: reproduce with: ant test -Dtestcase=TestIndexWriterMergePolicy -Dtestmethod=testMaxBufferedDocsChange -Dtests.seed=5199282654207860248:-4379090235199517829 -Dtests.multiplier=3
            [junit] NOTE: test params are: locale=is_IS, timezone=Africa/Porto-Novo
            [junit] ------------- ---------------- ---------------
            [junit] TEST org.apache.lucene.index.TestIndexWriterMergePolicy FAILED
        
        Show
        Robert Muir added a comment - Hudson hit this last night (brancH_3x) [junit] Testsuite: org.apache.lucene.index.TestIndexWriterMergePolicy [junit] Testcase: testMaxBufferedDocsChange(org.apache.lucene.index.TestIndexWriterMergePolicy): FAILED [junit] maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32 _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32 _61:c10->_32 _62:c5->_32 _63:c5->_62 [junit] junit.framework.AssertionFailedError: maxMergeDocs=2147483647; numSegments=11; upperBound=10; mergeFactor=10; segs=_65:c5950 _5t:c10->_32 _5u:c10->_32 _5v:c10->_32 _5w:c10->_32 _5x:c10->_32 _5y:c10->_32 _5z:c10->_32 _60:c10->_32 _61:c10->_32 _62:c5->_32 _63:c5->_62 [junit] at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:770) [junit] at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:737) [junit] at org.apache.lucene.index.TestIndexWriterMergePolicy.checkInvariants(TestIndexWriterMergePolicy.java:243) [junit] at org.apache.lucene.index.TestIndexWriterMergePolicy.testMaxBufferedDocsChange(TestIndexWriterMergePolicy.java:169) [junit] [junit] [junit] Tests run: 6, Failures: 1, Errors: 0, Time elapsed: 2.31 sec [junit] [junit] ------------- Standard Output --------------- [junit] NOTE: reproduce with: ant test -Dtestcase=TestIndexWriterMergePolicy -Dtestmethod=testMaxBufferedDocsChange -Dtests.seed=5199282654207860248:-4379090235199517829 -Dtests.multiplier=3 [junit] NOTE: test params are: locale=is_IS, timezone=Africa/Porto-Novo [junit] ------------- ---------------- --------------- [junit] TEST org.apache.lucene.index.TestIndexWriterMergePolicy FAILED
        Hide
        Michael McCandless added a comment -

        OK I think (again!) I found the root cause here – patch attached.

        Basically the test and LogMergePolicy disagreed on the boundary case of when a segment falls into the minimum level. Just have to change < to <=.

        Show
        Michael McCandless added a comment - OK I think (again!) I found the root cause here – patch attached. Basically the test and LogMergePolicy disagreed on the boundary case of when a segment falls into the minimum level. Just have to change < to <=.
        Hide
        Michael McCandless added a comment -

        Urgh – my commit breaks this test case:

        ant test-core -Dtestcase=TestIndexWriter -Dtestmethod=testOptimizeMaxNumSegments2 -Dtests.seed=6113348674281247226:-4858946393178103452
        
        Show
        Michael McCandless added a comment - Urgh – my commit breaks this test case: ant test-core -Dtestcase=TestIndexWriter -Dtestmethod=testOptimizeMaxNumSegments2 -Dtests.seed=6113348674281247226:-4858946393178103452
        Hide
        Jason Rutherglen added a comment -

        Ah, I saw this error from "testMaxBufferedDocsChange" in testing LUCENE-2680. Maybe it's not the changes I made in that particular case!

        Show
        Jason Rutherglen added a comment - Ah, I saw this error from "testMaxBufferedDocsChange" in testing LUCENE-2680 . Maybe it's not the changes I made in that particular case!
        Hide
        Michael McCandless added a comment -

        Slowly, nervously, I again mark this one fixed...

        Show
        Michael McCandless added a comment - Slowly, nervously, I again mark this one fixed...
        Hide
        Grant Ingersoll added a comment -

        Bulk close for 3.1

        Show
        Grant Ingersoll added a comment - Bulk close for 3.1

          People

          • Assignee:
            Unassigned
            Reporter:
            Michael McCandless
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development