Each first different query is slow

Lucian_Precup · October 21, 2013, 11:10am

Hello Elasticsearch and Elasticsearch users,

I encounter a strange issue with query performance. I am able to reproduce
this behavior with simple match queries, without using filters, facets or
sorts. In summary, the first query is always slow (like seconds). Then,
launching the very same query brings the expected performance (like under
300 milliseconds). Adding an additional parameter to the query (parameter
that narrow the number of results) leads to the same behavior: first query
slow, next query ok.

Here are some details:
I am using elasticsearch 0.90.1.
The index contains about 8 million documents and it has 3 gb. One shard,
zero replicas. For the queries reproducing the issue, I am using two
fields: firstname and lastname.

I first launch a match_all query with a terms_facet on lastname in order to
obtain the most commonly used names:
{
"from": 0,
"size": 0,
"query": {
"match_all": {}
},
"facets": {
"lastname": {
"terms": {
"field": "lastname",
"size": 1000
}
}
}
}

The I launch a match query with each of the 1000 names using JMeter:
{
"from": 0,
"size": 200,
"query": {
"bool": {
"must": [
{
"multi_match": {
"query": "${LASTNAME}",
"fields": [
"lastname"
]
}
}
]
}
}
}

For the first launch of each of the 1000 queries I have rather slow times
(the max is at about 11 seconds and every query takes at least a couple of
hundreds of milliseconds). Queries with names in the beginning of the list
are generally slower (because they bring more results).
For the second launch the maximum "took time" drops to 500 ms (which is
O.K. for our case) and every query is faster than it was on its first
launch.

For the third launch, I add a first name to the query. I just chose a
common name at random (say Jean - John)
{
"from": 0,
"size": 200,
"query": {
"bool": {
"must": [
{
"multi_match": {
"query": "${LASTNAME}",
"fields": [
"lastname"
]
}
},
{
"multi_match": {
"query": "jean",
"fields": [
"firstname"
]
}
}
]
}
}
}
Queries are again slow. Not as slow as the first launch but I feel like the
acceleration is just due to less results (because of the additional
parameter).
Relaunching the queries brings correct performance again (fourth launch).

To add one last thing. Relaunching the fourth launch after some server
inactivity (like over the weekend) brings up slow performance again (500ms
to 8 seconds).

Can this be related to some caching done by the file system ? Have you
encountered something similar ?

Thank you for your hints.

Best regards,
Lucian Precup

--
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.

Boaz_Leskes · October 21, 2013, 11:51am

Hi Lucian,

It does sound like you are looking at file cache issues. After the first
query, the terms list and posting lists for the top 1000 lastnames are
loaded into the file cache of the OS. The subsequent queries are then run
in memory (by the OS , as it doesn't need to go to file) and are therefore
faster. When you add the first name, you already have the lastname posting
list in memory but the first name ones need to be read from disk.

After the weekend the file cache has probably been cleared out and things
need to be read from disk again.

Do you leave enough memory for the file system cache of the OS? How much
memory does the machine have? how much is allocated to ES?

Cheers,
Boaz

On Monday, October 21, 2013 1:10:59 PM UTC+2, Lucian Precup wrote:

Hello Elasticsearch and Elasticsearch users,

I encounter a strange issue with query performance. I am able to reproduce
this behavior with simple match queries, without using filters, facets or
sorts. In summary, the first query is always slow (like seconds). Then,
launching the very same query brings the expected performance (like under
300 milliseconds). Adding an additional parameter to the query (parameter
that narrow the number of results) leads to the same behavior: first query
slow, next query ok.

Here are some details:
I am using elasticsearch 0.90.1.
The index contains about 8 million documents and it has 3 gb. One shard,
zero replicas. For the queries reproducing the issue, I am using two
fields: firstname and lastname.

I first launch a match_all query with a terms_facet on lastname in order
to obtain the most commonly used names:
{
"from": 0,
"size": 0,
"query": {
"match_all": {}
},
"facets": {
"lastname": {
"terms": {
"field": "lastname",
"size": 1000
}
}
}
}

The I launch a match query with each of the 1000 names using JMeter:
{
"from": 0,
"size": 200,
"query": {
"bool": {
"must": [
{
"multi_match": {
"query": "${LASTNAME}",
"fields": [
"lastname"
]
}
}
]
}
}
}

For the first launch of each of the 1000 queries I have rather slow times
(the max is at about 11 seconds and every query takes at least a couple of
hundreds of milliseconds). Queries with names in the beginning of the list
are generally slower (because they bring more results).
For the second launch the maximum "took time" drops to 500 ms (which is
O.K. for our case) and every query is faster than it was on its first
launch.

For the third launch, I add a first name to the query. I just chose a
common name at random (say Jean - John)
{
"from": 0,
"size": 200,
"query": {
"bool": {
"must": [
{
"multi_match": {
"query": "${LASTNAME}",
"fields": [
"lastname"
]
}
},
{
"multi_match": {
"query": "jean",
"fields": [
"firstname"
]
}
}
]
}
}
}
Queries are again slow. Not as slow as the first launch but I feel like
the acceleration is just due to less results (because of the additional
parameter).
Relaunching the queries brings correct performance again (fourth launch).

To add one last thing. Relaunching the fourth launch after some server
inactivity (like over the weekend) brings up slow performance again (500ms
to 8 seconds).

Can this be related to some caching done by the file system ? Have you
encountered something similar ?

Thank you for your hints.

Best regards,
Lucian Precup

--
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.

spinscale · October 21, 2013, 2:18pm

Hey,

it seems you have some processes running that invalidate the filesystem
cache. A very possible candidate for this is the updatedb command, which is
run daily by cron to create a small database for the locate command - but
there might be others as well.

--Alex

On Mon, Oct 21, 2013 at 1:51 PM, Boaz Leskes b.leskes@gmail.com wrote:

Hi Lucian,

It does sound like you are looking at file cache issues. After the first
query, the terms list and posting lists for the top 1000 lastnames are
loaded into the file cache of the OS. The subsequent queries are then run
in memory (by the OS , as it doesn't need to go to file) and are therefore
faster. When you add the first name, you already have the lastname posting
list in memory but the first name ones need to be read from disk.

After the weekend the file cache has probably been cleared out and things
need to be read from disk again.

Do you leave enough memory for the file system cache of the OS? How much
memory does the machine have? how much is allocated to ES?

Cheers,
Boaz

On Monday, October 21, 2013 1:10:59 PM UTC+2, Lucian Precup wrote:

Hello Elasticsearch and Elasticsearch users,

I encounter a strange issue with query performance. I am able to
reproduce this behavior with simple match queries, without using filters,
facets or sorts. In summary, the first query is always slow (like seconds).
Then, launching the very same query brings the expected performance (like
under 300 milliseconds). Adding an additional parameter to the query
(parameter that narrow the number of results) leads to the same behavior:
first query slow, next query ok.

Here are some details:
I am using elasticsearch 0.90.1.
The index contains about 8 million documents and it has 3 gb. One shard,
zero replicas. For the queries reproducing the issue, I am using two
fields: firstname and lastname.

I first launch a match_all query with a terms_facet on lastname in order
to obtain the most commonly used names:
{
"from": 0,
"size": 0,
"query": {
"match_all": {}
},
"facets": {
"lastname": {
"terms": {
"field": "lastname",
"size": 1000
}
}
}
}

The I launch a match query with each of the 1000 names using JMeter:
{
"from": 0,
"size": 200,
"query": {
"bool": {
"must": [
{
"multi_match": {
"query": "${LASTNAME}",
"fields": [
"lastname"
]
}
}
]
}
}
}

For the first launch of each of the 1000 queries I have rather slow times
(the max is at about 11 seconds and every query takes at least a couple of
hundreds of milliseconds). Queries with names in the beginning of the list
are generally slower (because they bring more results).
For the second launch the maximum "took time" drops to 500 ms (which is
O.K. for our case) and every query is faster than it was on its first
launch.

For the third launch, I add a first name to the query. I just chose a
common name at random (say Jean - John)
{
"from": 0,
"size": 200,
"query": {
"bool": {
"must": [
{
"multi_match": {
"query": "${LASTNAME}",
"fields": [
"lastname"
]
}
},
{
"multi_match": {
"query": "jean",
"fields": [
"firstname"
]
}
}
]
}
}
}
Queries are again slow. Not as slow as the first launch but I feel like
the acceleration is just due to less results (because of the additional
parameter).
Relaunching the queries brings correct performance again (fourth launch).

To add one last thing. Relaunching the fourth launch after some server
inactivity (like over the weekend) brings up slow performance again (500ms
to 8 seconds).

Can this be related to some caching done by the file system ? Have you
encountered something similar ?

Thank you for your hints.

Best regards,
Lucian Precup

--
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.

--
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.

Lucian_Precup · October 22, 2013, 1:35pm

Hello Boaz, Hello Alexander,

Thank you for your replies. Your hints make sense considering our
environments. We will launch some more tests to validate these hypothesis.
Thanks

Best regards,
Lucian

On Monday, October 21, 2013 4:18:54 PM UTC+2, Alexander Reelsen wrote:

Hey,

it seems you have some processes running that invalidate the filesystem
cache. A very possible candidate for this is the updatedb command, which is
run daily by cron to create a small database for the locate command - but
there might be others as well.

--Alex

On Mon, Oct 21, 2013 at 1:51 PM, Boaz Leskes <b.le...@gmail.com<javascript:>

wrote:

Hi Lucian,

It does sound like you are looking at file cache issues. After the first
query, the terms list and posting lists for the top 1000 lastnames are
loaded into the file cache of the OS. The subsequent queries are then run
in memory (by the OS , as it doesn't need to go to file) and are therefore
faster. When you add the first name, you already have the lastname posting
list in memory but the first name ones need to be read from disk.

After the weekend the file cache has probably been cleared out and things
need to be read from disk again.

Do you leave enough memory for the file system cache of the OS? How much
memory does the machine have? how much is allocated to ES?

Cheers,
Boaz

On Monday, October 21, 2013 1:10:59 PM UTC+2, Lucian Precup wrote:

Hello Elasticsearch and Elasticsearch users,

I encounter a strange issue with query performance. I am able to
reproduce this behavior with simple match queries, without using filters,
facets or sorts. In summary, the first query is always slow (like seconds).
Then, launching the very same query brings the expected performance (like
under 300 milliseconds). Adding an additional parameter to the query
(parameter that narrow the number of results) leads to the same behavior:
first query slow, next query ok.

Here are some details:
I am using elasticsearch 0.90.1.
The index contains about 8 million documents and it has 3 gb. One shard,
zero replicas. For the queries reproducing the issue, I am using two
fields: firstname and lastname.

I first launch a match_all query with a terms_facet on lastname in order
to obtain the most commonly used names:
{
"from": 0,
"size": 0,
"query": {
"match_all": {}
},
"facets": {
"lastname": {
"terms": {
"field": "lastname",
"size": 1000
}
}
}
}

The I launch a match query with each of the 1000 names using JMeter:
{
"from": 0,
"size": 200,
"query": {
"bool": {
"must": [
{
"multi_match": {
"query": "${LASTNAME}",
"fields": [
"lastname"
]
}
}
]
}
}
}

For the first launch of each of the 1000 queries I have rather slow
times (the max is at about 11 seconds and every query takes at least a
couple of hundreds of milliseconds). Queries with names in the beginning of
the list are generally slower (because they bring more results).
For the second launch the maximum "took time" drops to 500 ms (which is
O.K. for our case) and every query is faster than it was on its first
launch.

For the third launch, I add a first name to the query. I just chose a
common name at random (say Jean - John)
{
"from": 0,
"size": 200,
"query": {
"bool": {
"must": [
{
"multi_match": {
"query": "${LASTNAME}",
"fields": [
"lastname"
]
}
},
{
"multi_match": {
"query": "jean",
"fields": [
"firstname"
]
}
}
]
}
}
}
Queries are again slow. Not as slow as the first launch but I feel like
the acceleration is just due to less results (because of the additional
parameter).
Relaunching the queries brings correct performance again (fourth launch).

To add one last thing. Relaunching the fourth launch after some server
inactivity (like over the weekend) brings up slow performance again (500ms
to 8 seconds).

Can this be related to some caching done by the file system ? Have you
encountered something similar ?

Thank you for your hints.

Best regards,
Lucian Precup

--
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 elasticsearc...@googlegroups.com <javascript:>.
For more options, visit https://groups.google.com/groups/opt_out.

--
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.