CPU Spikes to more than 100% during bulk indexing


(Bhavani Ananth) #1

Hello,

I am having two Ubuntu systems in Amazon with the following configurations

Memory - 62.9GB
Hard Disk - 197GB
Hard Disk Available - 184GB
ard Disk Type: SSD
CPU - 8 Core

Oe ubuntu system has the ES setup. The following is the configuration ,
Java Version - Oracle Java 8
ES_HEAP_SIZE = 31g
Open File Descriptor 65535
shards 1
replicas 0
mlockall true
refresh interval 30s (tried with -1 also, same result)
max_locked_memory unlimited
vm.swapiness 1
throttle type merge
max_bytes_per_sec 20mb (tried changing to 100,150,10, but same result)

The ubuntu systems has the logstash setup for reading Apache logs. There are 10 logs each with 140000000 lines each. (14 crore lines)
When I start one logstash instance, around 1.6GB gets indexed in less than 1/2 hour. The CPU spikes ocassionally to more than 100%. But it's ocassional and more or less remains within 50-70%

When I start two instances of logstash, the CPU usage is more than 150% almost the whole time.
When I start 10 instances of logstash (25GB indexed), the usage is again more than 200%.

The system has room for accomodating more data (as it has a capacity 184 GB available) How can I reduce the spike in CPU. Do I necessarily have to go for more instances? What should be the ideal configuration? Thanks in advance for all your help!

Regards,
Bhavani

The hot_thread output is pasted below,
100.2% (501.1ms out of 500ms) cpu usage by thread 'elasticsearch[elk01][[logstash-2015.04.03][0]: Lucene Merge Thread #20]'
2/10 snapshots sharing following 10 elements
org.apache.lucene.codecs.PostingsConsumer.merge(PostingsConsumer.java:88)
org.apache.lucene.codecs.TermsConsumer.merge(TermsConsumer.java:110)
org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:72)
org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:399)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:112)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4223)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3811)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:409)
org.apache.lucene.index.TrackingConcurrentMergeScheduler.doMerge(TrackingConcurrentMergeScheduler.java:107)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:486)
8/10 snapshots sharing following 10 elements
org.apache.lucene.codecs.PostingsConsumer.merge(PostingsConsumer.java:83)
org.apache.lucene.codecs.TermsConsumer.merge(TermsConsumer.java:110)
org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:72)
org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:399)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:112)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4223)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3811)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:409)
org.apache.lucene.index.TrackingConcurrentMergeScheduler.doMerge(TrackingConcurrentMergeScheduler.java:107)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:486)
100.2% (501.1ms out of 500ms) cpu usage by thread 'elasticsearch[elk01][[logstash-2015.04.03][0]: Lucene Merge Thread #20]'
2/10 snapshots sharing following 12 elements
org.apache.lucene.codecs.lucene41.Lucene41PostingsReader$BlockDocsAndPositionsEnum.nextDoc(Lucene41PostingsReader.java:780)
org.apache.lucene.codecs.MappingMultiDocsAndPositionsEnum.nextDoc(MappingMultiDocsAndPositionsEnum.java:104)
org.apache.lucene.codecs.PostingsConsumer.merge(PostingsConsumer.java:109)
org.apache.lucene.codecs.TermsConsumer.merge(TermsConsumer.java:164)
org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:72)
org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:399)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:112)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4223)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3811)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:409)
org.apache.lucene.index.TrackingConcurrentMergeScheduler.doMerge(TrackingConcurrentMergeScheduler.java:107)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:486)
2/10 snapshots sharing following 10 elements
org.apache.lucene.codecs.PostingsConsumer.merge(PostingsConsumer.java:109)
org.apache.lucene.codecs.TermsConsumer.merge(TermsConsumer.java:164)
org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:72)
org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:399)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:112)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4223)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3811)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:409)
org.apache.lucene.index.TrackingConcurrentMergeScheduler.doMerge(TrackingConcurrentMergeScheduler.java:107)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:486)
3/10 snapshots sharing following 10 elements
org.apache.lucene.codecs.PostingsConsumer.merge(PostingsConsumer.java:118)
org.apache.lucene.codecs.TermsConsumer.merge(TermsConsumer.java:164)
org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:72)
org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:399)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:112)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4223)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3811)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:409)
org.apache.lucene.index.TrackingConcurrentMergeScheduler.doMerge(TrackingConcurrentMergeScheduler.java:107)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:486)
2/10 snapshots sharing following 14 elements
org.apache.lucene.codecs.lucene41.Lucene41SkipWriter.writeSkipData(Lucene41SkipWriter.java:151)
org.apache.lucene.codecs.MultiLevelSkipListWriter.bufferSkip(MultiLevelSkipListWriter.java:141)
org.apache.lucene.codecs.lucene41.Lucene41SkipWriter.bufferSkip(Lucene41SkipWriter.java:142)
org.apache.lucene.codecs.lucene41.Lucene41PostingsWriter.startDoc(Lucene41PostingsWriter.java:292)
org.apache.lucene.codecs.PostingsConsumer.merge(PostingsConsumer.java:115)
org.apache.lucene.codecs.TermsConsumer.merge(TermsConsumer.java:164)
org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:72)
org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:399)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:112)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4223)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3811)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:409)
org.apache.lucene.index.TrackingConcurrentMergeScheduler.doMerge(TrackingConcurrentMergeScheduler.java:107)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:486)
unique snapshot
org.apache.lucene.codecs.PostingsConsumer.merge(PostingsConsumer.java:120)
org.apache.lucene.codecs.TermsConsumer.merge(TermsConsumer.java:164)
org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:72)
org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:399)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:112)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4223)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3811)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:409)
org.apache.lucene.index.TrackingConcurrentMergeScheduler.doMerge(TrackingConcurrentMergeScheduler.java:107)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:486)
100.2% (500.9ms out of 500ms) cpu usage by thread 'elasticsearch[elk01][[logstash-2015.04.03][0]: Lucene Merge Thread #208]'
2/10 snapshots sharing following 16 elements
java.util.zip.CRC32.updateBytes(Native Method)
java.util.zip.CRC32.update(CRC32.java:65)
org.apache.lucene.store.BufferedChecksum.flush(BufferedChecksum.java:80)
org.apache.lucene.store.BufferedChecksum.update(BufferedChecksum.java:59)
org.apache.lucene.store.BufferedChecksumIndexInput.readBytes(BufferedChecksumIndexInput.java:50)
org.apache.lucene.codecs.compressing.LZ4.decompress(LZ4.java:101)
org.apache.lucene.codecs.compressing.CompressionMode$4.decompress(CompressionMode.java:135)
org.apache.lucene.codecs.compressing.CompressingStoredFieldsReader$ChunkIterator.decompress(CompressingStoredFieldsReader.java:508)
org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.merge(CompressingStoredFieldsWriter.java:378)
org.apache.lucene.index.SegmentMerger.mergeFields(SegmentMerger.java:332)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:100)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4223)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3811)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:409)
org.apache.lucene.index.TrackingConcurrentMergeScheduler.doMerge(TrackingConcurrentMergeScheduler.java:107)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:486)
5/10 snapshots sharing following 12 elements
org.apache.lucene.codecs.compressing.LZ4.compress(LZ4.java:243)
org.apache.lucene.codecs.compressing.CompressionMode$LZ4FastCompressor.compress(CompressionMode.java:161)
org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.flush(CompressingStoredFieldsWriter.java:236)
org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.finishDocument(CompressingStoredFieldsWriter.java:166)
org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.merge(CompressingStoredFieldsWriter.java:388)
org.apache.lucene.index.SegmentMerger.mergeFields(SegmentMerger.java:332)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:100)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4223)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3811)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:409)
org.apache.lucene.index.TrackingConcurrentMergeScheduler.doMerge(TrackingConcurrentMergeScheduler.java:107)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:486)
3/10 snapshots sharing following 7 elements
org.apache.lucene.index.SegmentMerger.mergeFields(SegmentMerger.java:332)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:100)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4223)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3811)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:409)
org.apache.lucene.index.TrackingConcurrentMergeScheduler.doMerge(TrackingConcurrentMergeScheduler.java:107)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:486)


(Harlin) #2

Why are you worried about 200% CPU usage on an 8 core machine?


(Mark Walkom) #3

Please keep it to one thread CPU spikes to more than 150% on running logstash instance


(Mark Walkom) #4