You are viewing a plain text version of this content. The canonical link for it is here.
Posted to java-user@lucene.apache.org by Pierre-Henri Toussaint <pi...@gmail.com> on 2011/08/03 16:16:38 UTC
Thread locking and extreme low perfs while merging
(ConcurrentMergeScheduler issue ?
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
Re: Thread locking while merging (ConcurrentMergeScheduler issue?)
Posted by Michael McCandless <lu...@mikemccandless.com>.
Indeed, from the log fragment I can see the merges are just really
slow. You had 6 merges run:
IW 0 [Wed Aug 03 22:43:24 CEST 2011; Lucene Merge Thread #0]: merged
segment size=1234.550 MB vs estimate=1300.063 MB
IW 0 [Thu Aug 04 00:15:54 CEST 2011; Lucene Merge Thread #4]: merged
segment size=740.168 MB vs estimate=780.602 MB
IW 0 [Thu Aug 04 00:29:49 CEST 2011; Lucene Merge Thread #1]: merged
segment size=1165.862 MB vs estimate=1224.516 MB
IW 0 [Thu Aug 04 00:39:36 CEST 2011; Lucene Merge Thread #5]: merged
segment size=899.690 MB vs estimate=943.422 MB
IW 0 [Thu Aug 04 00:39:52 CEST 2011; Lucene Merge Thread #3]: merged
segment size=1046.637 MB vs estimate=1097.111 MB
IW 0 [Thu Aug 04 01:07:04 CEST 2011; Lucene Merge Thread #2]: merged
segment size=1281.083 MB vs estimate=1340.087 MB
And the times are long:
IW 0 [Wed Aug 03 22:43:25 CEST 2011; Lucene Merge Thread #0]: merge
time 4194615 msec for 744793 docs
IW 0 [Thu Aug 04 00:15:55 CEST 2011; Lucene Merge Thread #4]: merge
time 6461433 msec for 1205717 docs
IW 0 [Thu Aug 04 00:29:50 CEST 2011; Lucene Merge Thread #1]: merge
time 9783566 msec for 1472419 docs
IW 0 [Thu Aug 04 00:39:38 CEST 2011; Lucene Merge Thread #5]: merge
time 7209832 msec for 1468231 docs
IW 0 [Thu Aug 04 00:39:53 CEST 2011; Lucene Merge Thread #3]: merge
time 8662995 msec for 1699997 docs
IW 0 [Thu Aug 04 01:07:04 CEST 2011; Lucene Merge Thread #2]: merge
time 11197195 msec for 1944231 docs
Though, for all but the first merge, the times include the "paused"
time, so it's not a real measure of how long the merge took. Still,
4195 seconds to merge to a ~1300 MB merged segment is really quite
long, but I think one big reason here is you are allowing too many
merge threads at once.
I would set CMS.setMaxThreadCount(1) and CMS.setMaxMergeCount(2), and
I would lower the number of indexing threads to 2. I think you IO
system is a big bottleneck here, not only because of merging and
flushing but also because presumably the source of the docs is on this
same single laptop spinning drive right?
Mike McCandless
http://blog.mikemccandless.com
On Wed, Aug 3, 2011 at 7:31 PM, Devon H. O'Dell <de...@gmail.com> wrote:
> For what it's worth, I've seen this happen too (using the stock Lucene
> 3.3 Java APIs), but it requires me to index many millions of
> documents, and doesn't start being a really big problem until the
> indexes get to be closer to 250GB in size. When they reach around 1TB,
> it will take around an hour for the merge to complete (which is
> frustrating). Similar to Pierre-Henri, I see virtually no disk I/O
> when it happens and the system in question is one of the Amazon EC2
> "Huge" instances (so, something like 8 cores and 32GB RAM) and disk
> I/O during indexing pushes around 100MB/s.
>
> If it would be useful to see additional reports / information from
> this scenario, I'm sure I can get something put together.
>
> --dho
>
> 2011/8/3 Pierre-Henri Toussaint <pi...@gmail.com>:
>> OK so the problem definitely comes from the slow merging.
>> I slightly increased the number merge count and thread to avoid the problem
>> described previously. But as expected, it just delayed it !
>>
>> results : 75 minutes to index the 33GB xml file, and 150 minutes to finish
>> the merge after indexer.close.
>> See uploaded http://lucene.472066.n3.nabble.com/file/n3223874/slowmerge log
>> file containing: logs (timems:numberofdocsindexed/current_title) +
>> infoStream + random threaddump.
>> You can spot "indexer.close (no optimize)" (line 5721) for indexing
>> completion and the beginning of merging nightmare.
>>
>> *conf :
>> */conf.setRAMBufferSizeMB(512);
>> ConcurrentMergeScheduler mergeScheduler = new ConcurrentMergeScheduler();
>> mergeScheduler.setMaxMergeCount(6);
>> mergeScheduler.setMaxThreadCount(4);
>> conf.setMergeScheduler(mergeScheduler);
>> writer = new ThreadedIndexWriter(directory, analyzer, true, 2, 5, conf);/
>>>>everything else default. no optimize called
>> *documents :
>> */pageDocument.add(new Field("title", page.getTitle(), Field.Store.YES,
>> Field.Index.NO));
>> pageDocument.add(new Field("text", page.getText(), Field.Store.NO,
>> Field.Index.ANALYZED));
>> if (page.getContributorUserName() != null)
>> pageDocument.add(new Field("contributorUserName",
>> page.getContributorUserName(), Field.Store.NO, Field.Index.ANALYZED));/
>> *infoStream info :*
>> setInfoStream
>> deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@2dafae45
>> dir=org.apache.lucene.store.NIOFSDirectory@/Users/ptoussaint/Documents/workspace/wikisearch/index2
>> lockFactory=org.apache.lucene.store.NativeFSLockFactory@39dd3812
>> index=
>> version=4.0-SNAPSHOT
>> matchVersion=LUCENE_40
>> analyzer=org.pache.soundcloud.wikisearch.Indexer$WikiAnalyzer
>> delPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy
>> commit=null
>> openMode=CREATE_OR_APPEND
>> similarityProvider=org.apache.lucene.search.DefaultSimilarityProvider
>> termIndexInterval=32
>> mergeScheduler=org.apache.lucene.index.ConcurrentMergeScheduler
>> default WRITE_LOCK_TIMEOUT=1000
>> writeLockTimeout=1000
>> maxBufferedDeleteTerms=-1
>> ramBufferSizeMB=512.0
>> maxBufferedDocs=-1
>> mergedSegmentWarmer=null
>> codecProvider=org.apache.lucene.index.codecs.CoreCodecProvider@6a8c436b
>> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10,
>> maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0,
>> expungeDeletesPctAllowed=10.0, segmentsPerTier=10.0, useCompoundFile=true,
>> noCFSRatio=0.1
>> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@1e9e5c73
>> readerPooling=false
>> readerTermsIndexDivisor=1
>> flushPolicy=org.apache.lucene.index.FlushByRamOrCountsPolicy@2ec791b9
>> perThreadHardLimitMB=1945
>>
>>
>>
>> --
>> View this message in context: http://lucene.472066.n3.nabble.com/Thread-locking-while-merging-ConcurrentMergeScheduler-issue-tp3222427p3223874.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
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: java-user-unsubscribe@lucene.apache.org
For additional commands, e-mail: java-user-help@lucene.apache.org
Re: Thread locking while merging (ConcurrentMergeScheduler issue?)
Posted by "Devon H. O'Dell" <de...@gmail.com>.
For what it's worth, I've seen this happen too (using the stock Lucene
3.3 Java APIs), but it requires me to index many millions of
documents, and doesn't start being a really big problem until the
indexes get to be closer to 250GB in size. When they reach around 1TB,
it will take around an hour for the merge to complete (which is
frustrating). Similar to Pierre-Henri, I see virtually no disk I/O
when it happens and the system in question is one of the Amazon EC2
"Huge" instances (so, something like 8 cores and 32GB RAM) and disk
I/O during indexing pushes around 100MB/s.
If it would be useful to see additional reports / information from
this scenario, I'm sure I can get something put together.
--dho
2011/8/3 Pierre-Henri Toussaint <pi...@gmail.com>:
> OK so the problem definitely comes from the slow merging.
> I slightly increased the number merge count and thread to avoid the problem
> described previously. But as expected, it just delayed it !
>
> results : 75 minutes to index the 33GB xml file, and 150 minutes to finish
> the merge after indexer.close.
> See uploaded http://lucene.472066.n3.nabble.com/file/n3223874/slowmerge log
> file containing: logs (timems:numberofdocsindexed/current_title) +
> infoStream + random threaddump.
> You can spot "indexer.close (no optimize)" (line 5721) for indexing
> completion and the beginning of merging nightmare.
>
> *conf :
> */conf.setRAMBufferSizeMB(512);
> ConcurrentMergeScheduler mergeScheduler = new ConcurrentMergeScheduler();
> mergeScheduler.setMaxMergeCount(6);
> mergeScheduler.setMaxThreadCount(4);
> conf.setMergeScheduler(mergeScheduler);
> writer = new ThreadedIndexWriter(directory, analyzer, true, 2, 5, conf);/
>>>everything else default. no optimize called
> *documents :
> */pageDocument.add(new Field("title", page.getTitle(), Field.Store.YES,
> Field.Index.NO));
> pageDocument.add(new Field("text", page.getText(), Field.Store.NO,
> Field.Index.ANALYZED));
> if (page.getContributorUserName() != null)
> pageDocument.add(new Field("contributorUserName",
> page.getContributorUserName(), Field.Store.NO, Field.Index.ANALYZED));/
> *infoStream info :*
> setInfoStream
> deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@2dafae45
> dir=org.apache.lucene.store.NIOFSDirectory@/Users/ptoussaint/Documents/workspace/wikisearch/index2
> lockFactory=org.apache.lucene.store.NativeFSLockFactory@39dd3812
> index=
> version=4.0-SNAPSHOT
> matchVersion=LUCENE_40
> analyzer=org.pache.soundcloud.wikisearch.Indexer$WikiAnalyzer
> delPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy
> commit=null
> openMode=CREATE_OR_APPEND
> similarityProvider=org.apache.lucene.search.DefaultSimilarityProvider
> termIndexInterval=32
> mergeScheduler=org.apache.lucene.index.ConcurrentMergeScheduler
> default WRITE_LOCK_TIMEOUT=1000
> writeLockTimeout=1000
> maxBufferedDeleteTerms=-1
> ramBufferSizeMB=512.0
> maxBufferedDocs=-1
> mergedSegmentWarmer=null
> codecProvider=org.apache.lucene.index.codecs.CoreCodecProvider@6a8c436b
> mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10,
> maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0,
> expungeDeletesPctAllowed=10.0, segmentsPerTier=10.0, useCompoundFile=true,
> noCFSRatio=0.1
> indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@1e9e5c73
> readerPooling=false
> readerTermsIndexDivisor=1
> flushPolicy=org.apache.lucene.index.FlushByRamOrCountsPolicy@2ec791b9
> perThreadHardLimitMB=1945
>
>
>
> --
> View this message in context: http://lucene.472066.n3.nabble.com/Thread-locking-while-merging-ConcurrentMergeScheduler-issue-tp3222427p3223874.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
Re: Thread locking while merging (ConcurrentMergeScheduler issue?)
Posted by Pierre-Henri Toussaint <pi...@gmail.com>.
OK so the problem definitely comes from the slow merging.
I slightly increased the number merge count and thread to avoid the problem
described previously. But as expected, it just delayed it !
results : 75 minutes to index the 33GB xml file, and 150 minutes to finish
the merge after indexer.close.
See uploaded http://lucene.472066.n3.nabble.com/file/n3223874/slowmerge log
file containing: logs (timems:numberofdocsindexed/current_title) +
infoStream + random threaddump.
You can spot "indexer.close (no optimize)" (line 5721) for indexing
completion and the beginning of merging nightmare.
*conf :
*/conf.setRAMBufferSizeMB(512);
ConcurrentMergeScheduler mergeScheduler = new ConcurrentMergeScheduler();
mergeScheduler.setMaxMergeCount(6);
mergeScheduler.setMaxThreadCount(4);
conf.setMergeScheduler(mergeScheduler);
writer = new ThreadedIndexWriter(directory, analyzer, true, 2, 5, conf);/
>>everything else default. no optimize called
*documents :
*/pageDocument.add(new Field("title", page.getTitle(), Field.Store.YES,
Field.Index.NO));
pageDocument.add(new Field("text", page.getText(), Field.Store.NO,
Field.Index.ANALYZED));
if (page.getContributorUserName() != null)
pageDocument.add(new Field("contributorUserName",
page.getContributorUserName(), Field.Store.NO, Field.Index.ANALYZED));/
*infoStream info :*
setInfoStream
deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@2dafae45
dir=org.apache.lucene.store.NIOFSDirectory@/Users/ptoussaint/Documents/workspace/wikisearch/index2
lockFactory=org.apache.lucene.store.NativeFSLockFactory@39dd3812
index=
version=4.0-SNAPSHOT
matchVersion=LUCENE_40
analyzer=org.pache.soundcloud.wikisearch.Indexer$WikiAnalyzer
delPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy
commit=null
openMode=CREATE_OR_APPEND
similarityProvider=org.apache.lucene.search.DefaultSimilarityProvider
termIndexInterval=32
mergeScheduler=org.apache.lucene.index.ConcurrentMergeScheduler
default WRITE_LOCK_TIMEOUT=1000
writeLockTimeout=1000
maxBufferedDeleteTerms=-1
ramBufferSizeMB=512.0
maxBufferedDocs=-1
mergedSegmentWarmer=null
codecProvider=org.apache.lucene.index.codecs.CoreCodecProvider@6a8c436b
mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10,
maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0,
expungeDeletesPctAllowed=10.0, segmentsPerTier=10.0, useCompoundFile=true,
noCFSRatio=0.1
indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@1e9e5c73
readerPooling=false
readerTermsIndexDivisor=1
flushPolicy=org.apache.lucene.index.FlushByRamOrCountsPolicy@2ec791b9
perThreadHardLimitMB=1945
--
View this message in context: http://lucene.472066.n3.nabble.com/Thread-locking-while-merging-ConcurrentMergeScheduler-issue-tp3222427p3223874.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
Re: Thread locking and extreme low perfs while merging
(ConcurrentMergeScheduler issue ?
Posted by Michael McCandless <lu...@mikemccandless.com>.
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
<pi...@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
Re: Thread locking while merging (ConcurrentMergeScheduler issue?)
Posted by Michael McCandless <lu...@mikemccandless.com>.
On Wed, Aug 3, 2011 at 1:22 PM, Pierre-Henri Toussaint
<pi...@gmail.com> wrote:
>> 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.
>>
>>>> It's exactly what I just noticed. And 5 indexing thread vs 1 merge
>>>> doesn't sound fair.
> I read ConcurrentMergeScheduler source code and found out that if
> maxMergeCount is reached, incoming threads are forcefully paused, which
> totally make sense. I should try to raise a little bit the maxMergeCount to
> be accorded with indexing.
Well, the core problem is that merging is running too slowly vs how
quickly your indexing threads are generating new segments -- so if you
raise maxMergeCount, you'll only cause merging to fall even more
behind.
> However, I still don't understand why the merging take so much time (few
> minutes to an hour). During that time, the IO are almost non existant and
> CPU stays low. That's why I suspected an locking issue.
Yeah that's strange. It could simply be you are using too many
indexing threads (plus laptop drive being slowish) -- since you only
have 2 cores (Core 2 Duo) maybe cut back from 5 to 2 threads?
>> What kind of IO system do you have?
>>>> slow macbook laptop harddrive. I'm actually just trying to get my grips
>>>> with this wonderful library before, I hope, being able to use it on a
>>>> proper system.
This could explain the slow merging.
>> Can you setInfoStream in the IW and post the output? Could give more
>> clues...
>>>> will post that after my next test
OK maybe we'll get more insight...
Mike McCandless
http://blog.mikemccandless.com
---------------------------------------------------------------------
To unsubscribe, e-mail: java-user-unsubscribe@lucene.apache.org
For additional commands, e-mail: java-user-help@lucene.apache.org
Re: Thread locking while merging (ConcurrentMergeScheduler issue?)
Posted by Simon Willnauer <si...@googlemail.com>.
On Wed, Aug 3, 2011 at 7:22 PM, Pierre-Henri Toussaint
<pi...@gmail.com> wrote:
> Hello,
>
> First many thanks for getting in touch.
>
>
> Michael McCandless-2 wrote:
>>
>> 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.
>>
>>>> It's exactly what I just noticed. And 5 indexing thread vs 1 merge
>>>> doesn't sound fair.
> I read ConcurrentMergeScheduler source code and found out that if
> maxMergeCount is reached, incoming threads are forcefully paused, which
> totally make sense. I should try to raise a little bit the maxMergeCount to
> be accorded with indexing.
>
> However, I still don't understand why the merging take so much time (few
> minutes to an hour). During that time, the IO are almost non existant and
> CPU stays low. That's why I suspected an locking issue.
>
>
> Michael McCandless-2 wrote:
>>
>> Are you sure you passed 2 for numThreads to ThreadedIndexWriter? I see 5
>> threads in your stack traces, I think.
>>>> I actually passed 5 threads in ThreadedIndexWriter, my mistake. Post
>>>> edited.
>
>
> Michael McCandless-2 wrote:
>>
>> What kind of IO system do you have?
>>>> slow macbook laptop harddrive. I'm actually just trying to get my grips
>>>> with this wonderful library before, I hope, being able to use it on a
>>>> proper system.
>
>
> Michael McCandless-2 wrote:
>>
>> Can you setInfoStream in the IW and post the output? Could give more
>> clues...
>>>> will post that after my next test
>
>
> Simon Willnauer wrote:
>>
>> can you explain your configuration as well as the problem? I see one
>> thread merging (Runnable state) and three other merge threads that are
>> waiting on a lock. it seems that CMS has put them into wait state and
>> your indexing threads are blocking on a stall control (too many
>> merging threads). is it possible that you are flushing very often ie.
>> low ram buffer or low maxBufferedDocs so that many segments are
>> created?
>>
>>>> I think the flushing is fine (RAMBufferSizeMB:256mb)
> My configuration is a macbookpro 2.4ghz/4GBram. Not ideal, but the goal is
> not to benchmark Lucene.
I rather refer to your IndexWriterConfig here, can you post it and
maybe tell me a little about how you index, what you index etc. how
many segments do you have, if you optimize etc. not sure why this is
happening but maybe something that looks unrelated to you can help?
simon
>
> --
> View this message in context: http://lucene.472066.n3.nabble.com/Thread-locking-while-merging-ConcurrentMergeScheduler-issue-tp3222427p3222946.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
Re: Thread locking while merging (ConcurrentMergeScheduler issue?)
Posted by Pierre-Henri Toussaint <pi...@gmail.com>.
Hello,
First many thanks for getting in touch.
Michael McCandless-2 wrote:
>
> 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.
>
>>> It's exactly what I just noticed. And 5 indexing thread vs 1 merge
>>> doesn't sound fair.
I read ConcurrentMergeScheduler source code and found out that if
maxMergeCount is reached, incoming threads are forcefully paused, which
totally make sense. I should try to raise a little bit the maxMergeCount to
be accorded with indexing.
However, I still don't understand why the merging take so much time (few
minutes to an hour). During that time, the IO are almost non existant and
CPU stays low. That's why I suspected an locking issue.
Michael McCandless-2 wrote:
>
> Are you sure you passed 2 for numThreads to ThreadedIndexWriter? I see 5
> threads in your stack traces, I think.
>>> I actually passed 5 threads in ThreadedIndexWriter, my mistake. Post
>>> edited.
Michael McCandless-2 wrote:
>
> What kind of IO system do you have?
>>> slow macbook laptop harddrive. I'm actually just trying to get my grips
>>> with this wonderful library before, I hope, being able to use it on a
>>> proper system.
Michael McCandless-2 wrote:
>
> Can you setInfoStream in the IW and post the output? Could give more
> clues...
>>> will post that after my next test
Simon Willnauer wrote:
>
> can you explain your configuration as well as the problem? I see one
> thread merging (Runnable state) and three other merge threads that are
> waiting on a lock. it seems that CMS has put them into wait state and
> your indexing threads are blocking on a stall control (too many
> merging threads). is it possible that you are flushing very often ie.
> low ram buffer or low maxBufferedDocs so that many segments are
> created?
>
>>> I think the flushing is fine (RAMBufferSizeMB:256mb)
My configuration is a macbookpro 2.4ghz/4GBram. Not ideal, but the goal is
not to benchmark Lucene.
--
View this message in context: http://lucene.472066.n3.nabble.com/Thread-locking-while-merging-ConcurrentMergeScheduler-issue-tp3222427p3222946.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
Re: Thread locking while merging (ConcurrentMergeScheduler issue?)
Posted by Simon Willnauer <si...@googlemail.com>.
On Wed, Aug 3, 2011 at 5:15 PM, Pierre-Henri Toussaint
<pi...@gmail.com> wrote:
> I tried to switch back to Lucene 3.2.0, same configuration, and I encountered
> the same problem, be at a later stage.
> See http://piratepad.net/ep/pad/export/ro.kMgHIoReJ2w/rev.2?format=txt here
> the thread dump .
>
can you explain your configuration as well as the problem? I see one
thread merging (Runnable state) and three other merge threads that are
waiting on a lock. it seems that CMS has put them into wait state and
your indexing threads are blocking on a stall control (too many
merging threads). is it possible that you are flushing very often ie.
low ram buffer or low maxBufferedDocs so that many segments are
created?
simon
>
> --
> View this message in context: http://lucene.472066.n3.nabble.com/Thread-locking-while-merging-ConcurrentMergeScheduler-issue-tp3222427p3222577.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
Re: Thread locking while merging (ConcurrentMergeScheduler issue?)
Posted by Pierre-Henri Toussaint <pi...@gmail.com>.
I tried to switch back to Lucene 3.2.0, same configuration, and I encountered
the same problem, be at a later stage.
See http://piratepad.net/ep/pad/export/ro.kMgHIoReJ2w/rev.2?format=txt here
the thread dump .
--
View this message in context: http://lucene.472066.n3.nabble.com/Thread-locking-while-merging-ConcurrentMergeScheduler-issue-tp3222427p3222577.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