High Cpu in Idle State

Elastic Stack Elasticsearch
1

Hi,

I have been testing elasticsearch and have found it to slowly start using 100% of cpu even when there are no queries taking place. There's only few documents getting bulk indexed after every 10 seconds. But elasticsearch search is still using a lot of cpu in those idle 10 seconds.

I am using elasticsearch 0.90.2, mlockall at 1gb, fielddata cache set to soft. I don't think gc is the issue as there was no log warnings of slow gc calls.

It seems to be taking time in 1) org.elasticsearch.indices.cache.filter.IndicesFilterCache$ReaderCleaner
and 2) java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill

Hot Threads full dump

100.3% (501.4ms out of 500ms) cpu usage by thread 'elasticsearch[Braddock, Meggan][generic][T#192]'
2/10 snapshots sharing following 10 elements
org.elasticsearch.common.cache.LocalCache.getLiveValue(LocalCache.java:1950)
org.elasticsearch.common.cache.LocalCache$HashIterator.advanceTo(LocalCache.java:4389)
org.elasticsearch.common.cache.LocalCache$HashIterator.nextInTable(LocalCache.java:4373)
org.elasticsearch.common.cache.LocalCache$HashIterator.advance(LocalCache.java:4337)
org.elasticsearch.common.cache.LocalCache$HashIterator.nextEntry(LocalCache.java:4412)
org.elasticsearch.common.cache.LocalCache$KeyIterator.next(LocalCache.java:4428)
org.elasticsearch.indices.cache.filter.IndicesFilterCache$ReaderCleaner$1.run(IndicesFilterCache.java:184)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:722)
2/10 snapshots sharing following 5 elements
org.elasticsearch.common.trove.impl.hash.TObjectHash.contains(TObjectHash.java:153)
org.elasticsearch.indices.cache.filter.IndicesFilterCache$ReaderCleaner$1.run(IndicesFilterCache.java:185)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:722)
2/10 snapshots sharing following 8 elements
org.elasticsearch.common.cache.LocalCache$HashIterator.nextInTable(LocalCache.java:4372)
org.elasticsearch.common.cache.LocalCache$HashIterator.advance(LocalCache.java:4337)
org.elasticsearch.common.cache.LocalCache$HashIterator.nextEntry(LocalCache.java:4412)
org.elasticsearch.common.cache.LocalCache$KeyIterator.next(LocalCache.java:4428)
org.elasticsearch.indices.cache.filter.IndicesFilterCache$ReaderCleaner$1.run(IndicesFilterCache.java:184)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:722)
3/10 snapshots sharing following 7 elements
org.elasticsearch.common.cache.LocalCache$HashIterator.advance(LocalCache.java:4333)
org.elasticsearch.common.cache.LocalCache$HashIterator.nextEntry(LocalCache.java:4412)
org.elasticsearch.common.cache.LocalCache$KeyIterator.next(LocalCache.java:4428)
org.elasticsearch.indices.cache.filter.IndicesFilterCache$ReaderCleaner$1.run(IndicesFilterCache.java:184)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:722)
unique snapshot
org.elasticsearch.common.cache.LocalCache.getLiveValue(LocalCache.java:1947)
org.elasticsearch.common.cache.LocalCache$HashIterator.advanceTo(LocalCache.java:4389)
org.elasticsearch.common.cache.LocalCache$HashIterator.nextInTable(LocalCache.java:4373)
org.elasticsearch.common.cache.LocalCache$HashIterator.advance(LocalCache.java:4337)
org.elasticsearch.common.cache.LocalCache$HashIterator.nextEntry(LocalCache.java:4412)
org.elasticsearch.common.cache.LocalCache$KeyIterator.next(LocalCache.java:4428)
org.elasticsearch.indices.cache.filter.IndicesFilterCache$ReaderCleaner$1.run(IndicesFilterCache.java:184)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:722)

80.3% (401.3ms out of 500ms) cpu usage by thread 'elasticsearch[Braddock, Meggan][generic][T#192]'
10/10 snapshots sharing following 9 elements
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359)
java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:942)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:722)

Can someone help me with this? Thanks in advance.

2

Hi Max,

It looks like the cpu usage is coming from the background process that
cleans up cached filters. Are you make heavy use of changing filters (some
filters are cached by default).

You can check the size of the filter cache and the number of eviction but
calling:

curl -XGET "http://localhost:9200/_nodes/stats/?indices&pretty"

Cheers,
Boaz

On Tuesday, September 3, 2013 12:47:48 PM UTC+2, Max Little wrote:

Hi,

I have been testing elasticsearch and have found it to slowly start using
100% of cpu even when there are no queries taking place. There's only few
documents getting bulk indexed after every 10 seconds. But elasticsearch
search is still using a lot of cpu in those idle 10 seconds.

I am using elasticsearch 0.90.2, mlockall at 1gb, fielddata cache set to
soft. I don't think gc is the issue as there was no log warnings of slow
gc
calls.

It seems to be taking time in 1)
org.elasticsearch.indices.cache.filter.IndicesFilterCache$ReaderCleaner
and 2) java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill

Hot Threads full dump

100.3% (501.4ms out of 500ms) cpu usage by thread 'elasticsearch[Braddock,
Meggan][generic][T#192]'
2/10 snapshots sharing following 10 elements

org.elasticsearch.common.cache.LocalCache.getLiveValue(LocalCache.java:1950)

org.elasticsearch.common.cache.LocalCache$HashIterator.advanceTo(LocalCache.java:4389)

org.elasticsearch.common.cache.LocalCache$HashIterator.nextInTable(LocalCache.java:4373)

org.elasticsearch.common.cache.LocalCache$HashIterator.advance(LocalCache.java:4337)

org.elasticsearch.common.cache.LocalCache$HashIterator.nextEntry(LocalCache.java:4412)

org.elasticsearch.common.cache.LocalCache$KeyIterator.next(LocalCache.java:4428)

org.elasticsearch.indices.cache.filter.IndicesFilterCache$ReaderCleaner$1.run(IndicesFilterCache.java:184)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

   java.lang.Thread.run(Thread.java:722) 
 2/10 snapshots sharing following 5 elements

org.elasticsearch.common.trove.impl.hash.TObjectHash.contains(TObjectHash.java:153)

org.elasticsearch.indices.cache.filter.IndicesFilterCache$ReaderCleaner$1.run(IndicesFilterCache.java:185)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

   java.lang.Thread.run(Thread.java:722) 
 2/10 snapshots sharing following 8 elements

org.elasticsearch.common.cache.LocalCache$HashIterator.nextInTable(LocalCache.java:4372)

org.elasticsearch.common.cache.LocalCache$HashIterator.advance(LocalCache.java:4337)

org.elasticsearch.common.cache.LocalCache$HashIterator.nextEntry(LocalCache.java:4412)

org.elasticsearch.common.cache.LocalCache$KeyIterator.next(LocalCache.java:4428)

org.elasticsearch.indices.cache.filter.IndicesFilterCache$ReaderCleaner$1.run(IndicesFilterCache.java:184)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

   java.lang.Thread.run(Thread.java:722) 
 3/10 snapshots sharing following 7 elements

org.elasticsearch.common.cache.LocalCache$HashIterator.advance(LocalCache.java:4333)

org.elasticsearch.common.cache.LocalCache$HashIterator.nextEntry(LocalCache.java:4412)

org.elasticsearch.common.cache.LocalCache$KeyIterator.next(LocalCache.java:4428)

org.elasticsearch.indices.cache.filter.IndicesFilterCache$ReaderCleaner$1.run(IndicesFilterCache.java:184)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

   java.lang.Thread.run(Thread.java:722) 
 unique snapshot

org.elasticsearch.common.cache.LocalCache.getLiveValue(LocalCache.java:1947)

org.elasticsearch.common.cache.LocalCache$HashIterator.advanceTo(LocalCache.java:4389)

org.elasticsearch.common.cache.LocalCache$HashIterator.nextInTable(LocalCache.java:4373)

org.elasticsearch.common.cache.LocalCache$HashIterator.advance(LocalCache.java:4337)

org.elasticsearch.common.cache.LocalCache$HashIterator.nextEntry(LocalCache.java:4412)

org.elasticsearch.common.cache.LocalCache$KeyIterator.next(LocalCache.java:4428)

org.elasticsearch.indices.cache.filter.IndicesFilterCache$ReaderCleaner$1.run(IndicesFilterCache.java:184)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

   java.lang.Thread.run(Thread.java:722)

80.3% (401.3ms out of 500ms) cpu usage by thread 'elasticsearch[Braddock,
Meggan][generic][T#192]'
10/10 snapshots sharing following 9 elements
sun.misc.Unsafe.park(Native Method)

java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)

java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)

java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359)

java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:942)

java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

   java.lang.Thread.run(Thread.java:722)

Can someone help me with this? Thanks in advance.

--
View this message in context:
http://elasticsearch-users.115913.n3.nabble.com/High-Cpu-in-Idle-State-tp4040509.html
Sent from the Elasticsearch Users mailing list archive at Nabble.com.

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

3

Hi,

The filter cache was growing gradually because of changing filters.

Modifying filter cache type to soft keeps it in check and seems to solve the problem.

Thanks for pointing me in the right direction.

Cheers

4

The price you pay for soft references is heavy random activity on CPU and
GC if your cache is small. You should try to increase the cache size to
lower the risk of that, or consider to drop soft references.

Jörg

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

5

Hi Max,
I also wonder if you actually need those changing filters to be cached.
What kind of filters are they?
If you don't need them in cache you can just disable caching for each of
those using "_cache" : false .

Cheers
Luca

On Tuesday, September 3, 2013 8:07:35 PM UTC+2, Max Little wrote:

Hi,

The filter cache was growing gradually because of changing filters.

Modifying filter cache type to soft keeps it in check and seems to solve
the
problem.

Thanks for pointing me in the right direction.

Cheers

--
View this message in context:
http://elasticsearch-users.115913.n3.nabble.com/High-Cpu-in-Idle-State-tp4040509p4040534.html
Sent from the Elasticsearch Users mailing list archive at Nabble.com.

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.