Return-Path: Delivered-To: apmail-lucene-java-dev-archive@www.apache.org Received: (qmail 22969 invoked from network); 2 Aug 2009 18:52:14 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.3) by minotaur.apache.org with SMTP; 2 Aug 2009 18:52:14 -0000 Received: (qmail 82669 invoked by uid 500); 2 Aug 2009 18:52:18 -0000 Delivered-To: apmail-lucene-java-dev-archive@lucene.apache.org Received: (qmail 82604 invoked by uid 500); 2 Aug 2009 18:52:18 -0000 Mailing-List: contact java-dev-help@lucene.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: java-dev@lucene.apache.org Delivered-To: mailing list java-dev@lucene.apache.org Received: (qmail 82596 invoked by uid 99); 2 Aug 2009 18:52:18 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 02 Aug 2009 18:52:18 +0000 X-ASF-Spam-Status: No, hits=2.2 required=10.0 tests=HTML_MESSAGE,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of serera@gmail.com designates 209.85.219.226 as permitted sender) Received: from [209.85.219.226] (HELO mail-ew0-f226.google.com) (209.85.219.226) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 02 Aug 2009 18:52:10 +0000 Received: by ewy26 with SMTP id 26so3599413ewy.5 for ; Sun, 02 Aug 2009 11:51:48 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:mime-version:received:in-reply-to:references :date:message-id:subject:from:to:content-type; bh=nIQsYQqD9WlygdsaUd29O5/p2WcFKEneMlYjqzMIzKA=; b=VVzu0vnWsXYYEzNjom/I2CNwP31waYP/PEi8sVOGsAmNObUrD74sUuMKjEx+nZCQ8G fAJPxcyv1SN3xx1ffKomXlRu/m6YfzbrhzyxS5qvURyhXWrTHnQg1hZC3sc1+rWi6fsP EbRRr3ssOZpw8l9kFGq0LVZuCnyh+zN20dDxQ= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :content-type; b=aSq1PWyf1cOTnl1+RIG0qjGSsnZsvDwuONytqiyd4LTbrhs4yRAnFZKTxJSUE44DwB H0OOZV+KdY06ot2FVbcP5kvL3u/kTB9BXdGnkQgrAByjcSyWIlLSvdUlViRsRvnxTwRI CWhfgdbftnejIm8MiEroet7d1so6EYNbMPpDM= MIME-Version: 1.0 Received: by 10.216.91.10 with SMTP id g10mr993925wef.71.1249239108696; Sun, 02 Aug 2009 11:51:48 -0700 (PDT) In-Reply-To: <9ac0c6aa0908021045i19bdfe4ft37ffa73b77de1c86@mail.gmail.com> References: <4A74B851.8030503@gmail.com> <786fde50908020349v1addb022m1a7053dc1c4c64a8@mail.gmail.com> <9ac0c6aa0908021045i19bdfe4ft37ffa73b77de1c86@mail.gmail.com> Date: Sun, 2 Aug 2009 21:51:48 +0300 Message-ID: <786fde50908021151o7150d81fk334865771e2f0574@mail.gmail.com> Subject: Re: TestIndexWriter failure From: Shai Erera To: java-dev@lucene.apache.org Content-Type: multipart/alternative; boundary=0016e6d77e3c503c2b04702d2561 X-Virus-Checked: Checked by ClamAV on apache.org --0016e6d77e3c503c2b04702d2561 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Thanks Mike for the clarification. Almost all merge methods are synced on IndexWriter, except for mergeMiddle. So it is possible that you call abort, after the merge thread has already checked if the merge was aborted ... Maybe if we do: sync (this) { merge.checkAborted(directory); new SegmentMerger(...); } We'll protect against this particular exception? Because if merge.abort() wasn't called yet, the sync clause makes sure it won't be called until we get the SegmentMerger, otherwise we'll know the merge was aborted and so won't create SM at all. I looked at the rest of the method and this looks to be the only unprotected place. Although it is a loooong method, so I may have missed a spot. Shai On Sun, Aug 2, 2009 at 8:45 PM, Michael McCandless < lucene@mikemccandless.com> wrote: > The exceptions aren't expected. > > When you call IndexWriter.close(false), it's supposed to notify all > running merges to abort, wait until they in fact do stop, and then > return. > > But it looks as if there's a silly thread hazard, whereby IndexWriter > believes all merges have aborted, but in fact those 4 were just about > to get started and "missed" the abort request, and then tried to start > and hit the ACE. > > Mike > > On Sun, Aug 2, 2009 at 6:49 AM, Shai Erera wrote: > > Isn't this expected? I mean, if you close IndexWriter, but there are > merges > > run in the background, aren't they expected to hit an > > AlreadyClosedException? > > > > Perhaps we should fix the test to check whether CMS hit this exception > and > > if so clear it (as AFAIU, it's expected), and leave any other exceptions? > > This will require some change in CMS (to expose that information, through > > e.g. getUnhandledExceptions). > > > > Or add to CMS.Thread.run() a catch for AlreadyClosedException and ignore > it, > > as we do for MergeAbortedException? > > > > Or, stop doing any merges if CMS.close() has been called? > > > > On Sun, Aug 2, 2009 at 12:49 AM, Michael Busch > wrote: > >> > >> While running 'ant test' I just got this failure (on Mac OS 10.5.7). > Even > >> worse, the next time I ran it the test passed, so this might be hard to > >> reproduce. > >> I haven't tried yet to find out what caused this. > >> > >> [junit] Exception in thread "Lucene Merge Thread #1" > >> org.apache.lucene.index.MergePolicy$MergeException: > >> org.apache.lucene.store.AlreadyClosedException: this IndexWriter is > closed > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:351) > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:315) > >> [junit] Caused by: org.apache.lucene.store.AlreadyClosedException: > this > >> IndexWriter is closed > >> [junit] at > >> org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:791) > >> [junit] at > >> org.apache.lucene.index.IndexWriter.getDirectory(IndexWriter.java:2303) > >> [junit] at > >> org.apache.lucene.index.SegmentMerger.(SegmentMerger.java:88) > >> [junit] at > >> org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4942) > >> [junit] at > >> org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:4598) > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:235) > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:291) > >> [junit] Exception in thread "Lucene Merge Thread #2" > >> org.apache.lucene.index.MergePolicy$MergeException: > >> org.apache.lucene.store.AlreadyClosedException: this IndexWriter is > closed > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:351) > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:315) > >> [junit] Caused by: org.apache.lucene.store.AlreadyClosedException: > this > >> IndexWriter is closed > >> [junit] at > >> org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:791) > >> [junit] at > >> org.apache.lucene.index.IndexWriter.getDirectory(IndexWriter.java:2303) > >> [junit] at > >> org.apache.lucene.index.SegmentMerger.(SegmentMerger.java:88) > >> [junit] at > >> org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4942) > >> [junit] at > >> org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:4598) > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:235) > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:291) > >> [junit] Exception in thread "Lucene Merge Thread #3" > >> org.apache.lucene.index.MergePolicy$MergeException: > >> org.apache.lucene.store.AlreadyClosedException: this IndexWriter is > closed > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:351) > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:315) > >> [junit] Caused by: org.apache.lucene.store.AlreadyClosedException: > this > >> IndexWriter is closed > >> [junit] at > >> org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:791) > >> [junit] at > >> org.apache.lucene.index.IndexWriter.getDirectory(IndexWriter.java:2303) > >> [junit] at > >> org.apache.lucene.index.SegmentMerger.(SegmentMerger.java:88) > >> [junit] at > >> org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4942) > >> [junit] at > >> org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:4598) > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:235) > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:291) > >> [junit] Exception in thread "Lucene Merge Thread #4" > >> org.apache.lucene.index.MergePolicy$MergeException: > >> org.apache.lucene.store.AlreadyClosedException: this IndexWriter is > closed > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeException(ConcurrentMergeScheduler.java:351) > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:315) > >> [junit] Caused by: org.apache.lucene.store.AlreadyClosedException: > this > >> IndexWriter is closed > >> [junit] at > >> org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:791) > >> [junit] at > >> org.apache.lucene.index.IndexWriter.getDirectory(IndexWriter.java:2303) > >> [junit] at > >> org.apache.lucene.index.SegmentMerger.(SegmentMerger.java:88) > >> [junit] at > >> org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4942) > >> [junit] at > >> org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:4598) > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:235) > >> [junit] at > >> > org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:291) > >> [junit] ------------- ---------------- --------------- > >> [junit] Testcase: > >> testNoWaitClose(org.apache.lucene.index.TestIndexWriter): FAILED > >> [junit] ConcurrentMergeScheduler hit unhandled exceptions > >> [junit] junit.framework.AssertionFailedError: > ConcurrentMergeScheduler > >> hit unhandled exceptions > >> [junit] at > >> org.apache.lucene.util.LuceneTestCase.tearDown(LuceneTestCase.java:54) > >> [junit] Test org.apache.lucene.index.TestIndexWriter FAILED > >> > >> --------------------------------------------------------------------- > >> To unsubscribe, e-mail: java-dev-unsubscribe@lucene.apache.org > >> For additional commands, e-mail: java-dev-help@lucene.apache.org > >> > > > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: java-dev-unsubscribe@lucene.apache.org > For additional commands, e-mail: java-dev-help@lucene.apache.org > > --0016e6d77e3c503c2b04702d2561 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable
Thanks Mike for the clarification.

Almost all merge= methods are synced on IndexWriter, except for mergeMiddle. So it is possib= le that you call abort, after the merge thread has already checked if the m= erge was aborted ...

Maybe if we do:
sync (this) {
=A0 merge.checkAborted(directory);<= br>=A0 new SegmentMerger(...);
}

We'll protect against this p= articular exception? Because if merge.abort() wasn't called yet, the sy= nc clause makes sure it won't be called until we get the SegmentMerger,= otherwise we'll know the merge was aborted and so won't create SM = at all.

I looked at the rest of the method and this looks to be the only unprot= ected place. Although it is a loooong method, so I may have missed a spot.<= br>
Shai

On Sun, Aug 2, 2009 at 8:45 PM, Michael McCandless <lucene@mikemc= candless.com> wrote:
The exceptions aren't expected.

When you call IndexWriter.close(false), it's supposed to notify all
running merges to abort, wait until they in fact do stop, and then
return.

But it looks as if there's a silly thread hazard, whereby IndexWriter believes all merges have aborted, but in fact those 4 were just about
to get started and "missed" the abort request, and then tried to = start
and hit the ACE.

Mike

On Sun, Aug 2, 2009 at 6:49 AM, Shai Erera<serera@gmail.com> wrote:
> Isn't this expected? I mean, if you close IndexWriter, but there a= re merges
> run in the background, aren't they expected to hit an
> AlreadyClosedException?
>
> Perhaps we should fix the test to check whether CMS hit this exception= and
> if so clear it (as AFAIU, it's expected), and leave any other exce= ptions?
> This will require some change in CMS (to expose that information, thro= ugh
> e.g. getUnhandledExceptions).
>
> Or add to CMS.Thread.run() a catch for AlreadyClosedException and igno= re it,
> as we do for MergeAbortedException?
>
> Or, stop doing any merges if CMS.close() has been called?
>
> On Sun, Aug 2, 2009 at 12:49 AM, Michael Busch <buschmic@gmail.com> wrote:
>>
>> While running 'ant test' I just got this failure (on Mac O= S 10.5.7). Even
>> worse, the next time I ran it the test passed, so this might be ha= rd to
>> reproduce.
>> I haven't tried yet to find out what caused this.
>>
>> =A0 =A0[junit] Exception in thread "Lucene Merge Thread #1&qu= ot;
>> org.apache.lucene.index.MergePolicy$MergeException:
>> org.apache.lucene.store.AlreadyClosedException: this IndexWriter i= s closed
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeExcept= ion(ConcurrentMergeScheduler.java:351)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(C= oncurrentMergeScheduler.java:315)
>> =A0 =A0[junit] Caused by: org.apache.lucene.store.AlreadyClosedExc= eption: this
>> IndexWriter is closed
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:79= 1)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.getDirectory(IndexWriter.java:= 2303)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.SegmentMerger.<init>(SegmentMerger.j= ava:88)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4= 942)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:4598) >> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(Concurren= tMergeScheduler.java:235)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(C= oncurrentMergeScheduler.java:291)
>> =A0 =A0[junit] Exception in thread "Lucene Merge Thread #2&qu= ot;
>> org.apache.lucene.index.MergePolicy$MergeException:
>> org.apache.lucene.store.AlreadyClosedException: this IndexWriter i= s closed
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeExcept= ion(ConcurrentMergeScheduler.java:351)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(C= oncurrentMergeScheduler.java:315)
>> =A0 =A0[junit] Caused by: org.apache.lucene.store.AlreadyClosedExc= eption: this
>> IndexWriter is closed
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:79= 1)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.getDirectory(IndexWriter.java:= 2303)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.SegmentMerger.<init>(SegmentMerger.j= ava:88)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4= 942)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:4598) >> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(Concurren= tMergeScheduler.java:235)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(C= oncurrentMergeScheduler.java:291)
>> =A0 =A0[junit] Exception in thread "Lucene Merge Thread #3&qu= ot;
>> org.apache.lucene.index.MergePolicy$MergeException:
>> org.apache.lucene.store.AlreadyClosedException: this IndexWriter i= s closed
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeExcept= ion(ConcurrentMergeScheduler.java:351)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(C= oncurrentMergeScheduler.java:315)
>> =A0 =A0[junit] Caused by: org.apache.lucene.store.AlreadyClosedExc= eption: this
>> IndexWriter is closed
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:79= 1)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.getDirectory(IndexWriter.java:= 2303)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.SegmentMerger.<init>(SegmentMerger.j= ava:88)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4= 942)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:4598) >> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(Concurren= tMergeScheduler.java:235)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(C= oncurrentMergeScheduler.java:291)
>> =A0 =A0[junit] Exception in thread "Lucene Merge Thread #4&qu= ot;
>> org.apache.lucene.index.MergePolicy$MergeException:
>> org.apache.lucene.store.AlreadyClosedException: this IndexWriter i= s closed
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler.handleMergeExcept= ion(ConcurrentMergeScheduler.java:351)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(C= oncurrentMergeScheduler.java:315)
>> =A0 =A0[junit] Caused by: org.apache.lucene.store.AlreadyClosedExc= eption: this
>> IndexWriter is closed
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.ensureOpen(IndexWriter.java:79= 1)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.getDirectory(IndexWriter.java:= 2303)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.SegmentMerger.<init>(SegmentMerger.j= ava:88)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4= 942)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:4598) >> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(Concurren= tMergeScheduler.java:235)
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(C= oncurrentMergeScheduler.java:291)
>> =A0 =A0[junit] ------------- ---------------- ---------------
>> =A0 =A0[junit] Testcase:
>> testNoWaitClose(org.apache.lucene.index.TestIndexWriter): =A0 =A0F= AILED
>> =A0 =A0[junit] ConcurrentMergeScheduler hit unhandled exceptions >> =A0 =A0[junit] junit.framework.AssertionFailedError: ConcurrentMer= geScheduler
>> hit unhandled exceptions
>> =A0 =A0[junit] =A0 =A0 at
>> org.apache.lucene.util.LuceneTestCase.tearDown(LuceneTestCase.java= :54)
>> =A0 =A0[junit] Test org.apache.lucene.index.TestIndexWriter FAILED=
>>
>> ------------------------------------------------------------------= ---
>> To unsubscribe, e-mail: java-dev-unsubscribe@lucene.apache.org
>> For additional commands, e-mail: java-dev-help@lucene.apache.org
>>
>
>

---------------------------------------------------------------------
To unsubscribe, e-mail: java-dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: java-dev-help@lucene.apache.org


--0016e6d77e3c503c2b04702d2561--