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: [email protected]
For additional commands, e-mail: [email protected]
