lucene-java-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Michael McCandless <luc...@mikemccandless.com>
Subject Re: Thread locking and extreme low perfs while merging (ConcurrentMergeScheduler issue ?
Date Wed, 03 Aug 2011 16:15:51 GMT
It looks like merging is running too slowly in your environment,
relative to indexing; all of your indexing threads are stuck wanting
to launch a new merge but there's already the max allowed (1)
concurrent merge running and so IW (intentionally) stalls them.

Are you sure you passed 2 for numThreads to ThreadedIndexWriter?  I
see 5 threads in your stack traces, I think.

What kind of IO system do you have?

Can you setInfoStream in the IW and post the output?  Could give more clues...

Mike McCandless

http://blog.mikemccandless.com

On Wed, Aug 3, 2011 at 10:16 AM, Pierre-Henri Toussaint
<pierrehenri.toussaint@gmail.com> wrote:
> Hi All,
>
> I'm currently testing the new DocumentsWriterPerThread in Lucene 4.0.0
> (latest build). I use the wikipedia full english article dump as a source
> for indexing and the ThreadedIndexWriter implementation proposed in LIA to
> achieve concurrent indexing.
> Indexing performance seems good at the beginning (good throughput, cpu
> maxed, no drop while flushing!!), but then drop suddenly to nearly null
> after 20 minutes.
>
> See cpu usage drop bellow. IO is very low as well, and nothing get indexed
> from few minutes to an hour :
> http://lucene.472066.n3.nabble.com/file/n3222427/merge_problem_2.png
>
> After investigations, it appears that the performance drop while the merge
> occurs. I did a thread dump (see bellow) and it's pretty clear that
> everything wait for the merge worker to complete, which can take a long
> time.
>
> My config :
> -RAMBufferSizeMB:256mb
> -Indexer thread pool : 2/5 using the implementation proposed in LIA
> (ThreadedIndexWriter)
> -NIOFSDirectory
> -ConcurrentMergeScheduler, using default settings
> -osx10/core2duo@2.4ghz/4GBram
>
> What could cause this problem ?
> I use no external synchronisation around IndexWriter (as explained in
> javadoc). I tried w
>
> Thanks in advance for taking your time.
>
> /Full thread dump Java HotSpot(TM) 64-Bit Server VM (19.1-b02-334 mixed
> mode):
>
> "pool-1-thread-454645" prio=5 tid=101940000 nid=0x10cf90000 in Object.wait()
> [10cf8f000]
>   java.lang.Thread.State: WAITING (on object monitor)
>        at java.lang.Object.wait(Native Method)
>        - waiting on <7bd7dfd10> (a
> org.apache.lucene.index.ConcurrentMergeScheduler)
>        at java.lang.Object.wait(Object.java:485)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler.merge(ConcurrentMergeScheduler.java:319)
>        - locked <7bd7dfd10> (a org.apache.lucene.index.ConcurrentMergeScheduler)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1943)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1938)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1934)
>        at
> org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1548)
>        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1300)
>        at lia.admin.ThreadedIndexWriter.access$0(ThreadedIndexWriter.java:1)
>        at lia.admin.ThreadedIndexWriter$Job.run(ThreadedIndexWriter.java:52)
>        at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>        at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>        at java.lang.Thread.run(Thread.java:680)
>
> "pool-1-thread-451632" prio=5 tid=10193b000 nid=0x10ce8d000 in Object.wait()
> [10ce8c000]
>   java.lang.Thread.State: WAITING (on object monitor)
>        at java.lang.Object.wait(Native Method)
>        - waiting on <7bd7dfd10> (a
> org.apache.lucene.index.ConcurrentMergeScheduler)
>        at java.lang.Object.wait(Object.java:485)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler.merge(ConcurrentMergeScheduler.java:319)
>        - locked <7bd7dfd10> (a org.apache.lucene.index.ConcurrentMergeScheduler)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1943)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1938)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1934)
>        at
> org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1548)
>        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1300)
>        at lia.admin.ThreadedIndexWriter.access$0(ThreadedIndexWriter.java:1)
>        at lia.admin.ThreadedIndexWriter$Job.run(ThreadedIndexWriter.java:52)
>        at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>        at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>        at java.lang.Thread.run(Thread.java:680)
>
> "pool-1-thread-442636" prio=5 tid=10194e000 nid=0x10bef1000 in Object.wait()
> [10bef0000]
>   java.lang.Thread.State: WAITING (on object monitor)
>        at java.lang.Object.wait(Native Method)
>        - waiting on <7bd7dfd10> (a
> org.apache.lucene.index.ConcurrentMergeScheduler)
>        at java.lang.Object.wait(Object.java:485)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler.merge(ConcurrentMergeScheduler.java:319)
>        - locked <7bd7dfd10> (a org.apache.lucene.index.ConcurrentMergeScheduler)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1943)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1938)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1934)
>        at
> org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1548)
>        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1300)
>        at lia.admin.ThreadedIndexWriter.access$0(ThreadedIndexWriter.java:1)
>        at lia.admin.ThreadedIndexWriter$Job.run(ThreadedIndexWriter.java:52)
>        at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>        at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>        at java.lang.Thread.run(Thread.java:680)
>
> "pool-1-thread-427357" prio=5 tid=102b0d000 nid=0x10d901000 in Object.wait()
> [10d900000]
>   java.lang.Thread.State: WAITING (on object monitor)
>        at java.lang.Object.wait(Native Method)
>        - waiting on <7bd7dfd10> (a
> org.apache.lucene.index.ConcurrentMergeScheduler)
>        at java.lang.Object.wait(Object.java:485)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler.merge(ConcurrentMergeScheduler.java:319)
>        - locked <7bd7dfd10> (a org.apache.lucene.index.ConcurrentMergeScheduler)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1943)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1938)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1934)
>        at
> org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1548)
>        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1300)
>        at lia.admin.ThreadedIndexWriter.access$0(ThreadedIndexWriter.java:1)
>        at lia.admin.ThreadedIndexWriter$Job.run(ThreadedIndexWriter.java:52)
>        at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>        at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>        at java.lang.Thread.run(Thread.java:680)
>
> "Lucene Merge Thread #4" daemon prio=6 tid=102ae6000 nid=0x10bdee000 in
> Object.wait() [10bded000]
>   java.lang.Thread.State: TIMED_WAITING (on object monitor)
>        at java.lang.Object.wait(Native Method)
>        - waiting on <7d0a16870> (a org.apache.lucene.index.MergePolicy$OneMerge)
>        at
> org.apache.lucene.index.MergePolicy$OneMerge.checkAborted(MergePolicy.java:132)
>        - locked <7d0a16870> (a org.apache.lucene.index.MergePolicy$OneMerge)
>        at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3566)
>        at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3205)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:379)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:447)
>
> "pool-1-thread-412998" prio=5 tid=10193d800 nid=0x10cc87000 in Object.wait()
> [10cc86000]
>   java.lang.Thread.State: WAITING (on object monitor)
>        at java.lang.Object.wait(Native Method)
>        - waiting on <7bd7dfd10> (a
> org.apache.lucene.index.ConcurrentMergeScheduler)
>        at java.lang.Object.wait(Object.java:485)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler.merge(ConcurrentMergeScheduler.java:319)
>        - locked <7bd7dfd10> (a org.apache.lucene.index.ConcurrentMergeScheduler)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1943)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1938)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1934)
>        at
> org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1548)
>        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1300)
>        at lia.admin.ThreadedIndexWriter.access$0(ThreadedIndexWriter.java:1)
>        at lia.admin.ThreadedIndexWriter$Job.run(ThreadedIndexWriter.java:52)
>        at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>        at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>        at java.lang.Thread.run(Thread.java:680)
>
> "Lucene Merge Thread #3" daemon prio=6 tid=102b0b800 nid=0x10c901000 in
> Object.wait() [10c900000]
>   java.lang.Thread.State: TIMED_WAITING (on object monitor)
>        at java.lang.Object.wait(Native Method)
>        - waiting on <7c0222a80> (a org.apache.lucene.index.MergePolicy$OneMerge)
>        at
> org.apache.lucene.index.MergePolicy$OneMerge.checkAborted(MergePolicy.java:132)
>        - locked <7c0222a80> (a org.apache.lucene.index.MergePolicy$OneMerge)
>        at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3566)
>        at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3205)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:379)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:447)
>
> "Lucene Merge Thread #2" daemon prio=6 tid=102adc000 nid=0x10cd8a000 in
> Object.wait() [10cd89000]
>   java.lang.Thread.State: TIMED_WAITING (on object monitor)
>        at java.lang.Object.wait(Native Method)
>        - waiting on <7bd7faeb8> (a org.apache.lucene.index.MergePolicy$OneMerge)
>        at
> org.apache.lucene.index.MergePolicy$OneMerge.checkAborted(MergePolicy.java:132)
>        - locked <7bd7faeb8> (a org.apache.lucene.index.MergePolicy$OneMerge)
>        at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3515)
>        at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3205)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:379)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:447)
>
> "Lucene Merge Thread #1" daemon prio=6 tid=102ae0000 nid=0x10ca81000
> runnable [10ca80000]
>   java.lang.Thread.State: RUNNABLE
>        at sun.nio.ch.FileDispatcher.pread0(Native Method)
>        at sun.nio.ch.FileDispatcher.pread(FileDispatcher.java:31)
>        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:199)
>        at sun.nio.ch.IOUtil.read(IOUtil.java:175)
>        at sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:612)
>        at
> org.apache.lucene.store.NIOFSDirectory$NIOFSIndexInput.readInternal(NIOFSDirectory.java:215)
>        at
> org.apache.lucene.store.BufferedIndexInput.refill(BufferedIndexInput.java:237)
>        at
> org.apache.lucene.store.BufferedIndexInput.readByte(BufferedIndexInput.java:50)
>        at org.apache.lucene.store.DataInput.readVInt(DataInput.java:94)
>        at
> org.apache.lucene.store.BufferedIndexInput.readVInt(BufferedIndexInput.java:205)
>        at
> org.apache.lucene.index.codecs.standard.StandardPostingsReader$SegmentDocsAndPositionsEnum.nextDoc(StandardPostingsReader.java:499)
>        at
> org.apache.lucene.index.codecs.MappingMultiDocsAndPositionsEnum.nextDoc(MappingMultiDocsAndPositionsEnum.java:84)
>        at
> org.apache.lucene.index.codecs.PostingsConsumer.merge(PostingsConsumer.java:79)
>        at
> org.apache.lucene.index.codecs.TermsConsumer.merge(TermsConsumer.java:112)
>        at
> org.apache.lucene.index.codecs.FieldsConsumer.merge(FieldsConsumer.java:53)
>        at org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:566)
>        at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:135)
>        at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:3569)
>        at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3205)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:379)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:447)
>
> "Surrogate Locker Thread (CMS)" daemon prio=5 tid=10284a800 nid=0x10af01000
> waiting on condition [00000000]
>   java.lang.Thread.State: RUNNABLE
>
> "Finalizer" daemon prio=8 tid=102842000 nid=0x10aa8a000 in Object.wait()
> [10aa89000]
>   java.lang.Thread.State: WAITING (on object monitor)
>        at java.lang.Object.wait(Native Method)
>        - waiting on <7bd7c43e8> (a java.lang.ref.ReferenceQueue$Lock)
>        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
>        - locked <7bd7c43e8> (a java.lang.ref.ReferenceQueue$Lock)
>        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
>        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
>
> "Reference Handler" daemon prio=10 tid=102841000 nid=0x10a987000 in
> Object.wait() [10a986000]
>   java.lang.Thread.State: WAITING (on object monitor)
>        at java.lang.Object.wait(Native Method)
>        - waiting on <7bd7ca638> (a java.lang.ref.Reference$Lock)
>        at java.lang.Object.wait(Object.java:485)
>        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
>        - locked <7bd7ca638> (a java.lang.ref.Reference$Lock)
>
> "main" prio=5 tid=101801000 nid=0x100601000 in Object.wait() [1005ff000]
>   java.lang.Thread.State: WAITING (on object monitor)
>        at java.lang.Object.wait(Native Method)
>        - waiting on <7bd7dfd10> (a
> org.apache.lucene.index.ConcurrentMergeScheduler)
>        at java.lang.Object.wait(Object.java:485)
>        at
> org.apache.lucene.index.ConcurrentMergeScheduler.merge(ConcurrentMergeScheduler.java:319)
>        - locked <7bd7dfd10> (a org.apache.lucene.index.ConcurrentMergeScheduler)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1943)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1938)
>        at org.apache.lucene.index.IndexWriter.maybeMerge(IndexWriter.java:1934)
>        at
> org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1548)
>        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1300)
>        at lia.admin.ThreadedIndexWriter.access$0(ThreadedIndexWriter.java:1)
>        at lia.admin.ThreadedIndexWriter$Job.run(ThreadedIndexWriter.java:52)
>        at
> java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(ThreadPoolExecutor.java:1746)
>        at
> java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:767)
>        at
> java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:658)
>        at lia.admin.ThreadedIndexWriter.addDocument(ThreadedIndexWriter.java:82)
>        at org.pache.soundcloud.wikisearch.Indexer.addContact(Indexer.java:69)
>        at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source)
>        at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>        at java.lang.reflect.Method.invoke(Method.java:597)
>        at
> org.apache.commons.beanutils.MethodUtils.invokeMethod(MethodUtils.java:282)
>        at org.apache.commons.digester.SetNextRule.end(SetNextRule.java:220)
>        at org.apache.commons.digester.Rule.end(Rule.java:257)
>        at org.apache.commons.digester.Digester.endElement(Digester.java:1345)
>        at
> com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.endElement(AbstractSAXParser.java:601)
>        at
> com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanEndElement(XMLDocumentFragmentScannerImpl.java:1782)
>        at
> com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(XMLDocumentFragmentScannerImpl.java:2938)
>        at
> com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:648)
>        at
> com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:511)
>        at
> com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:808)
>        at
> com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:737)
>        at
> com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:119)
>        at
> com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1205)
>        at
> com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:522)
>        at org.apache.commons.digester.Digester.parse(Digester.java:1871)
>        at org.pache.soundcloud.wikisearch.Indexer.main(Indexer.java:119)
>        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>        at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
>        at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>        at java.lang.reflect.Method.invoke(Method.java:597)
>        at
> org.eclipse.jdt.internal.jarinjarloader.JarRsrcLoader.main(JarRsrcLoader.java:58)/
>
>
>
> --
> View this message in context: http://lucene.472066.n3.nabble.com/Thread-locking-and-extreme-low-perfs-while-merging-ConcurrentMergeScheduler-issue-tp3222427p3222427.html
> Sent from the Lucene - Java Users mailing list archive at Nabble.com.
>
> ---------------------------------------------------------------------
> 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


Mime
View raw message