Operating system is Solaris. Directory is a NAS. Directory implementation is SimpleFSDirectory. I sent you the full log.
Thanks, Tim On Thu, Mar 15, 2012 at 4:04 PM, Michael McCandless < luc...@mikemccandless.com> wrote: > Hmm, which OS/filesystem is the index on? Which Directory impl are > you using...? > > Indeed CheckIndex sees the 5111 segments, so something seems amiss. > > The log was edited right? EG I can't see the IW open log entries... > and IW 51 is missing (it goes straight from 50 to 52). Can you post > the full log? Also, can you attach it (instead of inlining it), maybe > gzip'd, so it doesn't get line-wrapped? > > Finally, can you run things a big longer, so we can see the > pathological behavior emerge? > > The only odd thing I see in the log is that IW seems to be attempting > to delete files (eg _1a.cfs) that are still "live", which is odd. > > That the delete did not succeed could just be that the file is open > from a reader (do you have a reader open on the index?)... though, I > would have expected to see "unable to remove file..." in the > InfoStream output. > > Mike McCandless > > http://blog.mikemccandless.com > > > On Thu, Mar 15, 2012 at 10:30 AM, Tim Bogaert <boggu...@gmail.com> wrote: > > Hi Mike, > > > > Segment format: FORMAT_3_1 [Lucene 3.1+] > > NumBadSegments: 0 > > NumSegments: 5111 > > Clean?: true > > TotLoseDocCount: 0 > > Partial: false > > > > > > I reindexed and let the feed come in again...The logs of the result are > > below (I just copied a few) after 10 minutes : > > Segment format: FORMAT_3_1 [Lucene 3.1+] > > NumBadSegments: 0 > > NumSegments: 11 > > Clean?: true > > TotLoseDocCount: 0 > > Partial: false > > > > What I noticed in the log was that _1a.cfs is getting deleted, but it > seems > > to be still in the directory : > > > > ls -al > > -rw-r--r-- 1 web web 1444172 Mar 15 15:13 _17.fdt > > -rw-r--r-- 1 web web 88804 Mar 15 15:13 _17.fdx > > -rw-r--r-- 1 web web 142 Mar 15 15:13 _17.fnm > > -rw-r--r-- 1 web web 4352933 Mar 15 15:13 _17.frq > > -rw-r--r-- 1 web web 177604 Mar 15 15:13 _17.nrm > > -rw-r--r-- 1 web web 5931105 Mar 15 15:13 _17.prx > > -rw-r--r-- 1 web web 18159 Mar 15 15:13 _17.tii > > -rw-r--r-- 1 web web 1421338 Mar 15 15:13 _17.tis > > -rw-r--r-- 1 web web 36 Mar 15 15:14 _17_1.del > > -rw-r--r-- 1 web web 379400 Mar 15 15:13 _18.cfs > > -rw-r--r-- 1 web web 424376 Mar 15 15:13 _19.cfs > > -rw-r--r-- 1 web web 463177 Mar 15 15:13 _1a.cfs > > -rw-r--r-- 1 web web 108875 Mar 15 15:13 _1b.cfs > > -rw-r--r-- 1 web web 4481 Mar 15 15:14 _1c.cfs > > -rw-r--r-- 1 web web 4465 Mar 15 15:15 _1d.cfs > > -rw-r--r-- 1 web web 4534 Mar 15 15:17 _1e.cfs > > -rw-r--r-- 1 web web 3252 Mar 15 15:18 _1f.cfs > > -rw-r--r-- 1 web web 3314 Mar 15 15:21 _1g.cfs > > -rw-r--r-- 1 web web 2340 Mar 15 15:25 _1h.cfs > > -rw-r--r-- 1 web web 3902 Mar 15 15:27 _1i.cfs > > -rw-r--r-- 1 web web 1687 Mar 15 15:28 _1j.cfs > > -rw-r--r-- 1 web web 20 Mar 15 15:28 segments.gen > > -rw-r--r-- 1 web web 2735 Mar 15 15:28 segments_1h > > > > > > Here is (part of) the log : > > > > 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #2]: TMP: > > seg=_h(3.5):c1 size=0.007 MB [merging] [floored] > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #2]: TMP: > > seg=_b(3.5):c1 size=0.007 MB [merging] [floored] > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #2]: TMP: > > seg=_g(3.5):c1 size=0.006 MB [merging] [floored] > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #2]: TMP: > > seg=_c(3.5):c1 size=0.006 MB [merging] [floored] > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #2]: TMP: > > seg=_11(3.5):c1 size=0.005 MB [merging] [floored] > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #2]: TMP: > > seg=_12(3.5):c1 size=0.005 MB [merging] [floored] > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #2]: TMP: > > seg=_6(3.5):c1 size=0.005 MB [merging] [floored] > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #2]: TMP: > > allowedSegmentCount=1 vs count=15 (eligible count=5) tooBigCount=0 > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #2]: merge time > 46 > > msec for 10 docs > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: now flush at close > > waitForMerges=true > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #2]: CMS: > merge > > thread: done > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: now trigger flush > > reason=explicit flush > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #2]: CMS: set > > priority of merge thread Lucene Merge Thread #3 to 6 > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: start flush: > > applyAllDeletes=true > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: index before > flush > > _0(3.5):C73 _1(3.5):C70 _2(3.5):C23 _3(3.5):c7 _16(3.5):c10 _6(3.5):c1 > > _18(3.5):c10 _17(3.5):c10 _b(3.5):c1 _c(3.5):c1 _d(3.5):c1 _g(3.5):c1 > > _h(3.5):c1 _11(3.5):c1 _12(3.5):c1 > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: DW: flush: no > docs; > > skipping > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: apply all deletes > > during flush > > BD 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: applyDeletes: no > > deletes; skipping > > BD 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: prune > > sis=org.apache.lucene.index.SegmentInfos@1cad1e6 minGen=0 packetCount=0 > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: clearFlushPending > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: CMS: now merge > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: CMS: index: > > _0(3.5):C73 _1(3.5):C70 _2(3.5):C23 _3(3.5):c7 _16(3.5):c10 _6(3.5):c1 > > _18(3.5):c10 _17(3.5):c10 _b(3.5):c1 _c(3.5):c1 _d(3.5):c1 _g(3.5):c1 > > _h(3.5):c1 _11(3.5):c1 _12(3.5):c1 > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: CMS: no more > > merges pending; now return > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: waitForMerges > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #3]: merge store > > matchedCount=10 vs 10 > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #3]: merged > > segment size=0.076 MB vs estimate=0.103 MB > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #3]: > commitMerge: > > _2(3.5):C23 _3(3.5):c7 _d(3.5):c1 _h(3.5):c1 _b(3.5):c1 _g(3.5):c1 > > _c(3.5):c1 _11(3.5):c1 _12(3.5):c1 _6(3.5):c1 into _19 index=_0(3.5):C73 > > _1(3.5):C70 _2(3.5):C23 _3(3.5):c7 _16(3.5):c10 _6(3.5):c1 _18(3.5):c10 > > _17(3.5):c10 _b(3.5):c1 _c(3.5):c1 _d(3.5):c1 _g(3.5):c1 _h(3.5):c1 > > _11(3.5):c1 _12(3.5):c1 > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #3]: > > commitMergeDeletes _2(3.5):C23 _3(3.5):c7 _d(3.5):c1 _h(3.5):c1 > _b(3.5):c1 > > _g(3.5):c1 _c(3.5):c1 _11(3.5):c1 _12(3.5):c1 _6(3.5):c1 into _19 > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #3]: after > commit: > > _0(3.5):C73 _1(3.5):C70 _19(3.5):C38 _16(3.5):c10 _18(3.5):c10 > _17(3.5):c10 > > IFD [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #3]: now > checkpoint > > "segments_15" [6 segments ; isCommit = false] > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #3]: merge time > 61 > > msec for 38 docs > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: waitForMerges done > > IW 50 [Thu Mar 15 15:25:23 MET 2012; Lucene Merge Thread #3]: CMS: > merge > > thread: done > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: now call final > > commit() > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: commit: start > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: commit: enter lock > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: commit: already > > prepared > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: commit: > > pendingCommit != null > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: commit: wrote > > segments file "segments_16" > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: now checkpoint > > "segments_16" [42 segments ; isCommit = true] > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: deleteCommits: now > > decRef commit "segments_15" > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: delete "segments_15" > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: commit: done > > IW 50 [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: at close: > > _0(3.5):C73 _1(3.5):C70 _19(3.5):C38 _16(3.5):c10 _18(3.5):c10 > _17(3.5):c10 > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: delete "_19.tii" > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: delete "_19.tis" > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: delete "_18.cfs" > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: delete "_19.nrm" > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: delete "_19.fnm" > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: delete "_19.fdt" > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: delete "_17.cfs" > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: delete "_19.prx" > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: delete "_16.cfs" > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: delete "_19.fdx" > > IFD [Thu Mar 15 15:25:23 MET 2012; pool-2-thread-1]: delete "_19.frq" > > Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: applyDeletes: no deletes; > > skipping > > BD 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: prune > > sis=org.apache.lucene.index.SegmentInfos@59d9fe minGen=0 packetCount=0 > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: clearFlushPending > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: CMS: now merge > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: CMS: index: > > _0(3.5):C73 _1(3.5):C70 _2(3.5):C23 _1a(3.5):C16 _17(3.5):c10 > _19(3.5):c10 > > _18(3.5):c10 > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: CMS: no more > > merges pending; now return > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: waitForMerges > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: waitForMerges done > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: now call final > > commit() > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: commit: start > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: commit: enter lock > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: commit: already > > prepared > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: commit: > > pendingCommit != null > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: commit: wrote > > segments file "segments_17" > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: now checkpoint > > "segments_17" [43 segments ; isCommit = true] > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: deleteCommits: now > > decRef commit "segments_16" > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: delete "segments_16" > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: commit: done > > IW 52 [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: at close: > > _0(3.5):C73 _1(3.5):C70 _2(3.5):C23 _1a(3.5):C16 _17(3.5):c10 > _19(3.5):c10 > > _18(3.5):c10 > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: delete "_1a.fdx" > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: delete "_1a.tis" > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: delete "_1a.frq" > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: delete "_1a.tii" > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: delete "_1a.fnm" > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: delete "_1a.fdt" > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: delete "_18.cfs" > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: delete "_1a.nrm" > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: delete "_19.cfs" > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: delete "_17.cfs" > > IFD [Thu Mar 15 15:25:27 MET 2012; pool-2-thread-1]: delete "_1a.prx" > > > > IW 53 [Thu Mar 15 15:25:38 MET 2012; Lucene Merge Thread #3]: CMS: > merge > > thread: done > > IW 53 [Thu Mar 15 15:25:38 MET 2012; Lucene Merge Thread #0]: CMS: set > > priority of merge thread Lucene Merge Thread #3 to 6 > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: now flush at close > > waitForMerges=true > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: now trigger flush > > reason=explicit flush > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: start flush: > > applyAllDeletes=true > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: index before > flush > > _0(3.5):C73 _1(3.5):C70 _2(3.5):C23 _3(3.5):c7 _18(3.5):c10 _1b(3.5):c10 > > _1a(3.5):c10 _19(3.5):c10 > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: DW: flush: no > docs; > > skipping > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: apply all deletes > > during flush > > BD 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: applyDeletes: no > > deletes; skipping > > BD 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: prune > > sis=org.apache.lucene.index.SegmentInfos@e91b11 minGen=0 packetCount=0 > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: clearFlushPending > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: CMS: now merge > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: CMS: index: > > _0(3.5):C73 _1(3.5):C70 _2(3.5):C23 _3(3.5):c7 _18(3.5):c10 _1b(3.5):c10 > > _1a(3.5):c10 _19(3.5):c10 > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: CMS: no more > > merges pending; now return > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: waitForMerges > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: waitForMerges done > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: now call final > > commit() > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: commit: start > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: commit: enter lock > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: commit: already > > prepared > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: commit: > > pendingCommit != null > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: commit: wrote > > segments file "segments_18" > > IFD [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: now checkpoint > > "segments_18" [44 segments ; isCommit = true] > > IFD [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: deleteCommits: now > > decRef commit "segments_17" > > IFD [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: delete "segments_17" > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: commit: done > > IW 53 [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: at close: > > _0(3.5):C73 _1(3.5):C70 _2(3.5):C23 _3(3.5):c7 _18(3.5):c10 _1b(3.5):c10 > > _1a(3.5):c10 _19(3.5):c10 > > IFD [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: delete "_1b.cfs" > > IFD [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: delete "_18.cfs" > > IFD [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: delete "_19.cfs" > > IFD [Thu Mar 15 15:25:38 MET 2012; pool-2-thread-1]: delete "_1a.cfs" > > > > Kind regards, > > Bogguard > > > > On Thu, Mar 15, 2012 at 1:21 PM, Michael McCandless < > > luc...@mikemccandless.com> wrote: > > > >> Hmm, that's odd... > >> > >> Can you set IndexWriter's infoStream and then capture the output while > >> doing the small writes every few seconds and post back? > >> > >> If you run CheckIndex on the index does it also report ~3000 segments? > >> > >> Mike McCandless > >> > >> http://blog.mikemccandless.com > >> > >> On Thu, Mar 15, 2012 at 7:14 AM, Tim Bogaert <boggu...@gmail.com> > wrote: > >> > Hi, > >> > > >> > We migrated our project to Lucene 3.5 and used the TieredMergePolicy > with > >> > all its defaults. > >> > Our project contains a relatively small index (+-90MB) and gets small > >> > writes every few seconds. > >> > The behaviour we see is that when we reindex everything works great > and > >> > performant, > >> > but when we keep the index running for some days we see a lot > (+-3000) of > >> > very small .cfs files (between 1KB and 10KB) are being generated and > the > >> > performance drops significantly. > >> > Reïndexing solves the problem, but this shouldn't be the solution. > >> > > >> > Is there a way to change the behaviour of the .cfs files. I noticed > you > >> can > >> > fully disable it, but I read that this isn't adviced. > >> > > >> > Kind regards, > >> > Bogguard > >> > >> --------------------------------------------------------------------- > >> To unsubscribe, e-mail: java-user-unsubscr...@lucene.apache.org > >> For additional commands, e-mail: java-user-h...@lucene.apache.org > >> > >> > > --------------------------------------------------------------------- > To unsubscribe, e-mail: java-user-unsubscr...@lucene.apache.org > For additional commands, e-mail: java-user-h...@lucene.apache.org > >
