Thanks Yonik -- I'll dig! On Tue, Mar 8, 2011 at 12:30 PM, Yonik Seeley <[email protected]> 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: [email protected] For additional commands, e-mail: [email protected]
