OME while reading Completion Suggester Stats in /_cat/indices

[schmittberger]

Hi, I am running a single elasticsearch 5.5.0 node on a server with 4 CPUs, 32 GB RAM (16 GB for ES) and 2 TB SSD Drive. It has about 50 Million documents in 2 indices. One index has 5 shards and one has only 1. Since some time now the cluster has status green but as soon as I navigate to /_cat/indices elasticsearch reads huge amounts of data into the heap an finally crashes with a Java Heap Space Exception. The Stacktrace is as follows:

[2018-06-15T13:55:35,349][ERROR][o.e.b.ElasticsearchUncaughtExceptionHandler] [] fatal error in thread [elasticsearch[_L29Y8s][management][T#3]], exiting java.lang.OutOfMemoryError: Java heap space at org.apache.lucene.util.fst.FST.(FST.java:387) ~[lucene-core-6.6.0.jar:6.6.0 5c7a7b65d2aa7ce5ec96458315c661a18b320241 - ishan - 2017-05-30 07:29:46] at org.apache.lucene.util.fst.FST.(FST.java:313) ~[lucene-core-6.6.0.jar:6.6.0 5c7a7b65d2aa7ce5ec96458315c661a18b320241 - ishan - 2017-05-30 07:29:46] at org.apache.lucene.search.suggest.document.NRTSuggester.load(NRTSuggester.java:306) ~[lucene-suggest-6.6.0.jar:6.6.0 5c7a7b65d2aa7ce5ec96458315c661a18b320241 - ishan - 2017-05-30 07:30:09] at org.apache.lucene.search.suggest.document.CompletionsTermsReader.suggester(CompletionsTermsReader.java:66) ~[lucene-suggest-6.6.0.jar:6.6.0 5c7a7b65d2aa7ce5ec96458315c661a18b320241 - ishan - 2017-05-30 07:30:09] at org.apache.lucene.search.suggest.document.CompletionTerms.suggester(CompletionTerms.java:71) ~[lucene-suggest-6.6.0.jar:6.6.0 5c7a7b65d2aa7ce5ec96458315c661a18b320241 - ishan - 2017-05-30 07:30:09] at org.elasticsearch.search.suggest.completion.CompletionFieldStats.completionStats(CompletionFieldStats.java:57) ~[elasticsearch-5.5.0.jar:5.5.0] at org.elasticsearch.index.shard.IndexShard.completionStats(IndexShard.java:743) ~[elasticsearch-5.5.0.jar:5.5.0] at org.elasticsearch.action.admin.indices.stats.CommonStats.(CommonStats.java:207) ~[elasticsearch-5.5.0.jar:5.5.0] at org.elasticsearch.action.admin.indices.stats.TransportIndicesStatsAction.shardOperation(TransportIndicesStatsAction.java:163) ~[elasticsearch-5.5.0.jar:5.5.0] at org.elasticsearch.action.admin.indices.stats.TransportIndicesStatsAction.shardOperation(TransportIndicesStatsAction.java:47) ~[elasticsearch-5.5.0.jar:5.5.0] at org.elasticsearch.action.support.broadcast.node.TransportBroadcastByNodeAction$BroadcastByNodeTransportRequestHandler.onShardOperation(TransportBroadcastByNodeAction.java:433) ~[elasticsearch-5.5.0.jar:5.5.0] at org.elasticsearch.action.support.broadcast.node.TransportBroadcastByNodeAction$BroadcastByNodeTransportRequestHandler.messageReceived(TransportBroadcastByNodeAction.java:412) ~[elasticsearch-5.5.0.jar:5.5.0] at org.elasticsearch.action.support.broadcast.node.TransportBroadcastByNodeAction$BroadcastByNodeTransportRequestHandler.messageReceived(TransportBroadcastByNodeAction.java:399) ~[elasticsearch-5.5.0.jar:5.5.0] at org.elasticsearch.transport.TransportRequestHandler.messageReceived(TransportRequestHandler.java:33) ~[elasticsearch-5.5.0.jar:5.5.0] at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:69) ~[elasticsearch-5.5.0.jar:5.5.0] at org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:644) ~[elasticsearch-5.5.0.jar:5.5.0] at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:638) ~[elasticsearch-5.5.0.jar:5.5.0] at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) ~[elasticsearch-5.5.0.jar:5.5.0] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_171] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_171] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_171]

I analyzed the HeapDump and found the org.apache.lucene.index.SegmentReader to be the main suspect:

Can anyone help me out with this?

[imotov]

@schmittberger how much head do you have normally, when you don't run /_cat/indices and how many shards and segments are in these 2 indices?

[elasticmachine]

Pinging @elastic/es-search-aggs

[elasticmachine]

Pinging @elastic/es-core-infra

[schmittberger]

The GC sometimes takes a couple seconds if lots of indexing is going on but the 16 GB were sufficient so far. 1 index has 5 shards and 1 index has only 1 shard. The 5 shards index is 30 GB big, the 1 shard index uses 20 GB. Can't really tell you the number of segments right now. They both contain 18 Mio. documents

[schmittberger]

Attached output of /_cat/segments?v es_segments.txt

[imotov]

@schmittberger GC should never take a couple of seconds. I think what is happening is that you are running pretty high in terms of memory utilization, so a small bump in required memory sends it overboard. Could you run GET _nodes/stats/jvm and see how heap_used_percent changes over time?

[schmittberger]

Currently it is at 19% and it also happens if I run /_cat/indices directly after a fresh startup. I don't think that that is the problem. I also gave ES 20 and 28 GB just for testing - no improvement.

{ "_nodes": { "total": 1, "successful": 1, "failed": 0 }, "jvm": { "timestamp": 1529354041477, "uptime_in_millis": 19156507, "mem": { "heap_used_in_bytes": 3314907056, "heap_used_percent": 19, "heap_committed_in_bytes": 17188257792, "heap_max_in_bytes": 17188257792, "non_heap_used_in_bytes": 104607456, "non_heap_committed_in_bytes": 111734784, "pools": { "young": { "used_in_bytes": 427819008, "max_in_bytes": 0, "peak_used_in_bytes": 1551892480, "peak_max_in_bytes": 0 }, "survivor": { "used_in_bytes": 41943040, "max_in_bytes": 0, "peak_used_in_bytes": 209715200, "peak_max_in_bytes": 0 }, "old": { "used_in_bytes": 2845145008, "max_in_bytes": 17188257792, "peak_used_in_bytes": 2845145008, "peak_max_in_bytes": 17188257792 } } }, "threads": { "count": 87, "peak_count": 103 }, "gc": { "collectors": { "young": { "collection_count": 11, "collection_time_in_millis": 634 }, "old": { "collection_count": 0, "collection_time_in_millis": 0 } } }, "buffer_pools": { "direct": { "count": 70, "used_in_bytes": 270597657, "total_capacity_in_bytes": 270597656 }, "mapped": { "count": 1076, "used_in_bytes": 705365939719, "total_capacity_in_bytes": 705365939719 } }, "classes": { "current_loaded_count": 13264, "total_loaded_count": 13264, "total_unloaded_count": 0 } } } } }

[imotov]

From @schmittberger's description it looks like completion suggester stats might be using a lot (12G+) of heap space.

[schmittberger]

@imotov - what would be your recommendation to solve the problem? More shards, more nodes, ditribute over several machines? More memory is according to the rule to never give more than 31 GB not feasible, is it?

[imotov]

@schmittberger do you have the suggester fields on both indices or only on autocomplete?

[schmittberger]

only on autocomplete

[imotov]

@schmittberger are you actually using the autocomplete functionality on this index?

[schmittberger]

yes, we especially created this index just for autocomplete functionality

[imotov]

Was the result of GET _nodes/stats/jvm executed after you run the autocomplete query? If not could you run a few autocomplete requests and then run GET _nodes/stats/jvm? Could you also check the mapping to see if you have more than one field with the type "completion" in your mapping?

[schmittberger]

Pretty much every field has the completion type. I deleted the index now to try more shards - so I unfortunately can't tell you the jvm stats anymore right now.

[imotov]

@schmittberger but you don't run the autocomplete functionality on all these fields on a regular bases, correct? I think what's happening here the overall size of FSTs for all fields in your index exceeds the size of your heap space. Since these FSTs are lazily loaded you are not experiencing any issues until you force all of them to load by running stats. I think you should see the same memory issues if run a query with suggesters on all fields in this index. Could you verify?

[schmittberger]

@imotov: Our queries usually target only 1 or 2 fields, that's right. I am sure you are right that a query on all fields will have the same effect. The question for me now is how to solve this problem. I tried 5 shards for the autocomplete index now - but after indexing 5 million documents the same behaviour shows up. So the only feasible solution seems to spread across more nodes. But 1 node for every 3-4 mio documents is not a realistic thing to me...

[imotov]

The FST trees are loaded in memory upon first access. So you need to either increase amount of heap available to shards with completion fields by adding more nodes or by distributing these shards more equally to all nodes, or you need to reduce the amount of required memory by reducing the number of completion fields.

Since this doesn't seem to be a bug, I am going to close this issue. Let's continue on our discussion forum https://discuss.elastic.co/ If you have any other questions.

[schmittberger]

OK, thank you for your help.

I would still say that this should be considered as a bug since the _stats/indices page doesn't really show any information about the autcomplete fields / functionality but the information is still loaded. Also it should not run out of memory (so fast) - the "normal" index can take way more documents and still show its stats without problem. Maybe there are technical reasons I don't know / understand right now - then it is ok, but otherwise I would say it's a bug.

[briceruzand]

Hello,

I am facing to the same trouble too, when some users (using cerebro) call _cat/indices api, for monitoring indices redexing on our ES cluster, our server crash (on ES 6.5).

GET _cat/indices?format=json consume a lot of memory up to OutOfMemoryError according to the information returned (no data on Completion suggest statistics are returned).

GET _stats/ do the same, "completion" option activated by default (Completion suggest statistics) lead to load in memory all FST Suggester at the same time (or in a short time, and in parallel way)

I think is a bug because in real life not all that memory should be loaded a the same time and it could be garbage collected, because FST Suggester are lazy loaded.

_stats and _cat/indices should be improve to reduce the cluster memory usage.

It can be done on _stats by using options like _stats/store,docs.

Information on FST Suggester should be disabled by default according to the memory needed to only provide statistics (especially on _cat/indices api). Or maybe getting information on "completion" should not trigger FST Suggester load.

All others feature that I use are fast and work well with a few gigabytes of Ram. I cannot add more nodes or more RAM only for statistics features :-(

Thank you for you interest,

Best regards Brice Ruzand

[schmittberger]

I also still consider this as a bug that really needs fixing.

[jimczi]

I think is a bug because in real life not all that memory should be loaded a the same time and it could be garbage collected, because FST Suggester are lazy loaded.

They are lazily loaded but the memory will be used at some point, it can be suggestion queries that target the completion field, a merge that needs to read the data or the statistics endpoint to get the memory usage. If you cannot afford the memory needed by these completion fields maybe you should remove some of them or merge multiple fields in one.