[HUDSON] Lucene-Solr-tests-only-trunk - Build # 5709 - Failure

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

[HUDSON] Lucene-Solr-tests-only-trunk - Build # 5709 - Failure

Apache Jenkins Server
Build: https://hudson.apache.org/hudson/job/Lucene-Solr-tests-only-trunk/5709/

1 tests failed.
REGRESSION:  org.apache.lucene.index.TestIndexWriter.testIndexingThenDeleting

Error Message:
flush happened too quickly during deleting count=1155

Stack Trace:
junit.framework.AssertionFailedError: flush happened too quickly during deleting count=1155
        at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1213)
        at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1145)
        at org.apache.lucene.index.TestIndexWriter.testIndexingThenDeleting(TestIndexWriter.java:2579)




Build Log (for compile errors):
[...truncated 3082 lines...]



---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [HUDSON] Lucene-Solr-tests-only-trunk - Build # 5709 - Failure

Michael McCandless-2
This seed doesn't repro the failure for me:

    ant test -Dtestcase=TestIndexWriter
-Dtestmethod=testIndexingThenDeleting
-Dtests.seed=2772841086465723649:-8475474922759781208
-Dtests.multiplier=3

Can anyone repro in their env?

Mike

On Mon, Mar 7, 2011 at 8:33 PM, Apache Hudson Server
<[hidden email]> wrote:

> Build: https://hudson.apache.org/hudson/job/Lucene-Solr-tests-only-trunk/5709/
>
> 1 tests failed.
> REGRESSION:  org.apache.lucene.index.TestIndexWriter.testIndexingThenDeleting
>
> Error Message:
> flush happened too quickly during deleting count=1155
>
> Stack Trace:
> junit.framework.AssertionFailedError: flush happened too quickly during deleting count=1155
>        at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1213)
>        at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1145)
>        at org.apache.lucene.index.TestIndexWriter.testIndexingThenDeleting(TestIndexWriter.java:2579)
>
>
>
>
> Build Log (for compile errors):
> [...truncated 3082 lines...]
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>



--
Mike

http://blog.mikemccandless.com

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

RE: [HUDSON] Lucene-Solr-tests-only-trunk - Build # 5709 - Failure

steve_rowe
Mike,

I can repro, but not consistently.  In a while[1] script, after 12 iterations (I compiled with Java 5, then ran tests with Java 6, as on Jenkins):

junit-sequential:
    [junit] RESOURCE LEAK: test method: 'testIndexingThenDeleting' left 1 thread(s) running
    [junit] NOTE: test params are: codec=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}, locale=th, timezone=US/East-Indiana
    [junit] NOTE: all tests run in this JVM:
    [junit] [TestIndexWriter]
    [junit] NOTE: Windows 7 6.1 amd64/Sun Microsystems Inc. 1.6.0_23 (64-bit)/cpus=8,threads=1,free=98650696,total=124321792
    [junit] ------------- ---------------- ---------------
    [junit] Testcase: testIndexingThenDeleting(org.apache.lucene.index.TestIndexWriter):        FAILED
    [junit] flush happened too quickly during deleting count=1155
    [junit] junit.framework.AssertionFailedError: flush happened too quickly during deleting count=1155
    [junit]     at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1213)
    [junit]     at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1145)
    [junit]     at org.apache.lucene.index.TestIndexWriter.testIndexingThenDeleting(TestIndexWriter.java:2579)

> -----Original Message-----
> From: Michael McCandless [mailto:[hidden email]]
> Sent: Tuesday, March 08, 2011 4:46 AM
> To: [hidden email]
> Cc: Apache Hudson Server
> Subject: Re: [HUDSON] Lucene-Solr-tests-only-trunk - Build # 5709 -
> Failure
>
> This seed doesn't repro the failure for me:
>
>     ant test -Dtestcase=TestIndexWriter
> -Dtestmethod=testIndexingThenDeleting
> -Dtests.seed=2772841086465723649:-8475474922759781208
> -Dtests.multiplier=3
>
> Can anyone repro in their env?
>
> Mike
>
> On Mon, Mar 7, 2011 at 8:33 PM, Apache Hudson Server
> <[hidden email]> wrote:
> > Build: https://hudson.apache.org/hudson/job/Lucene-Solr-tests-only-
> trunk/5709/
> >
> > 1 tests failed.
> >
> REGRESSION:  org.apache.lucene.index.TestIndexWriter.testIndexingThenDelet
> ing
> >
> > Error Message:
> > flush happened too quickly during deleting count=1155
> >
> > Stack Trace:
> > junit.framework.AssertionFailedError: flush happened too quickly during
> deleting count=1155
> >        at
> org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(Lucene
> TestCase.java:1213)
> >        at
> org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(Lucene
> TestCase.java:1145)
> >        at
> org.apache.lucene.index.TestIndexWriter.testIndexingThenDeleting(TestIndex
> Writer.java:2579)
> >
> >
> >
> >
> > Build Log (for compile errors):
> > [...truncated 3082 lines...]
> >
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: [hidden email]
> > For additional commands, e-mail: [hidden email]
> >
> >
>
>
>
> --
> Mike
>
> http://blog.mikemccandless.com
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [HUDSON] Lucene-Solr-tests-only-trunk - Build # 5709 - Failure

Michael McCandless-2
On Tue, Mar 8, 2011 at 9:05 AM, Steven A Rowe <[hidden email]> wrote:

> Mike,
>
> I can repro, but not consistently.  In a while[1] script, after 12 iterations (I compiled with Java 5, then ran tests with Java 6, as on Jenkins):
>
> junit-sequential:
>    [junit] RESOURCE LEAK: test method: 'testIndexingThenDeleting' left 1 thread(s) running
>    [junit] NOTE: test params are: codec=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}, locale=th, timezone=US/East-Indiana
>    [junit] NOTE: all tests run in this JVM:
>    [junit] [TestIndexWriter]
>    [junit] NOTE: Windows 7 6.1 amd64/Sun Microsystems Inc. 1.6.0_23 (64-bit)/cpus=8,threads=1,free=98650696,total=124321792
>    [junit] ------------- ---------------- ---------------
>    [junit] Testcase: testIndexingThenDeleting(org.apache.lucene.index.TestIndexWriter):        FAILED
>    [junit] flush happened too quickly during deleting count=1155
>    [junit] junit.framework.AssertionFailedError: flush happened too quickly during deleting count=1155
>    [junit]     at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1213)
>    [junit]     at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1145)
>    [junit]     at org.apache.lucene.index.TestIndexWriter.testIndexingThenDeleting(TestIndexWriter.java:2579)

Thanks Steven.

Curious... I can't get it to fail under while 1 on my (Linux) box.

Can you run w/ -Dtests.verbose=true and post the output when it fails?  Thanks

--
Mike

http://blog.mikemccandless.com

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [HUDSON] Lucene-Solr-tests-only-trunk - Build # 5709 - Failure

Yonik Seeley-2-2
In reply to this post by Michael McCandless-2
Failed on my mac on the second try:


    [junit] Testsuite: org.apache.lucene.index.TestIndexWriter
    [junit] Tests run: 1, Failures: 1, Errors: 0, Time elapsed: 12.039 sec
    [junit]
    [junit] ------------- Standard Error -----------------
    [junit] NOTE: reproduce with: ant test -Dtestcase=TestIndexWriter
-Dtestmethod=testIndexingThenDeleting
-Dtests.seed=2772841086465723649:-8475474922759781208
-Dtests.multiplier=3
    [junit] WARNING: test method: 'testIndexingThenDeleting' left
thread running: merge thread: _0(4.0):Cv9021 _3(4.0):Cv10594 into _7
    [junit] WARNING: test method: 'testIndexingThenDeleting' left
thread running: merge thread: _4(4.0):Cv5297 _5(4.0):Cv5297 into _6
    [junit] RESOURCE LEAK: test method: 'testIndexingThenDeleting'
left 2 thread(s) running
    [junit] NOTE: test params are: codec=RandomCodecProvider:
{field=MockFixedIntBlock(blockSize=26)}, locale=th,
timezone=US/East-Indiana
    [junit] NOTE: all tests run in this JVM:
    [junit] [TestIndexWriter]
    [junit] NOTE: Mac OS X 10.6.6 x86_64/Apple Inc. 1.6.0_22
(64-bit)/cpus=4,threads=2,free=57964904,total=85000192
    [junit] ------------- ---------------- ---------------
    [junit] Testcase:
testIndexingThenDeleting(org.apache.lucene.index.TestIndexWriter): FAILED
    [junit] flush happened too quickly during deleting count=1155
    [junit] junit.framework.AssertionFailedError: flush happened too
quickly during deleting count=1155
    [junit] at
org.apache.lucene.index.TestIndexWriter.testIndexingThenDeleting(TestIndexWriter.java:2579)
    [junit] at
org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1213)
    [junit] at
org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1145)
    [junit]
    [junit]
    [junit] Test org.apache.lucene.index.TestIndexWriter FAILED


-Yonik
http://lucidimagination.com



On Tue, Mar 8, 2011 at 4:46 AM, Michael McCandless
<[hidden email]> wrote:

> This seed doesn't repro the failure for me:
>
>    ant test -Dtestcase=TestIndexWriter
> -Dtestmethod=testIndexingThenDeleting
> -Dtests.seed=2772841086465723649:-8475474922759781208
> -Dtests.multiplier=3
>
> Can anyone repro in their env?
>
> Mike
>
> On Mon, Mar 7, 2011 at 8:33 PM, Apache Hudson Server
> <[hidden email]> wrote:
>> Build: https://hudson.apache.org/hudson/job/Lucene-Solr-tests-only-trunk/5709/
>>
>> 1 tests failed.
>> REGRESSION:  org.apache.lucene.index.TestIndexWriter.testIndexingThenDeleting
>>
>> Error Message:
>> flush happened too quickly during deleting count=1155
>>
>> Stack Trace:
>> junit.framework.AssertionFailedError: flush happened too quickly during deleting count=1155
>>        at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1213)
>>        at org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1145)
>>        at org.apache.lucene.index.TestIndexWriter.testIndexingThenDeleting(TestIndexWriter.java:2579)
>>
>>
>>
>>
>> Build Log (for compile errors):
>> [...truncated 3082 lines...]
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>
>
>
> --
> Mike
>
> http://blog.mikemccandless.com
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [HUDSON] Lucene-Solr-tests-only-trunk - Build # 5709 - Failure

Yonik Seeley-2-2
Verbose version below.

-Yonik
http://lucidimagination.com

junit-sequential:
    [junit] Testsuite: org.apache.lucene.index.TestIndexWriter
    [junit] Tests run: 1, Failures: 1, Errors: 0, Time elapsed: 12.834 sec
    [junit]
    [junit] ------------- Standard Output ---------------
    [junit]
    [junit] NOTE: running test testIndexingThenDeleting
    [junit] IFD [Tue Mar 08 12:27:38 EST 2011; main]: setInfoStream
deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@38650646
    [junit] IW 0 [Tue Mar 08 12:27:38 EST 2011; main]:
    [junit] dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@21b64e6a
lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@47d62270)
    [junit] index=
    [junit] version=4.0-SNAPSHOT
    [junit] matchVersion=LUCENE_40
    [junit] analyzer=org.apache.lucene.analysis.MockAnalyzer
    [junit] delPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy
    [junit] commit=null
    [junit] openMode=CREATE_OR_APPEND
    [junit] similarityProvider=org.apache.lucene.search.DefaultSimilarity
    [junit] termIndexInterval=721
    [junit] mergeScheduler=org.apache.lucene.index.ConcurrentMergeScheduler
    [junit] default WRITE_LOCK_TIMEOUT=1000
    [junit] writeLockTimeout=1000
    [junit] maxBufferedDeleteTerms=-1
    [junit] ramBufferSizeMB=0.5
    [junit] maxBufferedDocs=-1
    [junit] mergedSegmentWarmer=null
    [junit] codecProvider=RandomCodecProvider: {}
    [junit] mergePolicy=[LogDocMergePolicy: minMergeSize=1000,
mergeFactor=2, maxMergeSize=9223372036854775807,
maxMergeSizeForOptimize=9223372036854775807,
calibrateSizeByDeletes=true, maxMergeDocs=2147483647,
useCompoundFile=true, requireContiguousMerge=false]
    [junit] maxThreadStates=8
    [junit] readerPooling=false
    [junit] readerTermsIndexDivisor=1
    [junit]
    [junit] TEST: iter doIndexing=true
    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.502 vs trigger=0.5 deletesMB=0
byteBlockFree=0.502 perDocFree=0.502
    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]: DW:     nothing
to free; set bufferIsFull
    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]: DW:     after
free: freedMB=0 usedMB=0.502
    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]: now trigger
flush reason=ram full: new document
    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]:   index before flush
    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]: DW: flush
postings as segment _0 numDocs=9021
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: new segment
has vectors
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:
flushedFiles=[_0.nrm, _0_0.frq, _0.fnm, _0_0.tib, _0.tvd, _0.tvf,
_0_0.tii, _0_0.skp, _0.tvx, _0_0.pos, _0_0.doc, _0.fdx, _0_0.pyl,
_0.fdt]
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flushed
codecs=SegmentCodecs [codecs=[MockFixedIntBlock(blockSize=26)],
provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush:
segment=_0(4.0):Cv9021
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:
ramUsed=0.502 MB newFlushedSize=1.969 MB (0.627 MB w/o doc stores)
docs/MB=4,581.765 new/old=124.906%
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush time 1694 msec
    [junit] IFD [Tue Mar 08 12:27:43 EST 2011; main]: now checkpoint
"null" [1 segments ; isCommit = false]
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: don't apply
deletes now delTermCount=0 bytesUsed=0
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: clearFlushPending
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: LMP:
findMerges: 1 segments
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: LMP: seg _0
level=13.139071 size=9021
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: LMP:   level
12.389071 to 13.139071: 1 segments
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: CMS: now merge
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: CMS:   index:
_0(4.0):Cv9021
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: CMS:   no more
merges pending; now return
    [junit] TEST: iter doIndexing=false
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.501 vs trigger=0.5 deletesMB=0
byteBlockFree=0.501 perDocFree=0.501
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.47
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.47 perDocFree=0.47
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.438 perDocFree=0.438
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.407 perDocFree=0.407
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.376 perDocFree=0.376
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.345 perDocFree=0.345
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.313 perDocFree=0.313
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.282 perDocFree=0.282
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.251 perDocFree=0.251
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.22 perDocFree=0.22
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.188 perDocFree=0.188
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.157 perDocFree=0.157
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.126 perDocFree=0.126
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     nothing to free
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0.001 usedMB=0.499
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
byteBlockFree=0.125 perDocFree=0.125
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     nothing
to free; set bufferIsFull
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
free: freedMB=0 usedMB=0.5
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: now trigger
flush reason=ram full: add delete/doc
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   index before
flush _0(4.0):Cv9021
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: no
docs; skipping
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: push
buffered deletes
    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: push deletes
2989 deleted terms (unique count=2989) bytesUsed=191296 delGen=2
packetCount=1
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: delGen=2
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: don't apply
deletes now delTermCount=2989 bytesUsed=191296
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: clearFlushPending
    [junit] TEST: iter doIndexing=false
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: now trigger
flush reason=ram full: add delete/doc
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   index before
flush _0(4.0):Cv9021
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: no
docs; skipping
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: push
buffered deletes
    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: push deletes
1539 deleted terms (unique count=1539) bytesUsed=98496 delGen=3
packetCount=2
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: delGen=3
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: force apply
deletes bytesUsed=289792 vs ramBuffer=524288.0
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: apply all
deletes during flush
    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: applyDeletes:
infos=[_0(4.0):Cv9021] packetCount=2
    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]:
seg=_0(4.0):Cv9021 segGen=1 coalesced deletes=[gen=0 4528 deleted
terms (unique count=2989) bytesUsed=382592] delCount=0
    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: applyDeletes took 43 msec
    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: prune
sis=[_0(4.0):Cv9021] minGen=4 packetCount=2
    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: pruneDeletes:
prune 2 packets; 0 packets remain
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: clearFlushPending
    [junit] TEST: iter doIndexing=false
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: now trigger
flush reason=ram full: add delete/doc
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   index before
flush _0(4.0):Cv9021
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: no
docs; skipping
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: push
buffered deletes
    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: push deletes
2989 deleted terms (unique count=2989) bytesUsed=191296 delGen=5
packetCount=1
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: delGen=5
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: don't apply
deletes now delTermCount=2989 bytesUsed=191296
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: clearFlushPending
    [junit] TEST: iter doIndexing=true
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: now trigger
flush reason=ram full: new document
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   index before
flush _0(4.0):Cv9021
    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush
postings as segment _1 numDocs=5297
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW: new segment
has vectors
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW:
flushedFiles=[_1_0.doc, _1.tvx, _1_0.tii, _1_0.frq, _1_0.tib, _1.fnm,
_1_0.pos, _1_0.pyl, _1.fdx, _1.tvf, _1.fdt, _1_0.skp, _1.tvd, _1.nrm]
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW: flushed
codecs=SegmentCodecs [codecs=[MockFixedIntBlock(blockSize=26)],
provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW: flush:
segment=_1(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW:
ramUsed=0.346 MB newFlushedSize=1.156 MB (0.368 MB w/o doc stores)
docs/MB=4,581.306 new/old=106.538%
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW: flush time 943 msec
    [junit] IFD [Tue Mar 08 12:27:44 EST 2011; main]: now checkpoint
"null" [2 segments ; isCommit = false]
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: don't apply
deletes now delTermCount=2989 bytesUsed=191296
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: clearFlushPending
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: LMP:
findMerges: 2 segments
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: LMP: seg _0
level=13.139071 size=9021
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: LMP: seg _1
level=12.370959 size=5297
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: LMP:   level
12.389071 to 13.139071: 1 segments
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: LMP:   level
11.620959 to 12.370959: 1 segments
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: CMS: now merge
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: CMS:   index:
_0(4.0):Cv9021 _1(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: CMS:   no more
merges pending; now return
    [junit] TEST: iter doIndexing=true
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.345 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.345 perDocFree=0.345
    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW:     after
free: freedMB=0.063 usedMB=0.464
    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.346 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.346 perDocFree=0.346
    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]: DW:     nothing
to free; set bufferIsFull
    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]: DW:     after
free: freedMB=0 usedMB=0.528
    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]: now trigger
flush reason=ram full: new document
    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]:   index before
flush _0(4.0):Cv9021 _1(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]: DW: flush
postings as segment _2 numDocs=5297
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW: new segment
has vectors
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:
flushedFiles=[_2_0.frq, _2_0.doc, _2_0.pyl, _2_0.pos, _2.fdt, _2.fdx,
_2.tvx, _2.fnm, _2.tvd, _2_0.tib, _2_0.skp, _2.tvf, _2.nrm, _2_0.tii]
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW: flushed
codecs=SegmentCodecs [codecs=[MockFixedIntBlock(blockSize=26)],
provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW: flush:
segment=_2(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:
ramUsed=0.346 MB newFlushedSize=1.156 MB (0.368 MB w/o doc stores)
docs/MB=4,581.306 new/old=106.538%
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW: flush time 939 msec
    [junit] IFD [Tue Mar 08 12:27:46 EST 2011; main]: now checkpoint
"null" [3 segments ; isCommit = false]
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: don't apply
deletes now delTermCount=2989 bytesUsed=191296
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: clearFlushPending
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP:
findMerges: 3 segments
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP: seg _0
level=13.139071 size=9021
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP: seg _1
level=12.370959 size=5297
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP: seg _2
level=12.370959 size=5297
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP:   level
12.389071 to 13.139071: 1 segments
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP:   level
11.620959 to 12.370959: 2 segments
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP:     1 to
3: add this merge
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: add merge to
pendingMerges: _1(4.0):Cv5297 _2(4.0):Cv5297 [total 1 pending]
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: CMS: now merge
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: CMS:   index:
_0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297
    [junit] BD 0 [Tue Mar 08 12:27:46 EST 2011; main]: applyDeletes:
infos=[_1(4.0):Cv5297, _2(4.0):Cv5297] packetCount=1
    [junit] BD 0 [Tue Mar 08 12:27:46 EST 2011; main]: applyDeletes took 0 msec
    [junit] BD 0 [Tue Mar 08 12:27:46 EST 2011; main]: prune
sis=[_0(4.0):Cv9021, _1(4.0):Cv5297, _2(4.0):Cv5297] minGen=4
packetCount=1
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: merge seg=_3
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: CMS:   consider
merge _1(4.0):Cv5297 _2(4.0):Cv5297 into _3
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: CMS:     launch
new thread [Lucene Merge Thread #0]
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; Lucene Merge Thread
#0]: CMS:   merge thread: start
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: CMS: set
priority of merge thread Lucene Merge Thread #0 to 6
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: CMS:   no more
merges pending; now return
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; Lucene Merge Thread
#0]: now merge
    [junit]   merge=_1(4.0):Cv5297 _2(4.0):Cv5297 into _3
    [junit]   index=_0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297
    [junit] TEST: iter doIndexing=true
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; Lucene Merge Thread
#0]: merging _1(4.0):Cv5297 _2(4.0):Cv5297 into _3 mergeVectors=true
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.345 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.345 perDocFree=0.345
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:     after
free: freedMB=0.063 usedMB=0.464
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; Lucene Merge Thread
#0]: merge: total 10594 docs
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.346 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.346 perDocFree=0.346
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:     nothing
to free; set bufferIsFull
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:     after
free: freedMB=0 usedMB=0.528
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: now trigger
flush reason=ram full: new document
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]:   index before
flush _0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW: flush
postings as segment _4 numDocs=5297
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: new segment
has vectors
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:
flushedFiles=[_4.tvx, _4_0.frq, _4.fnm, _4.nrm, _4.fdt, _4_0.tib,
_4.fdx, _4.tvd, _4.tvf, _4_0.skp, _4_0.doc, _4_0.tii, _4_0.pos,
_4_0.pyl]
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flushed
codecs=SegmentCodecs [codecs=[MockFixedIntBlock(blockSize=26)],
provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush:
segment=_4(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:
ramUsed=0.346 MB newFlushedSize=1.156 MB (0.368 MB w/o doc stores)
docs/MB=4,581.306 new/old=106.538%
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush time 955 msec
    [junit] IFD [Tue Mar 08 12:27:47 EST 2011; main]: now checkpoint
"null" [4 segments ; isCommit = false]
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: don't apply
deletes now delTermCount=2989 bytesUsed=191296
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: clearFlushPending
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP:
findMerges: 4 segments
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP: seg _0
level=13.139071 size=9021
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP: seg _1
already being merged; skip
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP: seg _2
already being merged; skip
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP: seg _4
level=12.370959 size=5297
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP:   level
12.389071 to 13.139071: 1 segments
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP:   level
11.620959 to 12.370959: 1 segments
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: CMS: now merge
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: CMS:   index:
_0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297 _4(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: CMS:   no more
merges pending; now return
    [junit] TEST: iter doIndexing=false
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.345 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.345 perDocFree=0.345
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
free: freedMB=0.063 usedMB=0.464
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.281 perDocFree=0.281
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.25 perDocFree=0.25
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.219 perDocFree=0.219
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.188 perDocFree=0.188
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.156 perDocFree=0.156
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.125 perDocFree=0.125
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     nothing
to free; set bufferIsFull
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
free: freedMB=0 usedMB=0.5
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: now trigger
flush reason=ram full: add delete/doc
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]:   index before
flush _0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297 _4(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush: no
docs; skipping
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush: push
buffered deletes
    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]: push deletes
1539 deleted terms (unique count=1539) bytesUsed=98496 delGen=10
packetCount=2
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush: delGen=10
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: force apply
deletes bytesUsed=289792 vs ramBuffer=524288.0
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: apply all
deletes during flush
    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]: applyDeletes:
infos=[_0(4.0):Cv9021, _1(4.0):Cv5297, _2(4.0):Cv5297, _4(4.0):Cv5297]
packetCount=2
    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]:
seg=_4(4.0):Cv5297 segGen=9 coalesced deletes=[gen=0 1539 deleted
terms (unique count=1539) bytesUsed=196992] delCount=0
    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]:
seg=_2(4.0):Cv5297 segGen=8 coalesced deletes=[gen=0 1539 deleted
terms (unique count=1539) bytesUsed=196992] delCount=0
    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]:
seg=_1(4.0):Cv5297 segGen=8 coalesced deletes=[gen=0 1539 deleted
terms (unique count=1539) bytesUsed=196992] delCount=0
    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]:
seg=_0(4.0):Cv9021 segGen=4 coalesced deletes=[gen=0 4528 deleted
terms (unique count=2989) bytesUsed=382592] delCount=0
    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]: applyDeletes took 33 msec
    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]: prune
sis=[_0(4.0):Cv9021, _1(4.0):Cv5297, _2(4.0):Cv5297, _4(4.0):Cv5297]
minGen=11 packetCount=2
    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]: pruneDeletes:
prune 2 packets; 0 packets remain
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: clearFlushPending
    [junit] TEST: iter doIndexing=false
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: now trigger
flush reason=ram full: add delete/doc
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]:   index before
flush _0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297 _4(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush: no
docs; skipping
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush: push
buffered deletes
    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]: push deletes
2989 deleted terms (unique count=2989) bytesUsed=191296 delGen=12
packetCount=1
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush: delGen=12
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: don't apply
deletes now delTermCount=2989 bytesUsed=191296
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: clearFlushPending
    [junit] TEST: iter doIndexing=true
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: now trigger
flush reason=ram full: new document
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]:   index before
flush _0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297 _4(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush
postings as segment _5 numDocs=5297
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: merge segmentCodecs=SegmentCodecs
[codecs=[MockFixedIntBlock(blockSize=26)],
provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: merge store matchedCount=2 vs 2
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: new segment
has vectors
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:
flushedFiles=[_5_0.pyl, _5.fnm, _5_0.doc, _5.fdt, _5.tvd, _5_0.pos,
_5.tvf, _5_0.tib, _5.nrm, _5.tvx, _5_0.skp, _5_0.tii, _5.fdx,
_5_0.frq]
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flushed
codecs=SegmentCodecs [codecs=[MockFixedIntBlock(blockSize=26)],
provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush:
segment=_5(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:
ramUsed=0.346 MB newFlushedSize=1.156 MB (0.368 MB w/o doc stores)
docs/MB=4,581.306 new/old=106.538%
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush time 925 msec
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; main]: now checkpoint
"null" [5 segments ; isCommit = false]
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: don't apply
deletes now delTermCount=2989 bytesUsed=191296
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: clearFlushPending
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP:
findMerges: 5 segments
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP: seg _0
level=13.139071 size=9021
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP: seg _1
already being merged; skip
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP: seg _2
already being merged; skip
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP: seg _4
level=12.370959 size=5297
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP: seg _5
level=12.370959 size=5297
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP:   level
12.389071 to 13.139071: 1 segments
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP:   level
11.620959 to 12.370959: 2 segments
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP:     1 to
3: add this merge
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: add merge to
pendingMerges: _4(4.0):Cv5297 _5(4.0):Cv5297 [total 1 pending]
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS: now merge
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS:   index:
_0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297 _4(4.0):Cv5297
_5(4.0):Cv5297
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: applyDeletes:
infos=[_4(4.0):Cv5297, _5(4.0):Cv5297] packetCount=1
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]:
seg=_4(4.0):Cv5297 segGen=11 coalesced deletes=[gen=0 2989 deleted
terms (unique count=2989) bytesUsed=382592] delCount=0
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: applyDeletes took 3 msec
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: prune
sis=[_0(4.0):Cv9021, _1(4.0):Cv5297, _2(4.0):Cv5297, _4(4.0):Cv5297,
_5(4.0):Cv5297] minGen=11 packetCount=1
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: merge seg=_6
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS:   consider
merge _4(4.0):Cv5297 _5(4.0):Cv5297 into _6
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: commitMerge: _1(4.0):Cv5297 _2(4.0):Cv5297 into _3
index=_0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297 _4(4.0):Cv5297
_5(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS:     launch
new thread [Lucene Merge Thread #1]
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: commitMergeDeletes _1(4.0):Cv5297 _2(4.0):Cv5297 into _3
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: after commit: _0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297
_5(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS: set
priority of merge thread Lucene Merge Thread #0 to 6
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#1]: CMS:   merge thread: start
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS: set
priority of merge thread Lucene Merge Thread #1 to 7
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: now checkpoint "null" [4 segments ; isCommit = false]
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2_0.frq"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1_0.frq"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1.fnm"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1_0.doc"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2_0.doc"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2.fdt"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2.fdx"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1.fdx"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1.fdt"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1_0.skp"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2_0.skp"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1.nrm"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2.nrm"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1_0.tii"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2_0.pos"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1_0.tib"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2.tvx"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1_0.pos"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2.tvd"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2.tvf"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1.tvx"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2_0.pyl"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2.fnm"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1_0.pyl"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1.tvf"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2_0.tib"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_1.tvd"
    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: delete "_2_0.tii"
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS:   no more
merges pending; now return
    [junit] TEST: iter doIndexing=false
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: LMP: findMerges: 4 segments
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: LMP: seg _0 level=13.139071 size=9021
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: LMP: seg _3 level=13.37096 size=10594
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.345 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.345 perDocFree=0.345
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: LMP: seg _4 already being merged; skip
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: LMP: seg _5 already being merged; skip
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
free: freedMB=0.063 usedMB=0.464
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: LMP:   level 12.62096 to 13.37096: 2 segments
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: LMP:     0 to 2: add this merge
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: add merge to pendingMerges: _0(4.0):Cv9021 _3(4.0):Cv10594 [total
1 pending]
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.281 perDocFree=0.281
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: merge time 2785 msec for 10594 docs
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#1]: now merge
    [junit]   merge=_4(4.0):Cv5297 _5(4.0):Cv5297 into _6
    [junit]   index=_0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297 _5(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: applyDeletes: infos=[_0(4.0):Cv9021, _3(4.0):Cv10594]
packetCount=1
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#1]: merging _4(4.0):Cv5297 _5(4.0):Cv5297 into _6 mergeVectors=true
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.25 perDocFree=0.25
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.219 perDocFree=0.219
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.188 perDocFree=0.188
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.156 perDocFree=0.156
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
free: freedMB=0.031 usedMB=0.469
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
byteBlockFree=0.125 perDocFree=0.125
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     nothing
to free; set bufferIsFull
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
free: freedMB=0 usedMB=0.5
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: now trigger
flush reason=ram full: add delete/doc
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#1]: merge: total 10594 docs
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: seg=_3(4.0):Cv10594 segGen=11 coalesced deletes=[gen=0 2989
deleted terms (unique count=2989) bytesUsed=382592] delCount=0
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: seg=_0(4.0):Cv9021 segGen=11 coalesced deletes=[gen=0 2989
deleted terms (unique count=2989) bytesUsed=382592] delCount=0
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: applyDeletes took 7 msec
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: prune sis=[_0(4.0):Cv9021, _3(4.0):Cv10594, _4(4.0):Cv5297,
_5(4.0):Cv5297] minGen=14 packetCount=1
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: pruneDeletes: prune 1 packets; 0 packets remain
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: merge seg=_7
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: CMS: set priority of merge thread Lucene Merge Thread #0 to 6
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]:   index before
flush _0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297 _5(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: CMS: set priority of merge thread Lucene Merge Thread #1 to 7
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: no
docs; skipping
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: CMS:   merge thread: do another merge _0(4.0):Cv9021
_3(4.0):Cv10594 into _7
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: push
buffered deletes
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: push deletes
1539 deleted terms (unique count=1539) bytesUsed=98496 delGen=16
packetCount=1
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: delGen=16
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: don't apply
deletes now delTermCount=1539 bytesUsed=98496
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: clearFlushPending
    [junit] TEST: iter doIndexing=false
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: now merge
    [junit]   merge=_0(4.0):Cv9021 _3(4.0):Cv10594 into _7
    [junit]   index=_0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297 _5(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: merging _0(4.0):Cv9021 _3(4.0):Cv10594 into _7 mergeVectors=true
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: now trigger
flush reason=ram full: add delete/doc
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]:   index before
flush _0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297 _5(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: no
docs; skipping
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: push
buffered deletes
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: push deletes
2243 deleted terms (unique count=2243) bytesUsed=143552 delGen=17
packetCount=2
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: delGen=17
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: don't apply
deletes now delTermCount=3782 bytesUsed=242048
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: clearFlushPending
    [junit] TEST: iter doIndexing=false
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: now trigger
flush reason=ram full: add delete/doc
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]:   start flush:
applyAllDeletes=false
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]:   index before
flush _0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297 _5(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: no
docs; skipping
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: push
buffered deletes
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: push deletes
1155 deleted terms (unique count=1155) bytesUsed=73920 delGen=18
packetCount=3
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: delGen=18
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
#0]: merge: total 19615 docs
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: force apply
deletes bytesUsed=315968 vs ramBuffer=524288.0
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: apply all
deletes during flush
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: applyDeletes:
infos=[_0(4.0):Cv9021, _3(4.0):Cv10594, _4(4.0):Cv5297,
_5(4.0):Cv5297] packetCount=3
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]:
seg=_3(4.0):Cv10594 segGen=15 coalesced deletes=[gen=0 4937 deleted
terms (unique count=2243) bytesUsed=287104] delCount=0
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]:
seg=_0(4.0):Cv9021 segGen=15 coalesced deletes=[gen=0 4937 deleted
terms (unique count=2243) bytesUsed=287104] delCount=0
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]:
seg=_5(4.0):Cv5297 segGen=14 coalesced deletes=[gen=0 4937 deleted
terms (unique count=2243) bytesUsed=287104] delCount=0
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]:
seg=_4(4.0):Cv5297 segGen=14 coalesced deletes=[gen=0 4937 deleted
terms (unique count=2243) bytesUsed=287104] delCount=0
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: applyDeletes took 5 msec
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: prune
sis=[_0(4.0):Cv9021, _3(4.0):Cv10594, _4(4.0):Cv5297, _5(4.0):Cv5297]
minGen=19 packetCount=3
    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: pruneDeletes:
prune 3 packets; 0 packets remain
    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: clearFlushPending
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: merge segmentCodecs=SegmentCodecs
[codecs=[MockFixedIntBlock(blockSize=26)],
provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: merge store matchedCount=2 vs 2
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: commitMerge: _4(4.0):Cv5297 _5(4.0):Cv5297 into _6
index=_0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297 _5(4.0):Cv5297
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: commitMergeDeletes _4(4.0):Cv5297 _5(4.0):Cv5297 into _6
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: after commit: _0(4.0):Cv9021 _3(4.0):Cv10594 _6(4.0):Cv10594
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: now checkpoint "null" [3 segments ; isCommit = false]
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5.fdt"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5.tvd"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5.tvf"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4.fnm"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4.fdx"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5_0.tib"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5.nrm"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5.tvx"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5_0.tii"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4_0.pyl"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4.tvx"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5_0.pyl"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5_0.pos"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4_0.tib"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4.tvd"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5_0.skp"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4.tvf"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4_0.tii"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4_0.pos"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4_0.frq"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4_0.doc"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5_0.frq"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5.fnm"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5_0.doc"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4.nrm"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4.fdt"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_4_0.skp"
    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: delete "_5.fdx"
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: LMP: findMerges: 3 segments
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: LMP: seg _0 already being merged; skip
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: LMP: seg _3 already being merged; skip
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: LMP: seg _6 level=13.37096 size=10594
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: LMP:   level 12.62096 to 13.37096: 1 segments
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: merge time 2245 msec for 10594 docs
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: CMS:   merge thread: done
    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
#1]: CMS: set priority of merge thread Lucene Merge Thread #0 to 6
    [junit] ------------- ---------------- ---------------
    [junit] ------------- Standard Error -----------------
    [junit] NOTE: reproduce with: ant test -Dtestcase=TestIndexWriter
-Dtestmethod=testIndexingThenDeleting
-Dtests.seed=2772841086465723649:-8475474922759781208
-Dtests.multiplier=3
    [junit] WARNING: test method: 'testIndexingThenDeleting' left
thread running: merge thread: _0(4.0):Cv9021 _3(4.0):Cv10594 into _7
    [junit] WARNING: test method: 'testIndexingThenDeleting' left
thread running: merge thread: _4(4.0):Cv5297 _5(4.0):Cv5297 into _6
    [junit] RESOURCE LEAK: test method: 'testIndexingThenDeleting'
left 2 thread(s) running
    [junit] NOTE: test params are: codec=RandomCodecProvider:
{field=MockFixedIntBlock(blockSize=26)}, locale=th,
timezone=US/East-Indiana
    [junit] NOTE: all tests run in this JVM:
    [junit] [TestIndexWriter]
    [junit] NOTE: Mac OS X 10.6.6 x86_64/Apple Inc. 1.6.0_22
(64-bit)/cpus=4,threads=2,free=68747472,total=85000192
    [junit] ------------- ---------------- ---------------
    [junit] Testcase:
testIndexingThenDeleting(org.apache.lucene.index.TestIndexWriter): FAILED
    [junit] flush happened too quickly during deleting count=1155
    [junit] junit.framework.AssertionFailedError: flush happened too
quickly during deleting count=1155
    [junit] at
org.apache.lucene.index.TestIndexWriter.testIndexingThenDeleting(TestIndexWriter.java:2579)
    [junit] at
org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1213)
    [junit] at
org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1145)
    [junit]
    [junit]
    [junit] Test org.apache.lucene.index.TestIndexWriter FAILED

BUILD FAILED
/opt/code/lusolr/lucene/common-build.xml:534: The following error
occurred while executing this line:
/opt/code/lusolr/lucene/common-build.xml:523: Tests failed!

Total time: 16 seconds

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [HUDSON] Lucene-Solr-tests-only-trunk - Build # 5709 - Failure

Michael McCandless-2
Thanks Yonik -- I'll dig!

On Tue, Mar 8, 2011 at 12:30 PM, Yonik Seeley
<[hidden email]> wrote:

> Verbose version below.
>
> -Yonik
> http://lucidimagination.com
>
> junit-sequential:
>    [junit] Testsuite: org.apache.lucene.index.TestIndexWriter
>    [junit] Tests run: 1, Failures: 1, Errors: 0, Time elapsed: 12.834 sec
>    [junit]
>    [junit] ------------- Standard Output ---------------
>    [junit]
>    [junit] NOTE: running test testIndexingThenDeleting
>    [junit] IFD [Tue Mar 08 12:27:38 EST 2011; main]: setInfoStream
> deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@38650646
>    [junit] IW 0 [Tue Mar 08 12:27:38 EST 2011; main]:
>    [junit] dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@21b64e6a
> lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@47d62270)
>    [junit] index=
>    [junit] version=4.0-SNAPSHOT
>    [junit] matchVersion=LUCENE_40
>    [junit] analyzer=org.apache.lucene.analysis.MockAnalyzer
>    [junit] delPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy
>    [junit] commit=null
>    [junit] openMode=CREATE_OR_APPEND
>    [junit] similarityProvider=org.apache.lucene.search.DefaultSimilarity
>    [junit] termIndexInterval=721
>    [junit] mergeScheduler=org.apache.lucene.index.ConcurrentMergeScheduler
>    [junit] default WRITE_LOCK_TIMEOUT=1000
>    [junit] writeLockTimeout=1000
>    [junit] maxBufferedDeleteTerms=-1
>    [junit] ramBufferSizeMB=0.5
>    [junit] maxBufferedDocs=-1
>    [junit] mergedSegmentWarmer=null
>    [junit] codecProvider=RandomCodecProvider: {}
>    [junit] mergePolicy=[LogDocMergePolicy: minMergeSize=1000,
> mergeFactor=2, maxMergeSize=9223372036854775807,
> maxMergeSizeForOptimize=9223372036854775807,
> calibrateSizeByDeletes=true, maxMergeDocs=2147483647,
> useCompoundFile=true, requireContiguousMerge=false]
>    [junit] maxThreadStates=8
>    [junit] readerPooling=false
>    [junit] readerTermsIndexDivisor=1
>    [junit]
>    [junit] TEST: iter doIndexing=true
>    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.502 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.502 perDocFree=0.502
>    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]: DW:     nothing
> to free; set bufferIsFull
>    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]: DW:     after
> free: freedMB=0 usedMB=0.502
>    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]: now trigger
> flush reason=ram full: new document
>    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]:   index before flush
>    [junit] IW 0 [Tue Mar 08 12:27:41 EST 2011; main]: DW: flush
> postings as segment _0 numDocs=9021
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: new segment
> has vectors
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:
> flushedFiles=[_0.nrm, _0_0.frq, _0.fnm, _0_0.tib, _0.tvd, _0.tvf,
> _0_0.tii, _0_0.skp, _0.tvx, _0_0.pos, _0_0.doc, _0.fdx, _0_0.pyl,
> _0.fdt]
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flushed
> codecs=SegmentCodecs [codecs=[MockFixedIntBlock(blockSize=26)],
> provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush:
> segment=_0(4.0):Cv9021
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:
> ramUsed=0.502 MB newFlushedSize=1.969 MB (0.627 MB w/o doc stores)
> docs/MB=4,581.765 new/old=124.906%
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush time 1694 msec
>    [junit] IFD [Tue Mar 08 12:27:43 EST 2011; main]: now checkpoint
> "null" [1 segments ; isCommit = false]
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: don't apply
> deletes now delTermCount=0 bytesUsed=0
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: clearFlushPending
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: LMP:
> findMerges: 1 segments
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: LMP: seg _0
> level=13.139071 size=9021
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: LMP:   level
> 12.389071 to 13.139071: 1 segments
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: CMS: now merge
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: CMS:   index:
> _0(4.0):Cv9021
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: CMS:   no more
> merges pending; now return
>    [junit] TEST: iter doIndexing=false
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.501 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.501 perDocFree=0.501
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.47
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.47 perDocFree=0.47
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.438 perDocFree=0.438
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.407 perDocFree=0.407
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.376 perDocFree=0.376
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.345 perDocFree=0.345
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.313 perDocFree=0.313
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.282 perDocFree=0.282
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.251 perDocFree=0.251
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.22 perDocFree=0.22
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.188 perDocFree=0.188
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.157 perDocFree=0.157
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.126 perDocFree=0.126
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     nothing to free
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0.001 usedMB=0.499
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.5 vs trigger=0.5 deletesMB=0
> byteBlockFree=0.125 perDocFree=0.125
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     nothing
> to free; set bufferIsFull
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW:     after
> free: freedMB=0 usedMB=0.5
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: now trigger
> flush reason=ram full: add delete/doc
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   index before
> flush _0(4.0):Cv9021
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: no
> docs; skipping
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: push
> buffered deletes
>    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: push deletes
> 2989 deleted terms (unique count=2989) bytesUsed=191296 delGen=2
> packetCount=1
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: delGen=2
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: don't apply
> deletes now delTermCount=2989 bytesUsed=191296
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: clearFlushPending
>    [junit] TEST: iter doIndexing=false
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: now trigger
> flush reason=ram full: add delete/doc
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   index before
> flush _0(4.0):Cv9021
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: no
> docs; skipping
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: push
> buffered deletes
>    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: push deletes
> 1539 deleted terms (unique count=1539) bytesUsed=98496 delGen=3
> packetCount=2
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: delGen=3
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: force apply
> deletes bytesUsed=289792 vs ramBuffer=524288.0
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: apply all
> deletes during flush
>    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: applyDeletes:
> infos=[_0(4.0):Cv9021] packetCount=2
>    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]:
> seg=_0(4.0):Cv9021 segGen=1 coalesced deletes=[gen=0 4528 deleted
> terms (unique count=2989) bytesUsed=382592] delCount=0
>    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: applyDeletes took 43 msec
>    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: prune
> sis=[_0(4.0):Cv9021] minGen=4 packetCount=2
>    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: pruneDeletes:
> prune 2 packets; 0 packets remain
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: clearFlushPending
>    [junit] TEST: iter doIndexing=false
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: now trigger
> flush reason=ram full: add delete/doc
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   index before
> flush _0(4.0):Cv9021
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: no
> docs; skipping
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: push
> buffered deletes
>    [junit] BD 0 [Tue Mar 08 12:27:43 EST 2011; main]: push deletes
> 2989 deleted terms (unique count=2989) bytesUsed=191296 delGen=5
> packetCount=1
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush: delGen=5
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: don't apply
> deletes now delTermCount=2989 bytesUsed=191296
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: clearFlushPending
>    [junit] TEST: iter doIndexing=true
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: now trigger
> flush reason=ram full: new document
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]:   index before
> flush _0(4.0):Cv9021
>    [junit] IW 0 [Tue Mar 08 12:27:43 EST 2011; main]: DW: flush
> postings as segment _1 numDocs=5297
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW: new segment
> has vectors
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW:
> flushedFiles=[_1_0.doc, _1.tvx, _1_0.tii, _1_0.frq, _1_0.tib, _1.fnm,
> _1_0.pos, _1_0.pyl, _1.fdx, _1.tvf, _1.fdt, _1_0.skp, _1.tvd, _1.nrm]
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW: flushed
> codecs=SegmentCodecs [codecs=[MockFixedIntBlock(blockSize=26)],
> provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW: flush:
> segment=_1(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW:
> ramUsed=0.346 MB newFlushedSize=1.156 MB (0.368 MB w/o doc stores)
> docs/MB=4,581.306 new/old=106.538%
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW: flush time 943 msec
>    [junit] IFD [Tue Mar 08 12:27:44 EST 2011; main]: now checkpoint
> "null" [2 segments ; isCommit = false]
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: don't apply
> deletes now delTermCount=2989 bytesUsed=191296
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: clearFlushPending
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: LMP:
> findMerges: 2 segments
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: LMP: seg _0
> level=13.139071 size=9021
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: LMP: seg _1
> level=12.370959 size=5297
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: LMP:   level
> 12.389071 to 13.139071: 1 segments
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: LMP:   level
> 11.620959 to 12.370959: 1 segments
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: CMS: now merge
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: CMS:   index:
> _0(4.0):Cv9021 _1(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: CMS:   no more
> merges pending; now return
>    [junit] TEST: iter doIndexing=true
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.345 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.345 perDocFree=0.345
>    [junit] IW 0 [Tue Mar 08 12:27:44 EST 2011; main]: DW:     after
> free: freedMB=0.063 usedMB=0.464
>    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.346 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.346 perDocFree=0.346
>    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]: DW:     nothing
> to free; set bufferIsFull
>    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]: DW:     after
> free: freedMB=0 usedMB=0.528
>    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]: now trigger
> flush reason=ram full: new document
>    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]:   index before
> flush _0(4.0):Cv9021 _1(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:45 EST 2011; main]: DW: flush
> postings as segment _2 numDocs=5297
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW: new segment
> has vectors
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:
> flushedFiles=[_2_0.frq, _2_0.doc, _2_0.pyl, _2_0.pos, _2.fdt, _2.fdx,
> _2.tvx, _2.fnm, _2.tvd, _2_0.tib, _2_0.skp, _2.tvf, _2.nrm, _2_0.tii]
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW: flushed
> codecs=SegmentCodecs [codecs=[MockFixedIntBlock(blockSize=26)],
> provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW: flush:
> segment=_2(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:
> ramUsed=0.346 MB newFlushedSize=1.156 MB (0.368 MB w/o doc stores)
> docs/MB=4,581.306 new/old=106.538%
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW: flush time 939 msec
>    [junit] IFD [Tue Mar 08 12:27:46 EST 2011; main]: now checkpoint
> "null" [3 segments ; isCommit = false]
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: don't apply
> deletes now delTermCount=2989 bytesUsed=191296
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: clearFlushPending
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP:
> findMerges: 3 segments
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP: seg _0
> level=13.139071 size=9021
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP: seg _1
> level=12.370959 size=5297
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP: seg _2
> level=12.370959 size=5297
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP:   level
> 12.389071 to 13.139071: 1 segments
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP:   level
> 11.620959 to 12.370959: 2 segments
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: LMP:     1 to
> 3: add this merge
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: add merge to
> pendingMerges: _1(4.0):Cv5297 _2(4.0):Cv5297 [total 1 pending]
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: CMS: now merge
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: CMS:   index:
> _0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297
>    [junit] BD 0 [Tue Mar 08 12:27:46 EST 2011; main]: applyDeletes:
> infos=[_1(4.0):Cv5297, _2(4.0):Cv5297] packetCount=1
>    [junit] BD 0 [Tue Mar 08 12:27:46 EST 2011; main]: applyDeletes took 0 msec
>    [junit] BD 0 [Tue Mar 08 12:27:46 EST 2011; main]: prune
> sis=[_0(4.0):Cv9021, _1(4.0):Cv5297, _2(4.0):Cv5297] minGen=4
> packetCount=1
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: merge seg=_3
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: CMS:   consider
> merge _1(4.0):Cv5297 _2(4.0):Cv5297 into _3
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: CMS:     launch
> new thread [Lucene Merge Thread #0]
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; Lucene Merge Thread
> #0]: CMS:   merge thread: start
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: CMS: set
> priority of merge thread Lucene Merge Thread #0 to 6
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: CMS:   no more
> merges pending; now return
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; Lucene Merge Thread
> #0]: now merge
>    [junit]   merge=_1(4.0):Cv5297 _2(4.0):Cv5297 into _3
>    [junit]   index=_0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297
>    [junit] TEST: iter doIndexing=true
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; Lucene Merge Thread
> #0]: merging _1(4.0):Cv5297 _2(4.0):Cv5297 into _3 mergeVectors=true
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.345 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.345 perDocFree=0.345
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:     after
> free: freedMB=0.063 usedMB=0.464
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; Lucene Merge Thread
> #0]: merge: total 10594 docs
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.346 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.346 perDocFree=0.346
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:     nothing
> to free; set bufferIsFull
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW:     after
> free: freedMB=0 usedMB=0.528
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: now trigger
> flush reason=ram full: new document
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]:   index before
> flush _0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:46 EST 2011; main]: DW: flush
> postings as segment _4 numDocs=5297
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: new segment
> has vectors
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:
> flushedFiles=[_4.tvx, _4_0.frq, _4.fnm, _4.nrm, _4.fdt, _4_0.tib,
> _4.fdx, _4.tvd, _4.tvf, _4_0.skp, _4_0.doc, _4_0.tii, _4_0.pos,
> _4_0.pyl]
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flushed
> codecs=SegmentCodecs [codecs=[MockFixedIntBlock(blockSize=26)],
> provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush:
> segment=_4(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:
> ramUsed=0.346 MB newFlushedSize=1.156 MB (0.368 MB w/o doc stores)
> docs/MB=4,581.306 new/old=106.538%
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush time 955 msec
>    [junit] IFD [Tue Mar 08 12:27:47 EST 2011; main]: now checkpoint
> "null" [4 segments ; isCommit = false]
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: don't apply
> deletes now delTermCount=2989 bytesUsed=191296
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: clearFlushPending
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP:
> findMerges: 4 segments
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP: seg _0
> level=13.139071 size=9021
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP: seg _1
> already being merged; skip
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP: seg _2
> already being merged; skip
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP: seg _4
> level=12.370959 size=5297
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP:   level
> 12.389071 to 13.139071: 1 segments
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: LMP:   level
> 11.620959 to 12.370959: 1 segments
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: CMS: now merge
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: CMS:   index:
> _0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297 _4(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: CMS:   no more
> merges pending; now return
>    [junit] TEST: iter doIndexing=false
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.345 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.345 perDocFree=0.345
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
> free: freedMB=0.063 usedMB=0.464
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.281 perDocFree=0.281
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.25 perDocFree=0.25
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.219 perDocFree=0.219
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.188 perDocFree=0.188
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.156 perDocFree=0.156
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.125 perDocFree=0.125
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     nothing
> to free; set bufferIsFull
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW:     after
> free: freedMB=0 usedMB=0.5
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: now trigger
> flush reason=ram full: add delete/doc
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]:   index before
> flush _0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297 _4(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush: no
> docs; skipping
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush: push
> buffered deletes
>    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]: push deletes
> 1539 deleted terms (unique count=1539) bytesUsed=98496 delGen=10
> packetCount=2
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush: delGen=10
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: force apply
> deletes bytesUsed=289792 vs ramBuffer=524288.0
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: apply all
> deletes during flush
>    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]: applyDeletes:
> infos=[_0(4.0):Cv9021, _1(4.0):Cv5297, _2(4.0):Cv5297, _4(4.0):Cv5297]
> packetCount=2
>    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]:
> seg=_4(4.0):Cv5297 segGen=9 coalesced deletes=[gen=0 1539 deleted
> terms (unique count=1539) bytesUsed=196992] delCount=0
>    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]:
> seg=_2(4.0):Cv5297 segGen=8 coalesced deletes=[gen=0 1539 deleted
> terms (unique count=1539) bytesUsed=196992] delCount=0
>    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]:
> seg=_1(4.0):Cv5297 segGen=8 coalesced deletes=[gen=0 1539 deleted
> terms (unique count=1539) bytesUsed=196992] delCount=0
>    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]:
> seg=_0(4.0):Cv9021 segGen=4 coalesced deletes=[gen=0 4528 deleted
> terms (unique count=2989) bytesUsed=382592] delCount=0
>    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]: applyDeletes took 33 msec
>    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]: prune
> sis=[_0(4.0):Cv9021, _1(4.0):Cv5297, _2(4.0):Cv5297, _4(4.0):Cv5297]
> minGen=11 packetCount=2
>    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]: pruneDeletes:
> prune 2 packets; 0 packets remain
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: clearFlushPending
>    [junit] TEST: iter doIndexing=false
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: now trigger
> flush reason=ram full: add delete/doc
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]:   index before
> flush _0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297 _4(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush: no
> docs; skipping
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush: push
> buffered deletes
>    [junit] BD 0 [Tue Mar 08 12:27:47 EST 2011; main]: push deletes
> 2989 deleted terms (unique count=2989) bytesUsed=191296 delGen=12
> packetCount=1
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush: delGen=12
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: don't apply
> deletes now delTermCount=2989 bytesUsed=191296
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: clearFlushPending
>    [junit] TEST: iter doIndexing=true
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: now trigger
> flush reason=ram full: new document
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]:   index before
> flush _0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297 _4(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:47 EST 2011; main]: DW: flush
> postings as segment _5 numDocs=5297
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: merge segmentCodecs=SegmentCodecs
> [codecs=[MockFixedIntBlock(blockSize=26)],
> provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: merge store matchedCount=2 vs 2
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: new segment
> has vectors
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:
> flushedFiles=[_5_0.pyl, _5.fnm, _5_0.doc, _5.fdt, _5.tvd, _5_0.pos,
> _5.tvf, _5_0.tib, _5.nrm, _5.tvx, _5_0.skp, _5_0.tii, _5.fdx,
> _5_0.frq]
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flushed
> codecs=SegmentCodecs [codecs=[MockFixedIntBlock(blockSize=26)],
> provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush:
> segment=_5(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:
> ramUsed=0.346 MB newFlushedSize=1.156 MB (0.368 MB w/o doc stores)
> docs/MB=4,581.306 new/old=106.538%
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush time 925 msec
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; main]: now checkpoint
> "null" [5 segments ; isCommit = false]
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: don't apply
> deletes now delTermCount=2989 bytesUsed=191296
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: clearFlushPending
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP:
> findMerges: 5 segments
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP: seg _0
> level=13.139071 size=9021
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP: seg _1
> already being merged; skip
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP: seg _2
> already being merged; skip
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP: seg _4
> level=12.370959 size=5297
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP: seg _5
> level=12.370959 size=5297
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP:   level
> 12.389071 to 13.139071: 1 segments
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP:   level
> 11.620959 to 12.370959: 2 segments
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: LMP:     1 to
> 3: add this merge
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: add merge to
> pendingMerges: _4(4.0):Cv5297 _5(4.0):Cv5297 [total 1 pending]
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS: now merge
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS:   index:
> _0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297 _4(4.0):Cv5297
> _5(4.0):Cv5297
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: applyDeletes:
> infos=[_4(4.0):Cv5297, _5(4.0):Cv5297] packetCount=1
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]:
> seg=_4(4.0):Cv5297 segGen=11 coalesced deletes=[gen=0 2989 deleted
> terms (unique count=2989) bytesUsed=382592] delCount=0
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: applyDeletes took 3 msec
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: prune
> sis=[_0(4.0):Cv9021, _1(4.0):Cv5297, _2(4.0):Cv5297, _4(4.0):Cv5297,
> _5(4.0):Cv5297] minGen=11 packetCount=1
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: merge seg=_6
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS:   consider
> merge _4(4.0):Cv5297 _5(4.0):Cv5297 into _6
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: commitMerge: _1(4.0):Cv5297 _2(4.0):Cv5297 into _3
> index=_0(4.0):Cv9021 _1(4.0):Cv5297 _2(4.0):Cv5297 _4(4.0):Cv5297
> _5(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS:     launch
> new thread [Lucene Merge Thread #1]
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: commitMergeDeletes _1(4.0):Cv5297 _2(4.0):Cv5297 into _3
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: after commit: _0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297
> _5(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS: set
> priority of merge thread Lucene Merge Thread #0 to 6
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #1]: CMS:   merge thread: start
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS: set
> priority of merge thread Lucene Merge Thread #1 to 7
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: now checkpoint "null" [4 segments ; isCommit = false]
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2_0.frq"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1_0.frq"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1.fnm"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1_0.doc"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2_0.doc"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2.fdt"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2.fdx"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1.fdx"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1.fdt"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1_0.skp"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2_0.skp"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1.nrm"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2.nrm"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1_0.tii"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2_0.pos"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1_0.tib"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2.tvx"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1_0.pos"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2.tvd"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2.tvf"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1.tvx"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2_0.pyl"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2.fnm"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1_0.pyl"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1.tvf"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2_0.tib"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_1.tvd"
>    [junit] IFD [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: delete "_2_0.tii"
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: CMS:   no more
> merges pending; now return
>    [junit] TEST: iter doIndexing=false
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: LMP: findMerges: 4 segments
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: LMP: seg _0 level=13.139071 size=9021
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: LMP: seg _3 level=13.37096 size=10594
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.345 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.345 perDocFree=0.345
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: LMP: seg _4 already being merged; skip
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: LMP: seg _5 already being merged; skip
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
> free: freedMB=0.063 usedMB=0.464
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: LMP:   level 12.62096 to 13.37096: 2 segments
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: LMP:     0 to 2: add this merge
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: add merge to pendingMerges: _0(4.0):Cv9021 _3(4.0):Cv10594 [total
> 1 pending]
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.281 perDocFree=0.281
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: merge time 2785 msec for 10594 docs
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #1]: now merge
>    [junit]   merge=_4(4.0):Cv5297 _5(4.0):Cv5297 into _6
>    [junit]   index=_0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297 _5(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: applyDeletes: infos=[_0(4.0):Cv9021, _3(4.0):Cv10594]
> packetCount=1
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #1]: merging _4(4.0):Cv5297 _5(4.0):Cv5297 into _6 mergeVectors=true
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.25 perDocFree=0.25
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.219 perDocFree=0.219
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.188 perDocFree=0.188
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.156 perDocFree=0.156
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
> free: freedMB=0.031 usedMB=0.469
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:   RAM:
> balance allocations: usedMB=0.318 vs trigger=0.5 deletesMB=0.182
> byteBlockFree=0.125 perDocFree=0.125
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     nothing
> to free; set bufferIsFull
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW:     after
> free: freedMB=0 usedMB=0.5
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: now trigger
> flush reason=ram full: add delete/doc
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #1]: merge: total 10594 docs
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: seg=_3(4.0):Cv10594 segGen=11 coalesced deletes=[gen=0 2989
> deleted terms (unique count=2989) bytesUsed=382592] delCount=0
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: seg=_0(4.0):Cv9021 segGen=11 coalesced deletes=[gen=0 2989
> deleted terms (unique count=2989) bytesUsed=382592] delCount=0
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: applyDeletes took 7 msec
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: prune sis=[_0(4.0):Cv9021, _3(4.0):Cv10594, _4(4.0):Cv5297,
> _5(4.0):Cv5297] minGen=14 packetCount=1
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: pruneDeletes: prune 1 packets; 0 packets remain
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: merge seg=_7
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: CMS: set priority of merge thread Lucene Merge Thread #0 to 6
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]:   index before
> flush _0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297 _5(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: CMS: set priority of merge thread Lucene Merge Thread #1 to 7
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: no
> docs; skipping
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: CMS:   merge thread: do another merge _0(4.0):Cv9021
> _3(4.0):Cv10594 into _7
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: push
> buffered deletes
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: push deletes
> 1539 deleted terms (unique count=1539) bytesUsed=98496 delGen=16
> packetCount=1
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: delGen=16
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: don't apply
> deletes now delTermCount=1539 bytesUsed=98496
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: clearFlushPending
>    [junit] TEST: iter doIndexing=false
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: now merge
>    [junit]   merge=_0(4.0):Cv9021 _3(4.0):Cv10594 into _7
>    [junit]   index=_0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297 _5(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: merging _0(4.0):Cv9021 _3(4.0):Cv10594 into _7 mergeVectors=true
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: now trigger
> flush reason=ram full: add delete/doc
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]:   index before
> flush _0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297 _5(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: no
> docs; skipping
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: push
> buffered deletes
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: push deletes
> 2243 deleted terms (unique count=2243) bytesUsed=143552 delGen=17
> packetCount=2
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: delGen=17
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: don't apply
> deletes now delTermCount=3782 bytesUsed=242048
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: clearFlushPending
>    [junit] TEST: iter doIndexing=false
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: now trigger
> flush reason=ram full: add delete/doc
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]:   start flush:
> applyAllDeletes=false
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]:   index before
> flush _0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297 _5(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: no
> docs; skipping
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: push
> buffered deletes
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: push deletes
> 1155 deleted terms (unique count=1155) bytesUsed=73920 delGen=18
> packetCount=3
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: DW: flush: delGen=18
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; Lucene Merge Thread
> #0]: merge: total 19615 docs
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: force apply
> deletes bytesUsed=315968 vs ramBuffer=524288.0
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: apply all
> deletes during flush
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: applyDeletes:
> infos=[_0(4.0):Cv9021, _3(4.0):Cv10594, _4(4.0):Cv5297,
> _5(4.0):Cv5297] packetCount=3
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]:
> seg=_3(4.0):Cv10594 segGen=15 coalesced deletes=[gen=0 4937 deleted
> terms (unique count=2243) bytesUsed=287104] delCount=0
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]:
> seg=_0(4.0):Cv9021 segGen=15 coalesced deletes=[gen=0 4937 deleted
> terms (unique count=2243) bytesUsed=287104] delCount=0
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]:
> seg=_5(4.0):Cv5297 segGen=14 coalesced deletes=[gen=0 4937 deleted
> terms (unique count=2243) bytesUsed=287104] delCount=0
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]:
> seg=_4(4.0):Cv5297 segGen=14 coalesced deletes=[gen=0 4937 deleted
> terms (unique count=2243) bytesUsed=287104] delCount=0
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: applyDeletes took 5 msec
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: prune
> sis=[_0(4.0):Cv9021, _3(4.0):Cv10594, _4(4.0):Cv5297, _5(4.0):Cv5297]
> minGen=19 packetCount=3
>    [junit] BD 0 [Tue Mar 08 12:27:48 EST 2011; main]: pruneDeletes:
> prune 3 packets; 0 packets remain
>    [junit] IW 0 [Tue Mar 08 12:27:48 EST 2011; main]: clearFlushPending
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: merge segmentCodecs=SegmentCodecs
> [codecs=[MockFixedIntBlock(blockSize=26)],
> provider=RandomCodecProvider: {field=MockFixedIntBlock(blockSize=26)}]
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: merge store matchedCount=2 vs 2
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: commitMerge: _4(4.0):Cv5297 _5(4.0):Cv5297 into _6
> index=_0(4.0):Cv9021 _3(4.0):Cv10594 _4(4.0):Cv5297 _5(4.0):Cv5297
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: commitMergeDeletes _4(4.0):Cv5297 _5(4.0):Cv5297 into _6
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: after commit: _0(4.0):Cv9021 _3(4.0):Cv10594 _6(4.0):Cv10594
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: now checkpoint "null" [3 segments ; isCommit = false]
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5.fdt"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5.tvd"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5.tvf"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4.fnm"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4.fdx"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5_0.tib"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5.nrm"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5.tvx"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5_0.tii"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4_0.pyl"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4.tvx"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5_0.pyl"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5_0.pos"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4_0.tib"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4.tvd"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5_0.skp"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4.tvf"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4_0.tii"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4_0.pos"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4_0.frq"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4_0.doc"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5_0.frq"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5.fnm"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5_0.doc"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4.nrm"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4.fdt"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_4_0.skp"
>    [junit] IFD [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: delete "_5.fdx"
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: LMP: findMerges: 3 segments
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: LMP: seg _0 already being merged; skip
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: LMP: seg _3 already being merged; skip
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: LMP: seg _6 level=13.37096 size=10594
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: LMP:   level 12.62096 to 13.37096: 1 segments
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: merge time 2245 msec for 10594 docs
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: CMS:   merge thread: done
>    [junit] IW 0 [Tue Mar 08 12:27:51 EST 2011; Lucene Merge Thread
> #1]: CMS: set priority of merge thread Lucene Merge Thread #0 to 6
>    [junit] ------------- ---------------- ---------------
>    [junit] ------------- Standard Error -----------------
>    [junit] NOTE: reproduce with: ant test -Dtestcase=TestIndexWriter
> -Dtestmethod=testIndexingThenDeleting
> -Dtests.seed=2772841086465723649:-8475474922759781208
> -Dtests.multiplier=3
>    [junit] WARNING: test method: 'testIndexingThenDeleting' left
> thread running: merge thread: _0(4.0):Cv9021 _3(4.0):Cv10594 into _7
>    [junit] WARNING: test method: 'testIndexingThenDeleting' left
> thread running: merge thread: _4(4.0):Cv5297 _5(4.0):Cv5297 into _6
>    [junit] RESOURCE LEAK: test method: 'testIndexingThenDeleting'
> left 2 thread(s) running
>    [junit] NOTE: test params are: codec=RandomCodecProvider:
> {field=MockFixedIntBlock(blockSize=26)}, locale=th,
> timezone=US/East-Indiana
>    [junit] NOTE: all tests run in this JVM:
>    [junit] [TestIndexWriter]
>    [junit] NOTE: Mac OS X 10.6.6 x86_64/Apple Inc. 1.6.0_22
> (64-bit)/cpus=4,threads=2,free=68747472,total=85000192
>    [junit] ------------- ---------------- ---------------
>    [junit] Testcase:
> testIndexingThenDeleting(org.apache.lucene.index.TestIndexWriter):      FAILED
>    [junit] flush happened too quickly during deleting count=1155
>    [junit] junit.framework.AssertionFailedError: flush happened too
> quickly during deleting count=1155
>    [junit]     at
> org.apache.lucene.index.TestIndexWriter.testIndexingThenDeleting(TestIndexWriter.java:2579)
>    [junit]     at
> org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1213)
>    [junit]     at
> org.apache.lucene.util.LuceneTestCase$LuceneTestCaseRunner.runChild(LuceneTestCase.java:1145)
>    [junit]
>    [junit]
>    [junit] Test org.apache.lucene.index.TestIndexWriter FAILED
>
> BUILD FAILED
> /opt/code/lusolr/lucene/common-build.xml:534: The following error
> occurred while executing this line:
> /opt/code/lusolr/lucene/common-build.xml:523: Tests failed!
>
> Total time: 16 seconds
>



--
Mike

http://blog.mikemccandless.com

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]