# Huge variance in query time **URL:** \ **Category:** Elasticsearch\ **Created:** [January 12, 2012, 3:42pm UTC](https://discuss.elastic.co/t/huge-variance-in-query-time/6364 "2012-01-12T15:42:18Z")\ **Posts on this page:** 6\ **Page:** 1
**Author:** ![Mike\_Peters](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/mike_peters/32/3022_2.png) [@Mike\_Peters](https://discuss.elastic.co/u/Mike_Peters)\ **Post date:** [January 12, 2012, 3:42pm UTC](https://discuss.elastic.co/t/huge-variance-in-query-time/6364/1 "2012-01-12T15:42:18Z")
Hi, I'm trying to understand why queries some time respond instantly and some time take a very long time to complete. No major load on elasticsearch, using 6 servers, 3 shards. We run the same exact query in a loop and while it's usually very fast, every minute or so, the query time jumps to above 5 seconds. Any ideas what could possibly be causing this? See below example of running the same query twice, 1 second apart. First time it's fast, then it gets slow, then fast again. curl -XGET "[http://localhost:5004/spi/storeproducts/\_search](http://localhost:5004/spi/storeproducts/_search)? pretty=true" -d '{"from":"0","size":"20","sort":{"\_score":""},"query": {"filtered":{"query":{"query\_string": {"query":"ppc\*","phraseSlop":"0","useDisMax":"false","fields": ["name.s^20","emailaddress.s^15","emailaddress\_aliases.s^10","\_all"]}},"filter": {"and":[{"term":{"\_account\_id":"1429"}}]}}}}' { "took" : 45, "timed\_out" : false, "\_shards" : { "total" : 3, "successful" : 3, "failed" : 0 }, "hits" : { "total" : 6, "max\_score" : 0.03996804, -- curl -XGET "[http://localhost:5004/spi/storeproducts/\_search](http://localhost:5004/spi/storeproducts/_search)? pretty=true" -d '{"from":"0","size":"20","sort":{"\_score":""},"query": {"filtered":{"query":{"query\_string": {"query":"ppc\*","phraseSlop":"0","useDisMax":"fase","fields": ["name.s^20","emailaddress.s^15","emailaddress\_aliases.s^10","\_all"]}},"filter": {"and":[{"term":{"\_account\_id":"1429"}}]}}}}' { "took" : 5845, "timed\_out" : false, "\_shards" : { "total" : 3, "successful" : 3, "failed" : 0 }, "hits" : { "total" : 6, "max\_score" : 0.03996804, ---
**Author:** ![Karussell1](https://avatars.discourse-cdn.com/v4/letter/k/50afbb/32.png) [@Karussell1](https://discuss.elastic.co/u/Karussell1)\ **Post date:** [January 13, 2012, 10:01am UTC](https://discuss.elastic.co/t/huge-variance-in-query-time/6364/2 "2012-01-13T10:01:05Z")
> Any ideas what could possibly be causing this? garbage collection? > We run the same exact query in a loop which features do you use in the query? how many queries / second and how many RAM do you have? Peter. On 12 Jan., 16:42, Mike Peters [m...@softwareprojects.com](mailto:m...@softwareprojects.com) wrote: > Hi, > > I'm trying to understand why queries some time respond instantly and > some time take a very long time to complete. > > No major load on elasticsearch, using 6 servers, 3 shards. > > We run the same exact query in a loop and while it's usually very > fast, every minute or so, the query time jumps to above 5 seconds. > > Any ideas what could possibly be causing this? > > See below example of running the same query twice, 1 second apart. > First time it's fast, then it gets slow, then fast again. > > curl -XGET "[http://localhost:5004/spi/storeproducts/\_search](http://localhost:5004/spi/storeproducts/_search)? > pretty=true" -d '{"from":"0","size":"20","sort":{"\_score":""},"query": > {"filtered":{"query":{"query\_string": > {"query":"ppc\*","phraseSlop":"0","useDisMax":"false","fields": > ["name.s^20","emailaddress.s^15","emailaddress\_aliases.s^10","\_all"]}},"fil ter": > {"and":[{"term":{"\_account\_id":"1429"}}]}}}}' > { > "took" : 45, > "timed\_out" : false, > "\_shards" : { > "total" : 3, > "successful" : 3, > "failed" : 0 > }, > "hits" : { > "total" : 6, > "max\_score" : 0.03996804, > > -- > > curl -XGET "[http://localhost:5004/spi/storeproducts/\_search](http://localhost:5004/spi/storeproducts/_search)? > pretty=true" -d '{"from":"0","size":"20","sort":{"\_score":""},"query": > {"filtered":{"query":{"query\_string": > {"query":"ppc\*","phraseSlop":"0","useDisMax":"fase","fields": > ["name.s^20","emailaddress.s^15","emailaddress\_aliases.s^10","\_all"]}},"fil ter": > {"and":[{"term":{"\_account\_id":"1429"}}]}}}}' > { > "took" : 5845, > "timed\_out" : false, > "\_shards" : { > "total" : 3, > "successful" : 3, > "failed" : 0 > }, > "hits" : { > "total" : 6, > "max\_score" : 0.03996804, ---
**Author:** ![kimchy](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kimchy/32/44952_2.png) [@kimchy](https://discuss.elastic.co/u/kimchy)\ **Post date:** [January 14, 2012, 4:04pm UTC](https://discuss.elastic.co/t/huge-variance-in-query-time/6364/3 "2012-01-14T16:04:30Z")
Another option is file system cache. You are using a prefix query that can be quite heavy to execute, and its much more affected by file system cache compared to other queries. Start by monitoring memory usage and work from there. On Fri, Jan 13, 2012 at 12:01 PM, Karussell [tableyourtime@googlemail.com](mailto:tableyourtime@googlemail.com)wrote: > > Any ideas what could possibly be causing this? > > garbage collection? > > > We run the same exact query in a loop > > which features do you use in the query? how many queries / second and > how many RAM do you have? > > Peter. > > On 12 Jan., 16:42, Mike Peters [m...@softwareprojects.com](mailto:m...@softwareprojects.com) wrote: > > > Hi, > > > > I'm trying to understand why queries some time respond instantly and > > some time take a very long time to complete. > > > > No major load on elasticsearch, using 6 servers, 3 shards. > > > > We run the same exact query in a loop and while it's usually very > > fast, every minute or so, the query time jumps to above 5 seconds. > > > > Any ideas what could possibly be causing this? > > > > See below example of running the same query twice, 1 second apart. > > First time it's fast, then it gets slow, then fast again. > > > > curl -XGET "[http://localhost:5004/spi/storeproducts/\_search](http://localhost:5004/spi/storeproducts/_search)? > > pretty=true" -d '{"from":"0","size":"20","sort":{"\_score":""},"query": > > {"filtered":{"query":{"query\_string": > > {"query":"ppc\*","phraseSlop":"0","useDisMax":"false","fields": > > ["name.s^20","emailaddress.s^15","emailaddress\_aliases.s^10","\_all"]}},"fil > ter": > > > {"and":[{"term":{"\_account\_id":"1429"}}]}}}}' > > { > > "took" : 45, > > "timed\_out" : false, > > "\_shards" : { > > "total" : 3, > > "successful" : 3, > > "failed" : 0 > > }, > > "hits" : { > > "total" : 6, > > "max\_score" : 0.03996804, > > > > -- > > > > curl -XGET "[http://localhost:5004/spi/storeproducts/\_search](http://localhost:5004/spi/storeproducts/_search)? > > pretty=true" -d '{"from":"0","size":"20","sort":{"\_score":""},"query": > > {"filtered":{"query":{"query\_string": > > {"query":"ppc\*","phraseSlop":"0","useDisMax":"fase","fields": > > ["name.s^20","emailaddress.s^15","emailaddress\_aliases.s^10","\_all"]}},"fil > ter": > > > {"and":[{"term":{"\_account\_id":"1429"}}]}}}}' > > { > > "took" : 5845, > > "timed\_out" : false, > > "\_shards" : { > > "total" : 3, > > "successful" : 3, > > "failed" : 0 > > }, > > "hits" : { > > "total" : 6, > > "max\_score" : 0.03996804, ---
**Author:** ![Mike\_Peters](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/mike_peters/32/3022_2.png) [@Mike\_Peters](https://discuss.elastic.co/u/Mike_Peters)\ **Post date:** [January 17, 2012, 3:35pm UTC](https://discuss.elastic.co/t/huge-variance-in-query-time/6364/4 "2012-01-17T15:35:42Z")
We've eliminated file-system-cache as the issue (iostat is good) and memory stays stable at 20% utilization Load is very low too Any other ideas? Any way to enable a verbose debug log, so that we can see where elasticsearch is spending the time while processing these type of queries? Mike On Jan 13, 5:01 am, Karussell [tableyourt...@googlemail.com](mailto:tableyourt...@googlemail.com) wrote: > > Any ideas what could possibly be causing this? > > garbage collection? > > > We run the same exact query in a loop > > which features do you use in the query? how many queries / second and > how many RAM do you have? > > Peter. > > On 12 Jan., 16:42,MikePeters[m...@softwareprojects.com](mailto:m...@softwareprojects.com) wrote: > > > Hi, > > > I'm trying to understand why queries some time respond instantly and > > some time take a very long time to complete. > > > No major load on elasticsearch, using 6 servers, 3 shards. > > > We run the same exact query in a loop and while it's usually very > > fast, every minute or so, the query time jumps to above 5 seconds. > > > Any ideas what could possibly be causing this? > > > See below example of running the same query twice, 1 second apart. > > First time it's fast, then it gets slow, then fast again. > > > curl -XGET "[http://localhost:5004/spi/storeproducts/\_search](http://localhost:5004/spi/storeproducts/_search)? > > pretty=true" -d '{"from":"0","size":"20","sort":{"\_score":""},"query": > > {"filtered":{"query":{"query\_string": > > {"query":"ppc\*","phraseSlop":"0","useDisMax":"false","fields": > > ["name.s^20","emailaddress.s^15","emailaddress\_aliases.s^10","\_all"]}},"fil ter": > > {"and":[{"term":{"\_account\_id":"1429"}}]}}}}' > > { > > "took" : 45, > > "timed\_out" : false, > > "\_shards" : { > > "total" : 3, > > "successful" : 3, > > "failed" : 0 > > }, > > "hits" : { > > "total" : 6, > > "max\_score" : 0.03996804, > > > -- > > > curl -XGET "[http://localhost:5004/spi/storeproducts/\_search](http://localhost:5004/spi/storeproducts/_search)? > > pretty=true" -d '{"from":"0","size":"20","sort":{"\_score":""},"query": > > {"filtered":{"query":{"query\_string": > > {"query":"ppc\*","phraseSlop":"0","useDisMax":"fase","fields": > > ["name.s^20","emailaddress.s^15","emailaddress\_aliases.s^10","\_all"]}},"fil ter": > > {"and":[{"term":{"\_account\_id":"1429"}}]}}}}' > > { > > "took" : 5845, > > "timed\_out" : false, > > "\_shards" : { > > "total" : 3, > > "successful" : 3, > > "failed" : 0 > > }, > > "hits" : { > > "total" : 6, > > "max\_score" : 0.03996804, ---
**Author:** ![kimchy](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/kimchy/32/44952_2.png) [@kimchy](https://discuss.elastic.co/u/kimchy)\ **Post date:** [January 18, 2012, 8:54pm UTC](https://discuss.elastic.co/t/huge-variance-in-query-time/6364/5 "2012-01-18T20:54:04Z")
What are you running on? This reminds me of the problem we had once on AWS with Ubuntu 10.04, where suddenly a GC will take a really long time, without any user time spent on it, which ended up a problem with AWS and Ubuntu. I suggest you enable GC logging (see elaticsearch.in.sh) and see what happens during the time that the query takes time. On Tue, Jan 17, 2012 at 5:35 PM, Mike Peters [mike@softwareprojects.com](mailto:mike@softwareprojects.com)wrote: > We've eliminated file-system-cache as the issue (iostat is good) and > memory stays stable at 20% utilization > > Load is very low too > > Any other ideas? > > Any way to enable a verbose debug log, so that we can see where > elasticsearch is spending the time while processing these type of > queries? > > Mike > > On Jan 13, 5:01 am, Karussell [tableyourt...@googlemail.com](mailto:tableyourt...@googlemail.com) wrote: > > > > Any ideas what could possibly be causing this? > > > > garbage collection? > > > > > We run the same exact query in a loop > > > > which features do you use in the query? how many queries / second and > > how many RAM do you have? > > > > Peter. > > > > On 12 Jan., 16:42,MikePeters[m...@softwareprojects.com](mailto:m...@softwareprojects.com) wrote: > > > > > Hi, > > > > > I'm trying to understand why queries some time respond instantly and > > > some time take a very long time to complete. > > > > > No major load on elasticsearch, using 6 servers, 3 shards. > > > > > We run the same exact query in a loop and while it's usually very > > > fast, every minute or so, the query time jumps to above 5 seconds. > > > > > Any ideas what could possibly be causing this? > > > > > See below example of running the same query twice, 1 second apart. > > > First time it's fast, then it gets slow, then fast again. > > > > > curl -XGET "[http://localhost:5004/spi/storeproducts/\_search](http://localhost:5004/spi/storeproducts/_search)? > > > pretty=true" -d '{"from":"0","size":"20","sort":{"\_score":""},"query": > > > {"filtered":{"query":{"query\_string": > > > {"query":"ppc\*","phraseSlop":"0","useDisMax":"false","fields": > > ["name.s^20","emailaddress.s^15","emailaddress\_aliases.s^10","\_all"]}},"fil > ter": > > > > {"and":[{"term":{"\_account\_id":"1429"}}]}}}}' > > > { > > > "took" : 45, > > > "timed\_out" : false, > > > "\_shards" : { > > > "total" : 3, > > > "successful" : 3, > > > "failed" : 0 > > > }, > > > "hits" : { > > > "total" : 6, > > > "max\_score" : 0.03996804, > > > > > -- > > > > > curl -XGET "[http://localhost:5004/spi/storeproducts/\_search](http://localhost:5004/spi/storeproducts/_search)? > > > pretty=true" -d '{"from":"0","size":"20","sort":{"\_score":""},"query": > > > {"filtered":{"query":{"query\_string": > > > {"query":"ppc\*","phraseSlop":"0","useDisMax":"fase","fields": > > ["name.s^20","emailaddress.s^15","emailaddress\_aliases.s^10","\_all"]}},"fil > ter": > > > > {"and":[{"term":{"\_account\_id":"1429"}}]}}}}' > > > { > > > "took" : 5845, > > > "timed\_out" : false, > > > "\_shards" : { > > > "total" : 3, > > > "successful" : 3, > > > "failed" : 0 > > > }, > > > "hits" : { > > > "total" : 6, > > > "max\_score" : 0.03996804, ---
**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\ **Post date:** [July 6, 2017, 3:42am UTC](https://discuss.elastic.co/t/huge-variance-in-query-time/6364/6 "2017-07-06T03:42:17Z")