Return-Path: Delivered-To: apmail-lucene-java-user-archive@www.apache.org Received: (qmail 37801 invoked from network); 27 Oct 2009 18:57:42 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.3) by minotaur.apache.org with SMTP; 27 Oct 2009 18:57:42 -0000 Received: (qmail 27774 invoked by uid 500); 27 Oct 2009 18:57:39 -0000 Delivered-To: apmail-lucene-java-user-archive@lucene.apache.org Received: (qmail 27739 invoked by uid 500); 27 Oct 2009 18:57:39 -0000 Mailing-List: contact java-user-help@lucene.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: java-user@lucene.apache.org Delivered-To: mailing list java-user@lucene.apache.org Received: (qmail 27729 invoked by uid 99); 27 Oct 2009 18:57:39 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 27 Oct 2009 18:57:39 +0000 X-ASF-Spam-Status: No, hits=1.2 required=10.0 tests=SPF_NEUTRAL X-Spam-Check-By: apache.org Received-SPF: neutral (nike.apache.org: local policy) Received: from [209.85.211.183] (HELO mail-yw0-f183.google.com) (209.85.211.183) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 27 Oct 2009 18:57:30 +0000 Received: by ywh13 with SMTP id 13so15047ywh.29 for ; Tue, 27 Oct 2009 11:57:08 -0700 (PDT) MIME-Version: 1.0 Received: by 10.150.241.5 with SMTP id o5mr15580764ybh.173.1256669828120; Tue, 27 Oct 2009 11:57:08 -0700 (PDT) In-Reply-To: References: <9ac0c6aa0910261150o509ab052j2e948f3c66da9753@mail.gmail.com> <9ac0c6aa0910261200p1e12078du4b76daec4907f6@mail.gmail.com> <9ac0c6aa0910270737q1abbf3bejd10b53ee5b9a78c0@mail.gmail.com> Date: Tue, 27 Oct 2009 14:57:07 -0400 Message-ID: <9ac0c6aa0910271157x555b0e3ar375d3e56f7466232@mail.gmail.com> Subject: Re: IO exception during merge/optimize From: Michael McCandless To: java-user@lucene.apache.org Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable X-Virus-Checked: Checked by ClamAV on apache.org This is odd -- is it reproducible? Can you narrow it down to a small set of docs that when indexed produce a corrupted index? If you attempt to optimize the index, does it fail? Mike On Tue, Oct 27, 2009 at 1:40 PM, Peter Keegan wrot= e: > It seems the index is corrupted immediately after the initial build (ampl= e > disk space was provided): > > Output from CheckIndex: > > Opening index @ D:\mnsavs\lresumes1\lresumes1.luc\lresumes1.search.main.2 > > Segments file=3Dsegments_3 numSegments=3D1 version=3DFORMAT_DIAGNOSTICS [= Lucene > 2.9] > =A01 of 1: name=3D_7 docCount=3D1077025 > =A0 =A0compound=3Dfalse > =A0 =A0hasProx=3Dtrue > =A0 =A0numFiles=3D8 > =A0 =A0size (MB)=3D3,201.196 > =A0 =A0diagnostics =3D {optimize=3Dtrue, mergeFactor=3D7, os.version=3D5.= 2, os=3DWindows > 2003, mergeDocStores=3Dfalse, lucene.version=3D2.9 exported - 2009-10-26 > 07:58:55, source=3Dmerge, os.arch=3Damd64, java.version=3D1.6.0_03, > java.vendor=3DSun Microsystems Inc.} > =A0 =A0docStoreOffset=3D0 > =A0 =A0docStoreSegment=3D_0 > =A0 =A0docStoreIsCompoundFile=3Dfalse > =A0 =A0no deletions > =A0 =A0test: open reader.........OK > =A0 =A0test: fields..............OK [33 fields] > =A0 =A0test: field norms.........OK [33 fields] > =A0 =A0test: terms, freq, prox...ERROR [term contents:? docFreq=3D1 !=3D = num docs > seen 482 + num docs deleted 0] > java.lang.RuntimeException: term contents:? docFreq=3D1 !=3D num docs see= n 482 + > num docs deleted 0 > =A0 =A0at org.apache.lucene.index.CheckIndex.testTermIndex(CheckIndex.jav= a:675) > =A0 =A0at org.apache.lucene.index.CheckIndex.checkIndex(CheckIndex.java:5= 30) > =A0 =A0at org.apache.lucene.index.CheckIndex.main(CheckIndex.java:903) > =A0 =A0test: stored fields.......OK [3231075 total field count; avg 3 fie= lds > per doc] > =A0 =A0test: term vectors........OK [0 total vector count; avg 0 term/fre= q > vector fields per doc] > FAILED > =A0 =A0WARNING: fixIndex() would remove reference to this segment; full > exception: > java.lang.RuntimeException: Term Index test failed > =A0 =A0at org.apache.lucene.index.CheckIndex.checkIndex(CheckIndex.java:5= 43) > =A0 =A0at org.apache.lucene.index.CheckIndex.main(CheckIndex.java:903) > > WARNING: 1 broken segments (containing 1077025 documents) detected > WARNING: would write new segments file, and 1077025 documents would be lo= st, > if -fix were specified > > Searching on this index seems to be fine, though. > > Here is the IndexWriter log from the build: > > IFD [Indexer]: setInfoStream > deletionPolicy=3Dorg.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy= @2a9cfec1 > IW 0 [Indexer]: setInfoStream: > dir=3Dorg.apache.lucene.store.SimpleFSDirectory@D:\mnsavs\lresumes1\lresu= mes1.luc\lresumes1.update.main.2 > autoCommit=3Dfalse > mergePolicy=3Dorg.apache.lucene.index.LogByteSizeMergePolicy@291946c2merg= eScheduler=3Dorg.apache.lucene.index.ConcurrentMergeScheduler@3a747fa2ramBu= fferSizeMB=3D16.0 > maxBufferedDocs=3D-1 maxBuffereDeleteTerms=3D-1 > maxFieldLength=3D2147483647 index=3D > IW 0 [Indexer]: setRAMBufferSizeMB 910.25 > IW 0 [Indexer]: setMaxBufferedDocs 1000000 > IW 0 [Indexer]: flush at getReader > IW 0 [Indexer]: =A0 flush: segment=3Dnull docStoreSegment=3Dnull docStore= Offset=3D0 > flushDocs=3Dfalse flushDeletes=3Dtrue flushDocStores=3Dfalse numDocs=3D0 > numBufDelTerms=3D0 > IW 0 [Indexer]: =A0 index before flush > IW 0 [UpdWriterBuild]: DW: =A0 RAM: now flush @ usedMB=3D886.463 allocMB= =3D886.463 > deletesMB=3D23.803 triggerMB=3D910.25 > IW 0 [UpdWriterBuild]: =A0 flush: segment=3D_0 docStoreSegment=3D_0 > docStoreOffset=3D0 flushDocs=3Dtrue flushDeletes=3Dfalse flushDocStores= =3Dfalse > numDocs=3D171638 numBufDelTerms=3D171638 > IW 0 [UpdWriterBuild]: =A0 index before flush > IW 0 [UpdWriterBuild]: DW: flush postings as segment _0 numDocs=3D171638 > IW 0 [UpdWriterBuild]: DW: =A0 oldRAMSize=3D929523712 newFlushedSize=3D57= 3198529 > docs/MB=3D313.985 new/old=3D61.666% > IFD [UpdWriterBuild]: now checkpoint "segments_1" [1 segments ; isCommit = =3D > false] > IFD [UpdWriterBuild]: now checkpoint "segments_1" [1 segments ; isCommit = =3D > false] > IW 0 [UpdWriterBuild]: LMP: findMerges: 1 segments > IW 0 [UpdWriterBuild]: LMP: =A0 level 8.008305 to 8.758305: 1 segments > IW 0 [UpdWriterBuild]: CMS: now merge > IW 0 [UpdWriterBuild]: CMS: =A0 index: _0:C171638->_0 > IW 0 [UpdWriterBuild]: CMS: =A0 no more merges pending; now return > IW 0 [UpdWriterBuild]: DW: =A0 RAM: now flush @ usedMB=3D857.977 allocMB= =3D901.32 > deletesMB=3D52.274 triggerMB=3D910.25 > IW 0 [UpdWriterBuild]: =A0 flush: segment=3D_1 docStoreSegment=3D_0 > docStoreOffset=3D171638 flushDocs=3Dtrue flushDeletes=3Dfalse flushDocSto= res=3Dfalse > numDocs=3D204995 numBufDelTerms=3D204995 > IW 0 [UpdWriterBuild]: =A0 index before flush _0:C171638->_0 > IW 0 [UpdWriterBuild]: DW: flush postings as segment _1 numDocs=3D204995 > IW 0 [UpdWriterBuild]: DW: =A0 oldRAMSize=3D899653632 newFlushedSize=3D54= 4283851 > docs/MB=3D394.928 new/old=3D60.499% > IFD [UpdWriterBuild]: now checkpoint "segments_1" [2 segments ; isCommit = =3D > false] > IFD [UpdWriterBuild]: now checkpoint "segments_1" [2 segments ; isCommit = =3D > false] > IW 0 [UpdWriterBuild]: LMP: findMerges: 2 segments > IW 0 [UpdWriterBuild]: LMP: =A0 level 8.008305 to 8.758305: 2 segments > IW 0 [UpdWriterBuild]: CMS: now merge > IW 0 [UpdWriterBuild]: CMS: =A0 index: _0:C171638->_0 _1:C204995->_0 > IW 0 [UpdWriterBuild]: CMS: =A0 no more merges pending; now return > IW 0 [UpdWriterBuild]: DW: =A0 RAM: now balance allocations: usedMB=3D834= .645 vs > trigger=3D910.25 allocMB=3D901.32 deletesMB=3D75.627 vs trigger=3D955.762 > byteBlockFree=3D35.938 charBlockFree=3D8.938 > IW 0 [UpdWriterBuild]: DW: =A0 =A0 nothing to free > IW 0 [UpdWriterBuild]: DW: =A0 =A0 after free: freedMB=3D66.613 usedMB=3D= 910.272 > allocMB=3D834.707 > IW 0 [UpdWriterBuild]: =A0 flush: segment=3D_2 docStoreSegment=3D_0 > docStoreOffset=3D376633 flushDocs=3Dtrue flushDeletes=3Dfalse flushDocSto= res=3Dfalse > numDocs=3D168236 numBufDelTerms=3D168236 > IW 0 [UpdWriterBuild]: =A0 index before flush _0:C171638->_0 _1:C204995->= _0 > IW 0 [UpdWriterBuild]: DW: flush postings as segment _2 numDocs=3D168236 > IW 0 [UpdWriterBuild]: DW: =A0 oldRAMSize=3D875188224 newFlushedSize=3D53= 0720464 > docs/MB=3D332.394 new/old=3D60.641% > IFD [UpdWriterBuild]: now checkpoint "segments_1" [3 segments ; isCommit = =3D > false] > IFD [UpdWriterBuild]: now checkpoint "segments_1" [3 segments ; isCommit = =3D > false] > IW 0 [UpdWriterBuild]: LMP: findMerges: 3 segments > IW 0 [UpdWriterBuild]: LMP: =A0 level 8.008305 to 8.758305: 3 segments > IW 0 [UpdWriterBuild]: CMS: now merge > IW 0 [UpdWriterBuild]: CMS: =A0 index: _0:C171638->_0 _1:C204995->_0 > _2:C168236->_0 > IW 0 [UpdWriterBuild]: CMS: =A0 no more merges pending; now return > IW 0 [UpdWriterBuild]: DW: =A0 RAM: now flush @ usedMB=3D814.282 allocMB= =3D835.832 > deletesMB=3D95.997 triggerMB=3D910.25 > IW 0 [UpdWriterBuild]: =A0 flush: segment=3D_3 docStoreSegment=3D_0 > docStoreOffset=3D544869 flushDocs=3Dtrue flushDeletes=3Dfalse flushDocSto= res=3Dfalse > numDocs=3D146894 numBufDelTerms=3D146894 > IW 0 [UpdWriterBuild]: =A0 index before flush _0:C171638->_0 _1:C204995->= _0 > _2:C168236->_0 > IW 0 [UpdWriterBuild]: DW: flush postings as segment _3 numDocs=3D146894 > IW 0 [UpdWriterBuild]: DW: =A0 oldRAMSize=3D853836800 newFlushedSize=3D52= 2388771 > docs/MB=3D294.856 new/old=3D61.181% > IFD [UpdWriterBuild]: now checkpoint "segments_1" [4 segments ; isCommit = =3D > false] > IFD [UpdWriterBuild]: now checkpoint "segments_1" [4 segments ; isCommit = =3D > false] > IW 0 [UpdWriterBuild]: LMP: findMerges: 4 segments > IW 0 [UpdWriterBuild]: LMP: =A0 level 8.008305 to 8.758305: 4 segments > IW 0 [UpdWriterBuild]: CMS: now merge > IW 0 [UpdWriterBuild]: CMS: =A0 index: _0:C171638->_0 _1:C204995->_0 > _2:C168236->_0 _3:C146894->_0 > IW 0 [UpdWriterBuild]: CMS: =A0 no more merges pending; now return > IW 0 [UpdWriterBuild]: DW: =A0 RAM: now flush @ usedMB=3D791.724 allocMB= =3D835.832 > deletesMB=3D118.535 triggerMB=3D910.25 > IW 0 [UpdWriterBuild]: =A0 flush: segment=3D_4 docStoreSegment=3D_0 > docStoreOffset=3D691763 flushDocs=3Dtrue flushDeletes=3Dfalse flushDocSto= res=3Dfalse > numDocs=3D162034 numBufDelTerms=3D162034 > IW 0 [UpdWriterBuild]: =A0 index before flush _0:C171638->_0 _1:C204995->= _0 > _2:C168236->_0 _3:C146894->_0 > IW 0 [UpdWriterBuild]: DW: flush postings as segment _4 numDocs=3D162034 > IW 0 [UpdWriterBuild]: DW: =A0 oldRAMSize=3D830182400 newFlushedSize=3D49= 8741034 > docs/MB=3D340.668 new/old=3D60.076% > IFD [UpdWriterBuild]: now checkpoint "segments_1" [5 segments ; isCommit = =3D > false] > IFD [UpdWriterBuild]: now checkpoint "segments_1" [5 segments ; isCommit = =3D > false] > IW 0 [UpdWriterBuild]: LMP: findMerges: 5 segments > IW 0 [UpdWriterBuild]: LMP: =A0 level 8.008305 to 8.758305: 5 segments > IW 0 [UpdWriterBuild]: CMS: now merge > IW 0 [UpdWriterBuild]: CMS: =A0 index: _0:C171638->_0 _1:C204995->_0 > _2:C168236->_0 _3:C146894->_0 _4:C162034->_0 > IW 0 [UpdWriterBuild]: CMS: =A0 no more merges pending; now return > IW 0 [UpdWriterBuild]: DW: =A0 RAM: now balance allocations: usedMB=3D771= .396 vs > trigger=3D910.25 allocMB=3D835.832 deletesMB=3D138.875 vs trigger=3D955.7= 62 > byteBlockFree=3D39.688 charBlockFree=3D7.188 > IW 0 [UpdWriterBuild]: DW: =A0 =A0 nothing to free > IW 0 [UpdWriterBuild]: DW: =A0 =A0 after free: freedMB=3D64.374 usedMB=3D= 910.271 > allocMB=3D771.458 > IW 0 [UpdWriterBuild]: =A0 flush: segment=3D_5 docStoreSegment=3D_0 > docStoreOffset=3D853797 flushDocs=3Dtrue flushDeletes=3Dfalse flushDocSto= res=3Dfalse > numDocs=3D146250 numBufDelTerms=3D146250 > IW 0 [UpdWriterBuild]: =A0 index before flush _0:C171638->_0 _1:C204995->= _0 > _2:C168236->_0 _3:C146894->_0 _4:C162034->_0 > IW 0 [UpdWriterBuild]: DW: flush postings as segment _5 numDocs=3D146250 > IW 0 [UpdWriterBuild]: DW: =A0 oldRAMSize=3D808866816 newFlushedSize=3D48= 5212402 > docs/MB=3D316.056 new/old=3D59.987% > IFD [UpdWriterBuild]: now checkpoint "segments_1" [6 segments ; isCommit = =3D > false] > IFD [UpdWriterBuild]: now checkpoint "segments_1" [6 segments ; isCommit = =3D > false] > IW 0 [UpdWriterBuild]: LMP: findMerges: 6 segments > IW 0 [UpdWriterBuild]: LMP: =A0 level 8.008305 to 8.758305: 6 segments > IW 0 [UpdWriterBuild]: CMS: now merge > IW 0 [UpdWriterBuild]: CMS: =A0 index: _0:C171638->_0 _1:C204995->_0 > _2:C168236->_0 _3:C146894->_0 _4:C162034->_0 _5:C146250->_0 > IW 0 [UpdWriterBuild]: CMS: =A0 no more merges pending; now return > IW 0 [Indexer]: commit: start > IW 0 [Indexer]: commit: now prepare > IW 0 [Indexer]: prepareCommit: flush > IW 0 [Indexer]: =A0 flush: segment=3D_6 docStoreSegment=3D_0 > docStoreOffset=3D1000047 flushDocs=3Dtrue flushDeletes=3Dtrue flushDocSto= res=3Dtrue > numDocs=3D76978 numBufDelTerms=3D76978 > IW 0 [Indexer]: =A0 index before flush _0:C171638->_0 _1:C204995->_0 > _2:C168236->_0 _3:C146894->_0 _4:C162034->_0 _5:C146250->_0 > IW 0 [Indexer]: =A0 flush shared docStore segment _0 > IW 0 [Indexer]: DW: closeDocStore: 2 files to flush to segment _0 > numDocs=3D1077025 > IW 0 [Indexer]: DW: flush postings as segment _6 numDocs=3D76978 > IW 0 [Indexer]: DW: =A0 oldRAMSize=3D486968320 newFlushedSize=3D273168136 > docs/MB=3D295.486 new/old=3D56.096% > IFD [Indexer]: now checkpoint "segments_1" [7 segments ; isCommit =3D fal= se] > IW 0 [Indexer]: DW: apply 1077025 buffered deleted terms and 0 deleted > docIDs and 0 deleted queries on 7 segments. > IFD [Indexer]: now checkpoint "segments_1" [7 segments ; isCommit =3D fal= se] > IW 0 [Indexer]: LMP: findMerges: 7 segments > IW 0 [Indexer]: LMP: =A0 level 8.008305 to 8.758305: 7 segments > IW 0 [Indexer]: CMS: now merge > IW 0 [Indexer]: CMS: =A0 index: _0:C171638->_0 _1:C204995->_0 _2:C168236-= >_0 > _3:C146894->_0 _4:C162034->_0 _5:C146250->_0 _6:C76978->_0 > IW 0 [Indexer]: CMS: =A0 no more merges pending; now return > IW 0 [Indexer]: startCommit(): start sizeInBytes=3D0 > IW 0 [Indexer]: startCommit index=3D_0:C171638->_0 _1:C204995->_0 > _2:C168236->_0 _3:C146894->_0 _4:C162034->_0 _5:C146250->_0 _6:C76978->_0 > changeCount=3D21 > IW 0 [Indexer]: now sync _0.tis > IW 0 [Indexer]: now sync _5.prx > IW 0 [Indexer]: now sync _3.frq > IW 0 [Indexer]: now sync _3.tii > IW 0 [Indexer]: now sync _1.frq > IW 0 [Indexer]: now sync _6.frq > IW 0 [Indexer]: now sync _4.prx > IW 0 [Indexer]: now sync _4.fnm > IW 0 [Indexer]: now sync _2.tii > IW 0 [Indexer]: now sync _3.fnm > IW 0 [Indexer]: now sync _1.fnm > IW 0 [Indexer]: now sync _6.tis > IW 0 [Indexer]: now sync _4.frq > IW 0 [Indexer]: now sync _5.nrm > IW 0 [Indexer]: now sync _5.tis > IW 0 [Indexer]: now sync _1.tii > IW 0 [Indexer]: now sync _4.tis > IW 0 [Indexer]: now sync _0.prx > IW 0 [Indexer]: now sync _3.nrm > IW 0 [Indexer]: now sync _4.tii > IW 0 [Indexer]: now sync _0.nrm > IW 0 [Indexer]: now sync _5.fnm > IW 0 [Indexer]: now sync _1.tis > IW 0 [Indexer]: now sync _0.fnm > IW 0 [Indexer]: now sync _2.prx > IW 0 [Indexer]: now sync _6.tii > IW 0 [Indexer]: now sync _4.nrm > IW 0 [Indexer]: now sync _2.frq > IW 0 [Indexer]: now sync _5.frq > IW 0 [Indexer]: now sync _3.prx > IW 0 [Indexer]: now sync _5.tii > IW 0 [Indexer]: now sync _2.fnm > IW 0 [Indexer]: now sync _1.prx > IW 0 [Indexer]: now sync _2.tis > IW 0 [Indexer]: now sync _0.tii > IW 0 [Indexer]: now sync _6.prx > IW 0 [Indexer]: now sync _0.frq > IW 0 [Indexer]: now sync _6.fnm > IW 0 [Indexer]: now sync _0.fdx > IW 0 [Indexer]: now sync _6.nrm > IW 0 [Indexer]: now sync _0.fdt > IW 0 [Indexer]: now sync _1.nrm > IW 0 [Indexer]: now sync _2.nrm > IW 0 [Indexer]: now sync _3.tis > IW 0 [Indexer]: done all syncs > IW 0 [Indexer]: commit: pendingCommit !=3D null > IW 0 [Indexer]: commit: wrote segments file "segments_2" > IFD [Indexer]: now checkpoint "segments_2" [7 segments ; isCommit =3D tru= e] > IFD [Indexer]: deleteCommits: now decRef commit "segments_1" > IFD [Indexer]: delete "segments_1" > IW 0 [Indexer]: commit: done > IW 0 [Indexer]: optimize: index now _0:C171638->_0 _1:C204995->_0 > _2:C168236->_0 _3:C146894->_0 _4:C162034->_0 _5:C146250->_0 _6:C76978->_0 > IW 0 [Indexer]: =A0 flush: segment=3Dnull docStoreSegment=3D_6 docStoreOf= fset=3D0 > flushDocs=3Dfalse flushDeletes=3Dtrue flushDocStores=3Dfalse numDocs=3D0 > numBufDelTerms=3D0 > IW 0 [Indexer]: =A0 index before flush _0:C171638->_0 _1:C204995->_0 > _2:C168236->_0 _3:C146894->_0 _4:C162034->_0 _5:C146250->_0 _6:C76978->_0 > IW 0 [Indexer]: add merge to pendingMerges: _0:C171638->_0 _1:C204995->_0 > _2:C168236->_0 _3:C146894->_0 _4:C162034->_0 _5:C146250->_0 _6:C76978->_0 > [optimize] [total 1 pending] > IW 0 [Indexer]: CMS: now merge > IW 0 [Indexer]: CMS: =A0 index: _0:C171638->_0 _1:C204995->_0 _2:C168236-= >_0 > _3:C146894->_0 _4:C162034->_0 _5:C146250->_0 _6:C76978->_0 > IW 0 [Indexer]: CMS: =A0 consider merge _0:C171638->_0 _1:C204995->_0 > _2:C168236->_0 _3:C146894->_0 _4:C162034->_0 _5:C146250->_0 _6:C76978->_0 > into _7 [optimize] > IW 0 [Indexer]: CMS: =A0 =A0 launch new thread [Lucene Merge Thread #0] > IW 0 [Indexer]: CMS: =A0 no more merges pending; now return > IW 0 [Lucene Merge Thread #0]: CMS: =A0 merge thread: start > IW 0 [Lucene Merge Thread #0]: now merge > =A0merge=3D_0:C171638->_0 _1:C204995->_0 _2:C168236->_0 _3:C146894->_0 > _4:C162034->_0 _5:C146250->_0 _6:C76978->_0 into _7 [optimize] > =A0merge=3Dorg.apache.lucene.index.MergePolicy$OneMerge@78688954 > =A0index=3D_0:C171638->_0 _1:C204995->_0 _2:C168236->_0 _3:C146894->_0 > _4:C162034->_0 _5:C146250->_0 _6:C76978->_0 > IW 0 [Lucene Merge Thread #0]: merging _0:C171638->_0 _1:C204995->_0 > _2:C168236->_0 _3:C146894->_0 _4:C162034->_0 _5:C146250->_0 _6:C76978->_0 > into _7 [optimize] > IW 0 [Lucene Merge Thread #0]: merge: total 1077025 docs > IW 0 [Lucene Merge Thread #0]: commitMerge: _0:C171638->_0 _1:C204995->_0 > _2:C168236->_0 _3:C146894->_0 _4:C162034->_0 _5:C146250->_0 _6:C76978->_0 > into _7 [optimize] index=3D_0:C171638->_0 _1:C204995->_0 _2:C168236->_0 > _3:C146894->_0 _4:C162034->_0 _5:C146250->_0 _6:C76978->_0 > IW 0 [Lucene Merge Thread #0]: commitMergeDeletes _0:C171638->_0 > _1:C204995->_0 _2:C168236->_0 _3:C146894->_0 _4:C162034->_0 _5:C146250->_= 0 > _6:C76978->_0 into _7 [optimize] > IFD [Lucene Merge Thread #0]: now checkpoint "segments_2" [1 segments ; > isCommit =3D false] > IW 0 [Lucene Merge Thread #0]: CMS: =A0 merge thread: done > IW 0 [Indexer]: now flush at close > IW 0 [Indexer]: =A0 flush: segment=3Dnull docStoreSegment=3D_6 docStoreOf= fset=3D0 > flushDocs=3Dfalse flushDeletes=3Dtrue flushDocStores=3Dtrue numDocs=3D0 > numBufDelTerms=3D0 > IW 0 [Indexer]: =A0 index before flush _7:C1077025->_0 > IW 0 [Indexer]: =A0 flush shared docStore segment _6 > IW 0 [Indexer]: DW: closeDocStore: 0 files to flush to segment _6 numDocs= =3D0 > IW 0 [Indexer]: CMS: now merge > IW 0 [Indexer]: CMS: =A0 index: _7:C1077025->_0 > IW 0 [Indexer]: CMS: =A0 no more merges pending; now return > IW 0 [Indexer]: now call final commit() > IW 0 [Indexer]: startCommit(): start sizeInBytes=3D0 > IW 0 [Indexer]: startCommit index=3D_7:C1077025->_0 changeCount=3D23 > IW 0 [Indexer]: now sync _7.prx > IW 0 [Indexer]: now sync _7.fnm > IW 0 [Indexer]: now sync _7.tis > IW 0 [Indexer]: now sync _7.nrm > IW 0 [Indexer]: now sync _7.tii > IW 0 [Indexer]: now sync _7.frq > IW 0 [Indexer]: done all syncs > IW 0 [Indexer]: commit: pendingCommit !=3D null > IW 0 [Indexer]: commit: wrote segments file "segments_3" > IFD [Indexer]: now checkpoint "segments_3" [1 segments ; isCommit =3D tru= e] > IFD [Indexer]: deleteCommits: now decRef commit "segments_2" > IFD [Indexer]: delete "_0.tis" > IFD [Indexer]: delete "_5.prx" > IFD [Indexer]: delete "_3.tii" > IFD [Indexer]: delete "_3.frq" > IFD [Indexer]: delete "_1.frq" > IFD [Indexer]: delete "_6.frq" > IFD [Indexer]: delete "_4.prx" > IFD [Indexer]: delete "_4.fnm" > IFD [Indexer]: delete "_2.tii" > IFD [Indexer]: delete "_3.fnm" > IFD [Indexer]: delete "_1.fnm" > IFD [Indexer]: delete "_6.tis" > IFD [Indexer]: delete "_4.frq" > IFD [Indexer]: delete "_5.nrm" > IFD [Indexer]: delete "_5.tis" > IFD [Indexer]: delete "_1.tii" > IFD [Indexer]: delete "_4.tis" > IFD [Indexer]: delete "_0.prx" > IFD [Indexer]: delete "_3.nrm" > IFD [Indexer]: delete "_4.tii" > IFD [Indexer]: delete "_0.nrm" > IFD [Indexer]: delete "_5.fnm" > IFD [Indexer]: delete "_1.tis" > IFD [Indexer]: delete "_0.fnm" > IFD [Indexer]: delete "_2.prx" > IFD [Indexer]: delete "_6.tii" > IFD [Indexer]: delete "_4.nrm" > IFD [Indexer]: delete "_2.frq" > IFD [Indexer]: delete "_5.frq" > IFD [Indexer]: delete "_3.prx" > IFD [Indexer]: delete "_5.tii" > IFD [Indexer]: delete "_2.fnm" > IFD [Indexer]: delete "_1.prx" > IFD [Indexer]: delete "_2.tis" > IFD [Indexer]: delete "_0.tii" > IFD [Indexer]: delete "_6.prx" > IFD [Indexer]: delete "_0.frq" > IFD [Indexer]: delete "segments_2" > IFD [Indexer]: delete "_6.fnm" > IFD [Indexer]: delete "_6.nrm" > IFD [Indexer]: delete "_1.nrm" > IFD [Indexer]: delete "_2.nrm" > IFD [Indexer]: delete "_3.tis" > IW 0 [Indexer]: commit: done > IW 0 [Indexer]: at close: _7:C1077025->_0 > > I see no errors. > Peter > > > On Tue, Oct 27, 2009 at 10:44 AM, Peter Keegan wr= ote: > >> >> >> On Tue, Oct 27, 2009 at 10:37 AM, Michael McCandless < >> lucene@mikemccandless.com> wrote: >> >>> OK that exception looks more reasonable, for a disk full event. >>> >>> But, I can't tell from your followon emails: did this lead to index >>> corruption? >>> >> >> Yes, but this may be caused by the application ignoring a Lucene excepti= on >> somewhere else. I will chase this down. >> >>> >>> Also, I noticed you're using a rather old 1.6.0 JRE (1.6.0_03) -- you >>> really should upgrade that to the latest 1.6.0 -- there's at least one >>> known problem with Lucene and early 1.6.0 JREs. >>> >> >> Yes, I remember this problem - that's why we stayed at _03 >> Thanks. >> >>> >>> Mike >>> >>> On Tue, Oct 27, 2009 at 10:00 AM, Peter Keegan >>> wrote: >>> > After rebuilding the corrupted indexes, the low disk space exception = is >>> now >>> > occurring as expected. Sorry for the distraction. >>> > >>> > fyi, here are the details: >>> > >>> > =A0java.io.IOException: There is not enough space on the disk >>> > =A0 =A0at java.io.RandomAccessFile.writeBytes(Native Method) >>> > =A0 =A0at java.io.RandomAccessFile.write(Unknown Source) >>> > =A0 =A0at >>> > >>> org.apache.lucene.store.SimpleFSDirectory$SimpleFSIndexOutput.flushBuff= er(SimpleFSDirectory.java:192) >>> > =A0 =A0at >>> > >>> org.apache.lucene.store.BufferedIndexOutput.flushBuffer(BufferedIndexOu= tput.java:96) >>> > =A0 =A0at >>> > >>> org.apache.lucene.store.BufferedIndexOutput.flush(BufferedIndexOutput.j= ava:85) >>> > =A0 =A0at >>> > >>> org.apache.lucene.store.BufferedIndexOutput.close(BufferedIndexOutput.j= ava:109) >>> > =A0 =A0at >>> > >>> org.apache.lucene.store.SimpleFSDirectory$SimpleFSIndexOutput.close(Sim= pleFSDirectory.java:199) >>> > =A0 =A0at org.apache.lucene.index.FieldsWriter.close(FieldsWriter.jav= a:144) >>> > =A0 =A0at >>> > >>> org.apache.lucene.index.SegmentMerger.mergeFields(SegmentMerger.java:35= 7) >>> > =A0 =A0at >>> org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:153) >>> > =A0 =A0at >>> > org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:5011= ) >>> > =A0 =A0at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:= 4596) >>> > =A0 =A0at >>> > >>> org.apache.lucene.index.IndexWriter.resolveExternalSegments(IndexWriter= .java:3786) >>> > =A0 =A0at >>> > >>> org.apache.lucene.index.IndexWriter.addIndexesNoOptimize(IndexWriter.ja= va:3695) >>> > >>> > >>> > And the corresponding index info log: >>> > >>> > IFD [Indexer]: setInfoStream >>> > >>> deletionPolicy=3Dorg.apache.lucene.index.KeepOnlyLastCommitDeletionPoli= cy@256ef705 >>> > IW 1 [Indexer]: setInfoStream: >>> > dir=3Dorg.apache.lucene.store.SimpleFSDirectory@D >>> :\mnsavs\lresumes3\lresumes3.luc\lresumes3.update.main.4 >>> > autoCommit=3Dfalse >>> > >>> mergePolicy=3Dorg.apache.lucene.index.LogByteSizeMergePolicy@181b7c76me= rgeScheduler >>> =3Dorg.apache.lucene.index.ConcurrentMergeScheduler@34883357ramBufferSi= zeMB >>> =3D16.0 >>> > maxBufferedDocs=3D-1 maxBuffereDeleteTerms=3D-1 >>> > maxFieldLength=3D2147483647 index=3D >>> > IW 1 [Indexer]: flush at addIndexesNoOptimize >>> > IW 1 [Indexer]: =A0 flush: segment=3Dnull docStoreSegment=3Dnull >>> docStoreOffset=3D0 >>> > flushDocs=3Dfalse flushDeletes=3Dtrue flushDocStores=3Dfalse numDocs= =3D0 >>> > numBufDelTerms=3D0 >>> > IW 1 [Indexer]: =A0 index before flush >>> > IW 1 [Indexer]: now start transaction >>> > IW 1 [Indexer]: LMP: findMerges: 2 segments >>> > IW 1 [Indexer]: LMP: =A0 level 8.774518 to 9.524518: 1 segments >>> > IW 1 [Indexer]: LMP: =A0 level 6.2973914 to 7.0473914: 1 segments >>> > IW 1 [Indexer]: CMS: now merge >>> > IW 1 [Indexer]: CMS: =A0 index: _7:Cx1075533->_0** _8:Cx2795** >>> > IW 1 [Indexer]: CMS: =A0 no more merges pending; now return >>> > IW 1 [Indexer]: add merge to pendingMerges: _7:Cx1075533->_0 [total 1 >>> > pending] >>> > IW 1 [Indexer]: now merge >>> > =A0merge=3D_7:Cx1075533->_0 into _0 [mergeDocStores] >>> > =A0merge=3Dorg.apache.lucene.index.MergePolicy$OneMerge@4d480ea >>> > =A0index=3D_7:Cx1075533->_0** _8:Cx2795** >>> > IW 1 [Indexer]: merging _7:Cx1075533->_0 into _0 [mergeDocStores] >>> > IW 1 [Indexer]: merge: total 1074388 docs >>> > IW 1 [Indexer]: commitMerge: _7:Cx1075533->_0 into _0 [mergeDocStores= ] >>> > index=3D_7:Cx1075533->_0** _8:Cx2795** >>> > IW 1 [Indexer]: commitMergeDeletes _7:Cx1075533->_0 into _0 >>> [mergeDocStores] >>> > IFD [Indexer]: now checkpoint "segments_1" [2 segments ; isCommit =3D >>> false] >>> > IW 1 [Indexer]: LMP: findMerges: 2 segments >>> > IW 1 [Indexer]: LMP: =A0 level 8.864886 to 9.614886: 1 segments >>> > IW 1 [Indexer]: LMP: =A0 level 6.2973914 to 7.0473914: 1 segments >>> > IW 1 [Indexer]: add merge to pendingMerges: _8:Cx2795 [total 1 pendin= g] >>> > IW 1 [Indexer]: now merge >>> > =A0merge=3D_8:Cx2795 into _1 [mergeDocStores] >>> > =A0merge=3Dorg.apache.lucene.index.MergePolicy$OneMerge@606f8b2b >>> > =A0index=3D_0:C1074388 _8:Cx2795** >>> > IW 1 [Indexer]: merging _8:Cx2795 into _1 [mergeDocStores] >>> > IW 1 [Indexer]: merge: total 2795 docs >>> > IW 1 [Indexer]: handleMergeException: merge=3D_8:Cx2795 into _1 >>> > [mergeDocStores] exc=3Djava.io.IOException: There is not enough space= on >>> the >>> > disk >>> > IW 1 [Indexer]: hit exception during merge >>> > IFD [Indexer]: refresh [prefix=3D_1]: removing newly created unrefere= nced >>> file >>> > "_1.fdt" >>> > IFD [Indexer]: delete "_1.fdt" >>> > IFD [Indexer]: refresh [prefix=3D_1]: removing newly created unrefere= nced >>> file >>> > "_1.fdx" >>> > IFD [Indexer]: delete "_1.fdx" >>> > IFD [Indexer]: refresh [prefix=3D_1]: removing newly created unrefere= nced >>> file >>> > "_1.fnm" >>> > IFD [Indexer]: delete "_1.fnm" >>> > IW 1 [Indexer]: now rollback transaction >>> > IW 1 [Indexer]: all running merges have aborted >>> > IFD [Indexer]: now checkpoint "segments_1" [0 segments ; isCommit =3D >>> false] >>> > IFD [Indexer]: delete "_0.nrm" >>> > IFD [Indexer]: delete "_0.tis" >>> > IFD [Indexer]: delete "_0.fnm" >>> > IFD [Indexer]: delete "_0.tii" >>> > IFD [Indexer]: delete "_0.frq" >>> > IFD [Indexer]: delete "_0.fdx" >>> > IFD [Indexer]: delete "_0.prx" >>> > IFD [Indexer]: delete "_0.fdt" >>> > >>> > >>> > Peter >>> > >>> > On Mon, Oct 26, 2009 at 3:59 PM, Peter Keegan >> >wrote: >>> > >>> >> >>> >> >>> >> On Mon, Oct 26, 2009 at 3:00 PM, Michael McCandless < >>> >> lucene@mikemccandless.com> wrote: >>> >> >>> >>> On Mon, Oct 26, 2009 at 2:55 PM, Peter Keegan >> > >>> >>> wrote: >>> >>> > On Mon, Oct 26, 2009 at 2:50 PM, Michael McCandless < >>> >>> > lucene@mikemccandless.com> wrote: >>> >>> > >>> >>> >> On Mon, Oct 26, 2009 at 10:44 AM, Peter Keegan < >>> peterlkeegan@gmail.com >>> >>> > >>> >>> >> wrote: >>> >>> >> > Even running in console mode, the exception is difficult to >>> >>> interpret. >>> >>> >> > Here's an exception that I think occurred during an add docume= nt, >>> >>> commit >>> >>> >> or >>> >>> >> > close: >>> >>> >> > doc counts differ for segment _g: field Reader shows 137 but >>> >>> segmentInfo >>> >>> >> > shows 5777 >>> >>> >> >>> >>> >> That's spooky. =A0Do you have the full exception for this one? = =A0What >>> IO >>> >>> >> system are you running on? =A0(Is it just a local drive on your >>> windows >>> >>> >> computer?) It's almost as if the IO system is not generating an >>> >>> >> IOException to Java when disk fills up. >>> >>> >> >>> >>> > >>> >>> > Index and code are all on a local drive. There is no other except= ion >>> >>> coming >>> >>> > back - just what I reported. >>> >>> >>> >>> But, you didn't report a traceback for this first one? >>> >>> >>> >> >>> >> Yes, I need to add some more printStackTrace calls. >>> >> >>> >> >>> >>> >>> >>> >> > I ensured that the disk space was low before updating the inde= x. >>> >>> >> >>> >>> >> You mean, to intentionally test the disk-full case? >>> >>> >> >>> >>> > >>> >>> > Yes, that's right. >>> >>> >>> >>> OK. =A0Can you turn on IndexWriter's infoStream, get this disk full= / >>> >>> corruption to happen again, and post back the resulting output? =A0= Make >>> >>> sure your index first passes CheckIndex before starting (so we don'= t >>> >>> begin the test w/ any pre-existing index corruption). >>> >>> >>> >> >>> >> Good point about CheckIndex. =A0I've already found 2 bad ones. I wil= l >>> build >>> >> new indexes from scratch. This will take a while. >>> >> >>> >> >>> >>> >> > On another occasion, the exception was: >>> >>> >> > background merge hit exception: _0:C1080260 _1:C139 _2:C123 >>> _3:C107 >>> >>> >> _4:C126 >>> >>> >> > _5:C121 _6:C126 _7:C711 _8:C116 into _9 [optimize] >>> [mergeDocStores] >>> >>> >> >>> >>> >> In this case, the SegmentMerger was trying to open this segment, >>> but >>> >>> >> on attempting to read the first int from the fdx (fields index) >>> file >>> >>> >> for one of the segments, it hit EOF. >>> >>> >> >>> >>> >> This is also spooky -- this looks like index corruption, which >>> should >>> >>> >> never happen on hitting disk full. >>> >>> >> >>> >>> > >>> >>> > That's what I thought, too. Could Lucene be catching the IOExcept= ion >>> and >>> >>> > turning it into a different exception? >>> >>> >>> >>> I think that's unlikely, but I guess possible. =A0We have "disk ful= l" >>> >>> tests in the unit tests, that throw an IOException at different tim= es. >>> >>> >>> >>> What exact windows version are you using? =A0The local drive is NTF= S? >>> >>> >>> >> >>> >> Windows Server 2003 Enterprise x64 SP2. Local drive is NTFS >>> >> >>> >> >>> >>> >>> >>> Mike >>> >>> >>> >>> -------------------------------------------------------------------= -- >>> >>> To unsubscribe, e-mail: java-user-unsubscribe@lucene.apache.org >>> >>> For additional commands, e-mail: java-user-help@lucene.apache.org >>> >>> >>> >>> >>> >> >>> > >>> >>> --------------------------------------------------------------------- >>> To unsubscribe, e-mail: java-user-unsubscribe@lucene.apache.org >>> For additional commands, e-mail: java-user-help@lucene.apache.org >>> >>> >> > --------------------------------------------------------------------- To unsubscribe, e-mail: java-user-unsubscribe@lucene.apache.org For additional commands, e-mail: java-user-help@lucene.apache.org