CPU utilization has been increased by 40% in ES 2.1.1 when compared with ES 1.6

Elastic Stack Elasticsearch
1

We have observed that the CPU utilization in 2.1.1(while indexing is in progress) is 40% more compared with 1.6;we have made sure that the dataset is same in both the cases. A quick profiling has pointed out that ES bulk index threads are taking a lot of time. I've added the relevant screen shots to this thread. Our primary assumption is that writing doc_values could be the suspect as now they are enabled by default in 2.1.1 contrary to 1.6. Please let me know if anyone else has observed this issue.

1.png1609×587 56.9 KB

2.png1560×640 56.9 KB

3.png1883×559 59.5 KB

2

What type of data is it?

3

It is log data in JSON format.

4

Is the node the same specs between 1.6 and 2.1?

5

Yes, it is.

6

Any clues on this issue ? Should I create a defect on ES in GitHub?

7

The same problem is reproducible with 2.2 as well. It seems Lucene merge therad is taking a lot of CPU. Any pointers?

Following is the hot threads output:
::: {Nebulo}{KmYP936jSBe3tWS7Eda5jQ}{***}{***:9300}{master=false}
Hot threads at 2016-05-06T18:59:53.684Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

99.7% (498.4ms out of 500ms) cpu usage by thread 'elasticsearch[Nebulo][[bw-2016-05-06-18-001][5]: Lucene Merge Thread #115]'
2/10 snapshots sharing following 13 elements
org.apache.lucene.codecs.lucene50.Lucene50PostingsWriter.finishTerm(Lucene50PostingsWriter.java:343)
org.apache.lucene.codecs.PushPostingsWriterBase.writeTerm(PushPostingsWriterBase.java:169)
org.apache.lucene.codecs.blocktree.BlockTreeTermsWriter$TermsWriter.write(BlockTreeTermsWriter.java:1041)
org.apache.lucene.codecs.blocktree.BlockTreeTermsWriter.write(BlockTreeTermsWriter.java:456)
org.apache.lucene.codecs.perfield.PerFieldPostingsFormat$FieldsWriter.write(PerFieldPostingsFormat.java:198)
org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:105)
org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:193)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:95)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4075)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3655)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:588)
org.elasticsearch.index.engine.ElasticsearchConcurrentMergeScheduler.doMerge(ElasticsearchConcurrentMergeScheduler.java:94)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:626)
8/10 snapshots sharing following 9 elements
org.apache.lucene.codecs.perfield.PerFieldPostingsFormat$FieldsWriter.write(PerFieldPostingsFormat.java:198)
org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:105)
org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:193)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:95)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4075)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3655)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:588)
org.elasticsearch.index.engine.ElasticsearchConcurrentMergeScheduler.doMerge(ElasticsearchConcurrentMergeScheduler.java:94)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:626)

84.6% (423.1ms out of 500ms) cpu usage by thread 'elasticsearch[Nebulo][[bw-2016-05-06-18-001][10]: Lucene Merge Thread #115]'
10/10 snapshots sharing following 11 elements
org.apache.lucene.codecs.blocktree.BlockTreeTermsWriter$TermsWriter.write(BlockTreeTermsWriter.java:1041)
org.apache.lucene.codecs.blocktree.BlockTreeTermsWriter.write(BlockTreeTermsWriter.java:456)
org.apache.lucene.codecs.perfield.PerFieldPostingsFormat$FieldsWriter.write(PerFieldPostingsFormat.java:198)
org.apache.lucene.codecs.FieldsConsumer.merge(FieldsConsumer.java:105)
org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:193)
org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:95)
org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4075)
org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3655)
org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:588)
org.elasticsearch.index.engine.ElasticsearchConcurrentMergeScheduler.doMerge(ElasticsearchConcurrentMergeScheduler.java:94)
org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:626)