# Bug? Elasticsearch 7 (after upgrade from 6.7) slow search during 3-5 seconds every 60 seconds **URL:** \ **Category:** Elasticsearch\ **Created:** [April 16, 2019, 7:52am UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017 "2019-04-16T07:52:56Z")\ **Posts on this page:** 18\ **Page:** 2
**Author:** ![DavidTurner](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/davidturner/32/22453_2.png) [@DavidTurner](https://discuss.elastic.co/u/DavidTurner)\ **Post date:** [April 17, 2019, 7:32am UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/21 "2019-04-17T07:32:32Z")
Ok, try the following settings: ```auto PUT /_cluster/settings { "persistent": { "transport.tracer.include": "indices:data/read/search*", "logger.org.elasticsearch.search": "TRACE", "logger.org.elasticsearch.tasks.TaskManager": "TRACE", "logger.org.elasticsearch.transport.TransportService.tracer": "TRACE" } } ``` This should give us some more detailed logs. After you've captured a slow query, you can reset the settings back to their defaults like this: ```auto PUT /_cluster/settings { "persistent": { "transport.tracer.include": null, "logger.org.elasticsearch.search": null, "logger.org.elasticsearch.tasks.TaskManager": null, "logger.org.elasticsearch.transport.TransportService.tracer": null } } ``` ---
**Author:** ![Nenad](https://avatars.discourse-cdn.com/v4/letter/n/13edae/32.png) [@Nenad](https://discuss.elastic.co/u/Nenad)\ **Post date:** [April 17, 2019, 9:54am UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/22 "2019-04-17T09:54:25Z")
Thank you on your help, I have set the log settings: ```auto {"persistent":{"logger":{"org":{"elasticsearch":{"search":"TRACE","tasks":{"TaskManager":"TRACE"},"transport":{"TransportService":{"tracer":"TRACE"}}}}},"transport":{"tracer":{"include":"indices:data/read/search*"}}},"transient":{}} ``` To be sure I do this the right way: I have a for loop on shell that execute dump command wait 200ms and repeat, during this I execute search query on shell until I catch when it slows down then I take the dump around this time. Dump (time in microseconds): 1555493939844626530 [https://pastebin.com/z8KhfaBY](https://pastebin.com/z8KhfaBY) 1555493940778830070 [https://pastebin.com/KHegMV9S](https://pastebin.com/KHegMV9S) 1555493941702770377 [https://pastebin.com/BYdd5gBR](https://pastebin.com/BYdd5gBR) 1555493942425515017 **Slow query "took":1047** 1555493942608281975 [https://pastebin.com/XSBCtBiH](https://pastebin.com/XSBCtBiH) 1555493944420553980 [https://pastebin.com/jbEfHwjm](https://pastebin.com/jbEfHwjm) Trace Log: [https://pastebin.com/PX4mqb2a](https://pastebin.com/PX4mqb2a) Aside of above, I have monitored network latency between the two nodes this is all the time below 0.5 ms. I then catched that with 1 node running only, after update of documents is done the first request take longer time (warming), but it took much longer (800ms vs 200ms) as on 6.7. ---
**Author:** ![DavidTurner](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/davidturner/32/22453_2.png) [@DavidTurner](https://discuss.elastic.co/u/DavidTurner)\ **Post date:** [April 17, 2019, 11:03am UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/23 "2019-04-17T11:03:46Z")
Right, that log is from `node-1` and has these two lines in it: ```auto [2019-04-17T11:39:02,442][TRACE][o.e.t.T.tracer] [node-1] [720416][indices:data/read/search[phase/query]] sent to [{node-2}{DKwENWkuQCi7T0hcIZkUfA}{1OkulvjIQhydOsXXY0K-YQ}{node-2-ip}{node-2-ip:9300}{ml.machine_memory=67161415680, ml.max_open_jobs=20, xpack.installed=true}] (timeout: [null]) [2019-04-17T11:39:03,484][TRACE][o.e.t.T.tracer] [node-1] [720416][indices:data/read/search[phase/query]] received response from [{node-2}{DKwENWkuQCi7T0hcIZkUfA}{1OkulvjIQhydOsXXY0K-YQ}{node-2-ip}{node-2-ip:9300}{ml.machine_memory=67161415680, ml.max_open_jobs=20, xpack.installed=true}] ``` This tells us that the query phase of this search took over a second on `node-2`, from `node-1`'s point of view. Can you share the logs from both nodes so we can see things from `node-2`'s point of view as well? ---
**Author:** ![Nenad](https://avatars.discourse-cdn.com/v4/letter/n/13edae/32.png) [@Nenad](https://discuss.elastic.co/u/Nenad)\ **Post date:** [April 17, 2019, 12:10pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/24 "2019-04-17T12:10:19Z")
Here is the node-2 Log: [https://pastebin.com/dRLPVr9X](https://pastebin.com/dRLPVr9X) ---
**Author:** ![DavidTurner](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/davidturner/32/22453_2.png) [@DavidTurner](https://discuss.elastic.co/u/DavidTurner)\ **Post date:** [April 17, 2019, 12:26pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/25 "2019-04-17T12:26:53Z")
Interesting, thanks. Here's the relevant lines from `node-2`: ```auto [2019-04-17T11:39:02,442][TRACE][o.e.t.T.tracer] [node-2] [720416][indices:data/read/search[phase/query]] received request [2019-04-17T11:39:02,442][TRACE][o.e.t.TaskManager] [node-2] register 14352 [netty] [indices:data/read/search[phase/query]] [shardId[[app1_profile][2]]] [2019-04-17T11:39:03,479][TRACE][o.e.s.q.QueryPhase] [node-2] [app1_profile][2] source[{"from":0,"size":1,"query":{"bool":{"filter":[{"term":{"member_status":{"value":1,"boost":1.0}}},{"terms":{"app_id":["","app1"],"boost":1.0}},{"term":{"country":{"value":"CH","boost":1.0}}},{"term":{"gender":{"value":0,"boost":1.0}}},{"term":{"search_male":{"value":1,"boost":1.0}}},{"range":{"dob":{"from":"now-44y/d","to":"now-20y/d","include_lower":true,"include_upper":true,"boost":1.0}}},{"range":{"search_min_age":{"from":null,"to":37,"include_lower":true,"include_upper":true,"boost":1.0}}},{"range":{"search_max_age":{"from":37,"to":null,"include_lower":true,"include_upper":true,"boost":1.0}}}],"must_not":[{"term":{"is_hidden":{"value":1,"boost":1.0}}},{"term":{"member_id":{"value":1,"boost":1.0}}}],"adjust_pure_negative":true,"boost":1.0}},"profile":true,"_source":{"includes":["hash_id","town","member_id","photo","first_name","gender","dob","last_request_dt","created_dt","geo_distance"],"excludes":[]},"script_fields":{"geo_distance":{"script":{"source":"doc['geo_pt'].arcDistance(params.lat, params.lon)","lang":"painless","params":{"lon":8.53955,"lat":47.37706}},"ignore_failure":false}},"sort":[{"_geo_distance":{"geo_pt":[{"lat":47.37706,"lon":8.53955}],"unit":"km","distance_type":"arc","order":"asc","validation_method":"STRICT","ignore_unmapped":false}},{"last_request_dt":{"order":"desc"}},{"member_id":{"order":"desc"}}]}], id[], [2019-04-17T11:39:03,483][TRACE][o.e.t.TaskManager] [node-2] unregister task for id: 14352 [2019-04-17T11:39:03,483][TRACE][o.e.t.T.tracer] [node-2] [720416][indices:data/read/search[phase/query]] sent response ``` The time is all spent between receiving the task at `11:39:02,442` and starting to execute it at `11:39:03,479`. The most relevant hot\_threads seems to be [https://pastebin.com/XSBCtBiH](https://pastebin.com/XSBCtBiH), assuming that your log times are UTC+2h. ```nohighlight Hot threads at 2019-04-17T09:39:02.612Z, interval=500ms, busiestThreads=999999, ignoreIdleThreads=false: ``` However there is literally nothing of interest in that thread dump. Bear with me, I'm going to speak to some colleagues. ---
**Author:** ![DavidTurner](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/davidturner/32/22453_2.png) [@DavidTurner](https://discuss.elastic.co/u/DavidTurner)\ **Post date:** [April 17, 2019, 12:29pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/26 "2019-04-17T12:29:47Z")
Can you provide the `gc.log` from `node-2` around this time? ---
**Author:** ![Nenad](https://avatars.discourse-cdn.com/v4/letter/n/13edae/32.png) [@Nenad](https://discuss.elastic.co/u/Nenad)\ **Post date:** [April 17, 2019, 12:40pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/27 "2019-04-17T12:40:21Z")
Thank you for explanation. Yes you're right UTC+2h. gc.log: [https://pasteby.com/DSLzu560mh](https://pasteby.com/DSLzu560mh) ---
**Author:** ![DavidTurner](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/davidturner/32/22453_2.png) [@DavidTurner](https://discuss.elastic.co/u/DavidTurner)\ **Post date:** [April 17, 2019, 12:55pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/28 "2019-04-17T12:55:31Z")
Could you try explicitly setting `index.refresh_interval` on this index? Doesn't really matter what you set it to, but `1s` is the default in 6.7 so you could try that. ---
**Author:** ![Nenad](https://avatars.discourse-cdn.com/v4/letter/n/13edae/32.png) [@Nenad](https://discuss.elastic.co/u/Nenad)\ **Post date:** [April 17, 2019, 1:34pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/29 "2019-04-17T13:34:07Z")
Awesome! This solved the Issue, thank you very much. I have set interval of 1s. Is there anything I should take care because I have set this? Btw. I have make a shell script and monitored many hundred querys, they took 6-11 ms, rarely one had need 20 - 25 ms. ---
**Author:** ![DavidTurner](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/davidturner/32/22453_2.png) [@DavidTurner](https://discuss.elastic.co/u/DavidTurner)\ **Post date:** [April 17, 2019, 1:49pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/30 "2019-04-17T13:49:11Z")
Ok, I think I can explain this. The change in 7.0 is [this one](https://www.elastic.co/guide/en/elasticsearch/reference/current/release-highlights-7.0.0.html#_skip_shard_refreshes_if_a_shard_is_search_idle), which is designed to avoid unnecessary refreshes on shard copies that are rarely searched, to improve indexing performance. However if you perform a search after a shard copy has gone search-idle _and_ you've just indexed some documents then the search will wait until the refresh has completed before proceeding. Setting the refresh interval to something (anything) prevents the shard from going search-idle. It shouldn't have much effect on an index that only rarely sees any indexing. I'm still puzzled about two things: 1. I think you were searching this shard frequently enough to prevent it from going search idle anyway. 2. I do not understand why we couldn't see a thread performing the refresh. Not to worry, I can look into these myself. ---
**Author:** ![Nenad](https://avatars.discourse-cdn.com/v4/letter/n/13edae/32.png) [@Nenad](https://discuss.elastic.co/u/Nenad)\ **Post date:** [April 17, 2019, 2:05pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/31 "2019-04-17T14:05:15Z")
Yes this is really strange, because of 1. even if no user is using the search over the Web UI there are two processes working on production all the time that fire permanently search requests (not below 1 per second), means the two involved index are used 24/7 frequently. If i can help with any tests on my side to catch the reason for 2. let me know. ---
**Author:** ![s1monw](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/s1monw/32/3637_2.png) [@s1monw](https://discuss.elastic.co/u/s1monw)\ **Post date:** [April 18, 2019, 11:08am UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/32 "2019-04-18T11:08:09Z")
can you try setting `"index.search.idle.after" : "10000d"` for this index and see what happens? it's a dynamic setting ---
**Author:** ![Nenad](https://avatars.discourse-cdn.com/v4/letter/n/13edae/32.png) [@Nenad](https://discuss.elastic.co/u/Nenad)\ **Post date:** [April 18, 2019, 12:53pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/33 "2019-04-18T12:53:06Z")
sure, shoud I set before `index.refresh_interval` = null? ---
**Author:** ![s1monw](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/s1monw/32/3637_2.png) [@s1monw](https://discuss.elastic.co/u/s1monw)\ **Post date:** [April 18, 2019, 12:59pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/34 "2019-04-18T12:59:49Z")
you can set it to 1 second. that's fine! ---
**Author:** ![Nenad](https://avatars.discourse-cdn.com/v4/letter/n/13edae/32.png) [@Nenad](https://discuss.elastic.co/u/Nenad)\ **Post date:** [April 18, 2019, 1:05pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/35 "2019-04-18T13:05:56Z")
```auto /_settings' -H 'Content-Type: application/json' -d '{ "index" : { "refresh_interval" : null, "search.idle.after" : "10000d" } }' ``` ```auto /_settings' -H 'Content-Type: application/json' -d '{ "index" : { "refresh_interval" : "1s", "search.idle.after" : "10000d" } }' ``` I have tested both, is working as it should with both settings. Should I go on 7.0.0 with `"index.search.idle.after" : "10000d"` or is `index.refresh_interval` fine too as the set value is enough real time for my use case? ---
**Author:** ![s1monw](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/s1monw/32/3637_2.png) [@s1monw](https://discuss.elastic.co/u/s1monw)\ **Post date:** [April 18, 2019, 1:07pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/36 "2019-04-18T13:07:59Z")
both are identical since setting it to `null` will reset to the default value and that is `1s`. To fix your issue you only need to set `"search.idle.after" : "10000d"` ---
**Author:** ![Nenad](https://avatars.discourse-cdn.com/v4/letter/n/13edae/32.png) [@Nenad](https://discuss.elastic.co/u/Nenad)\ **Post date:** [April 18, 2019, 1:10pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/37 "2019-04-18T13:10:27Z")
OK well, thank you for clarify. ---
**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\ **Post date:** [May 16, 2019, 1:10pm UTC](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017/38 "2019-05-16T13:10:28Z")
This topic was automatically closed 28 days after the last reply. New replies are no longer allowed. [Previous page](https://discuss.elastic.co/t/bug-elasticsearch-7-after-upgrade-from-6-7-slow-search-during-3-5-seconds-every-60-seconds/177017.md?page=1)