Extremely slow response from ElasticSearch

Question

Extremely slow response from ElasticSearch

Closed this issue 6 years ago · 10 comments

2018-05-09T11:21:20.168Z - info: [api] [req] endpoint=/v1/search text=thailand, size=40, private=false, name=English, iso6391=en, iso6393=eng, defaulted=true, querySize=80, parser=libpostal, country=thailand
2018-05-09T11:21:20.169Z - info: [api] [query:search] [search_input_type:admin]
2018-05-09T11:21:20.169Z - info: [api] [parser:libpostal] query type not supported
2018-05-09T11:21:20.170Z - info: [api] fallback queryText: thailand
2018-05-09T11:21:20.174Z - info: [api] Ignoring address parser output, regions only
2018-05-09T11:21:20.175Z - info: [api] [req] endpoint=/v1/search text=thailand, size=40, private=false, name=English, iso6391=en, iso6393=eng, defaulted=true, querySize=80, parser=addressit
2018-05-09T11:21:20.175Z - info: [api] [query:search] [parser:addressit] [param:size]
2018-05-09T11:21:20.177Z - debug: [api] [ES req] index=pelias, searchType=dfs_query_then_fetch, must=[$=peliasQueryFullToken, $=1, $=thailand], should=[$=peliasPhrase, type=phrase, $=1, $=2, $ref=$["body"]["query"]["bool"]["must"][0]["match"]["name.default"]["query"], $ref=$["body"]["query"]["bool"]["should"][0]["match"]["phrase.default"]["analyzer"], type=phrase, $ref=$["body"]["query"]["bool"]["should"][0]["match"]["phrase.default"]["boost"], $ref=$["body"]["query"]["bool"]["should"][0]["match"]["phrase.default"]["slop"], $ref=$["body"]["query"]["bool"]["must"][0]["match"]["name.default"]["query"], $=20, functions=[$=log1p, $=popularity, missing=1, $=1], score_mode=first, boost_mode=replace, $ref=$["body"]["query"]["bool"]["should"][0]["match"]["phrase.default"]["analyzer"], type=phrase, $ref=$["body"]["query"]["bool"]["should"][0]["match"]["phrase.default"]["boost"], $ref=$["body"]["query"]["bool"]["should"][0]["match"]["phrase.default"]["slop"], $ref=$["body"]["query"]["bool"]["must"][0]["match"]["name.default"]["query"], $=20, functions=[$=log1p, $=population, missing=1, $=2], score_mode=first, boost_mode=replace], $=80, $=true, sort=[_score]
2018-05-09T11:21:38.671Z - verbose: [api] time elasticsearch reported: 18.467

18.4 seconds (!!) response from m5.4xlarge machine, something's just not right.

Answer 1 · 2018-05-10T05:13:35.000Z

That is definitely really slow. Can you tell us a bit more about how you set up Elasticsearch?

Answer 2 · 2018-05-10T05:21:03.000Z

I've set 1 instance with 60gb ram, HEAP max to 31GB that's all. elastic 2.4.

Answer 3 · 2018-05-10T20:09:49.000Z

Take a look at the Elasticsearch setup we have in Terraform: https://github.com/pelias/kubernetes/tree/master/elasticsearch

It's a reasonable set of defaults for a full planet build.

Answer 4 · 2018-05-14T10:59:35.000Z

Ok, I think it has to do with the following errors, I am getting tons of them:

Caused by: CircuitBreakingException[[fielddata] Data too large, data for [name.default] would be larger than limit of [19903571558/18.5gb]]
	at org.elasticsearch.common.breaker.ChildMemoryCircuitBreaker.circuitBreak(ChildMemoryCircuitBreaker.java:97)
	at org.elasticsearch.common.breaker.ChildMemoryCircuitBreaker.addEstimateBytesAndMaybeBreak(ChildMemoryCircuitBreaker.java:147)
	at org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData$PagedBytesEstimator.beforeLoad(PagedBytesIndexFieldData.java:218)
	at org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData.loadDirect(PagedBytesIndexFieldData.java:89)
	at org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData.loadDirect(PagedBytesIndexFieldData.java:43)
	at org.elasticsearch.indices.fielddata.cache.IndicesFieldDataCache$IndexFieldCache$1.call(IndicesFieldDataCache.java:163)
	at org.elasticsearch.indices.fielddata.cache.IndicesFieldDataCache$IndexFieldCache$1.call(IndicesFieldDataCache.java:156)
	at com.google.common.cache.LocalCache$LocalManualCache$1.load(LocalCache.java:4742)
	at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3527)
	at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2319)
	at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2282)
	at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2197)

Answer 5 · 2018-05-16T07:03:58.000Z

And another debug from ElasticSearch's slowlog query:

[2018-05-16 06:59:17,400][WARN ][index.search.slowlog.query] [Vapor] [pelias][3] took[19.5s], took_millis[19536], types[], stats[], search_type[DFS_QUERY_THEN_FETCH], total_shards[4], source[{"query":{"bool":{"must":[{"match":{"parent.country_a":{"analyzer":"standard","query":"USA"}}},{"match":{"name.default":{"analyzer":"peliasQueryFullToken","boost":1,"query":"texas"}}}],"should":[{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"popularity","missing":1},"weight":1}],"score_mode":"first","boost_mode":"replace"}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"population","missing":1},"weight":2}],"score_mode":"first","boost_mode":"replace"}},{"match":{"parent.region_a":{"analyzer":"peliasAdmin","boost":1,"query":"TX"}}},{"multi_match":{"fields":["parent.region_a^1"],"query":"TX","analyzer":"peliasAdmin"}}]}},"size":80,"track_scores":true,"sort":["_score"]}], extra_source[],

[2018-05-16 06:59:18,968][WARN ][index.search.slowlog.query] [Vapor] [pelias][0] took[21.1s], took_millis[21104], types[], stats[], search_type[DFS_QUERY_THEN_FETCH], total_shards[4], source[{"query":{"bool":{"must":[{"match":{"parent.country_a":{"analyzer":"standard","query":"USA"}}},{"match":{"name.default":{"analyzer":"peliasQueryFullToken","boost":1,"query":"texas"}}}],"should":[{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"popularity","missing":1},"weight":1}],"score_mode":"first","boost_mode":"replace"}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"population","missing":1},"weight":2}],"score_mode":"first","boost_mode":"replace"}},{"match":{"parent.region_a":{"analyzer":"peliasAdmin","boost":1,"query":"TX"}}},{"multi_match":{"fields":["parent.region_a^1"],"query":"TX","analyzer":"peliasAdmin"}}]}},"size":80,"track_scores":true,"sort":["_score"]}], extra_source[],

[2018-05-16 06:59:18,975][WARN ][index.search.slowlog.query] [Vapor] [pelias][1] took[21.1s], took_millis[21111], types[], stats[], search_type[DFS_QUERY_THEN_FETCH], total_shards[4], source[{"query":{"bool":{"must":[{"match":{"parent.country_a":{"analyzer":"standard","query":"USA"}}},{"match":{"name.default":{"analyzer":"peliasQueryFullToken","boost":1,"query":"texas"}}}],"should":[{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"popularity","missing":1},"weight":1}],"score_mode":"first","boost_mode":"replace"}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"population","missing":1},"weight":2}],"score_mode":"first","boost_mode":"replace"}},{"match":{"parent.region_a":{"analyzer":"peliasAdmin","boost":1,"query":"TX"}}},{"multi_match":{"fields":["parent.region_a^1"],"query":"TX","analyzer":"peliasAdmin"}}]}},"size":80,"track_scores":true,"sort":["_score"]}], extra_source[],

[2018-05-16 06:59:20,317][WARN ][index.search.slowlog.query] [Vapor] [pelias][2] took[22.4s], took_millis[22453], types[], stats[], search_type[DFS_QUERY_THEN_FETCH], total_shards[4], source[{"query":{"bool":{"must":[{"match":{"parent.country_a":{"analyzer":"standard","query":"USA"}}},{"match":{"name.default":{"analyzer":"peliasQueryFullToken","boost":1,"query":"texas"}}}],"should":[{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"popularity","missing":1},"weight":1}],"score_mode":"first","boost_mode":"replace"}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"population","missing":1},"weight":2}],"score_mode":"first","boost_mode":"replace"}},{"match":{"parent.region_a":{"analyzer":"peliasAdmin","boost":1,"query":"TX"}}},{"multi_match":{"fields":["parent.region_a^1"],"query":"TX","analyzer":"peliasAdmin"}}]}},"size":80,"track_scores":true,"sort":["_score"]}], extra_source[],

[2018-05-16 06:59:20,853][DEBUG][index.search.slowlog.fetch] [Vapor] [pelias][2] took[535.4ms], took_millis[535], types[], stats[], search_type[DFS_QUERY_THEN_FETCH], total_shards[4], source[{"query":{"bool":{"must":[{"match":{"parent.country_a":{"analyzer":"standard","query":"USA"}}},{"match":{"name.default":{"analyzer":"peliasQueryFullToken","boost":1,"query":"texas"}}}],"should":[{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"popularity","missing":1},"weight":1}],"score_mode":"first","boost_mode":"replace"}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"population","missing":1},"weight":2}],"score_mode":"first","boost_mode":"replace"}},{"match":{"parent.region_a":{"analyzer":"peliasAdmin","boost":1,"query":"TX"}}},{"multi_match":{"fields":["parent.region_a^1"],"query":"TX","analyzer":"peliasAdmin"}}]}},"size":80,"track_scores":true,"sort":["_score"]}], extra_source[],

[2018-05-16 06:59:21,025][DEBUG][index.search.slowlog.fetch] [Vapor] [pelias][1] took[707.6ms], took_millis[707], types[], stats[], search_type[DFS_QUERY_THEN_FETCH], total_shards[4], source[{"query":{"bool":{"must":[{"match":{"parent.country_a":{"analyzer":"standard","query":"USA"}}},{"match":{"name.default":{"analyzer":"peliasQueryFullToken","boost":1,"query":"texas"}}}],"should":[{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"popularity","missing":1},"weight":1}],"score_mode":"first","boost_mode":"replace"}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"population","missing":1},"weight":2}],"score_mode":"first","boost_mode":"replace"}},{"match":{"parent.region_a":{"analyzer":"peliasAdmin","boost":1,"query":"TX"}}},{"multi_match":{"fields":["parent.region_a^1"],"query":"TX","analyzer":"peliasAdmin"}}]}},"size":80,"track_scores":true,"sort":["_score"]}], extra_source[],

[2018-05-16 06:59:21,519][DEBUG][index.search.slowlog.fetch] [Vapor] [pelias][3] took[1.2s], took_millis[1201], types[], stats[], search_type[DFS_QUERY_THEN_FETCH], total_shards[4], source[{"query":{"bool":{"must":[{"match":{"parent.country_a":{"analyzer":"standard","query":"USA"}}},{"match":{"name.default":{"analyzer":"peliasQueryFullToken","boost":1,"query":"texas"}}}],"should":[{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"popularity","missing":1},"weight":1}],"score_mode":"first","boost_mode":"replace"}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"population","missing":1},"weight":2}],"score_mode":"first","boost_mode":"replace"}},{"match":{"parent.region_a":{"analyzer":"peliasAdmin","boost":1,"query":"TX"}}},{"multi_match":{"fields":["parent.region_a^1"],"query":"TX","analyzer":"peliasAdmin"}}]}},"size":80,"track_scores":true,"sort":["_score"]}], extra_source[],

[2018-05-16 06:59:23,529][DEBUG][index.search.slowlog.fetch] [Vapor] [pelias][0] took[3.2s], took_millis[3211], types[], stats[], search_type[DFS_QUERY_THEN_FETCH], total_shards[4], source[{"query":{"bool":{"must":[{"match":{"parent.country_a":{"analyzer":"standard","query":"USA"}}},{"match":{"name.default":{"analyzer":"peliasQueryFullToken","boost":1,"query":"texas"}}}],"should":[{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"popularity","missing":1},"weight":1}],"score_mode":"first","boost_mode":"replace"}},{"function_score":{"query":{"match":{"phrase.default":{"analyzer":"peliasPhrase","type":"phrase","boost":1,"slop":2,"query":"texas"}}},"max_boost":20,"functions":[{"field_value_factor":{"modifier":"log1p","field":"population","missing":1},"weight":2}],"score_mode":"first","boost_mode":"replace"}},{"match":{"parent.region_a":{"analyzer":"peliasAdmin","boost":1,"query":"TX"}}},{"multi_match":{"fields":["parent.region_a^1"],"query":"TX","analyzer":"peliasAdmin"}}]}},"size":80,"track_scores":true,"sort":["_score"]}], extra_source[],

Answer 6 · 2018-06-07T22:45:57.000Z

@Binternet Hi, I am just following along with limited knowledge of Pelias, but I notice that the schema is using fielddata heavily.
The queries listed in your slowlog do not necessarily need fielddata for name.default.
If this data is blowing up and not necessarily leveraged, it may make sense to re-index without it and then you won't be hitting the circuit-breaker

Once again, I don't know all the use-cases for these fields in Pelias, so I may be wrong.

Answer 7 · 2018-06-08T16:41:34.000Z

@talevy you are correct that we currently have fielddata enabled in lots of places that don't need it. We are looking at disabling it in #302

However, we see those circuit breaker exceptions as well, which as I understand it are saying that Elasticsearch didn't even try to load the fielddata, which is just as well since it won't be used. Our clusters don't see queries taking 20+ seconds, so there must also be something else going on. I'm very curious to know what it is.

Answer 8 · 2018-06-12T04:30:54.000Z

@orangejulius if I am not mistaken, the fielddata that you have set is being eagerly loaded with(eager_global_ordinals) when new segments are created in the background. since these fields are not leveraging docvalues, this fielddata is loaded into memory. So this is in memory, whether queries are using them or not

Answer 9 · 2018-06-12T07:01:20.000Z

Toda raba @talevy for this =)
@orangejulius I thanked Tal in hebrew

Answer 10 · 2018-09-10T16:05:26.000Z

I'm going to close this since the Pelias team was never able to reproduce. If anyone see's something similar feel free to comment and re-open.