Profile API says that Lucene subquery took longer than whole query took time

[maxshortzp]

Elasticsearch version (bin/elasticsearch --version):

{
  "cluster_name" : "elasticsearch",
  "cluster_uuid" : "rIivUZ5hRIiZ3kNs2eWBHw",
  "version" : {
    "number" : "5.6.0",
    "build_hash" : "781a835",
    "build_date" : "2017-09-07T03:09:58.087Z",
    "build_snapshot" : false,
    "lucene_version" : "6.6.0"
  },
}

Plugins installed: []

JVM version (java -version):

java version "1.8.0_181"
Java(TM) SE Runtime Environment (build 1.8.0_181-b13)
Java HotSpot(TM) 64-Bit Server VM (build 25.181-b13, mixed mode)

OS version (uname -a if on a Unix-like system):

Linux 4.4.0-47-generic #68~14.04.1-Ubuntu SMP Wed Oct 26 19:42:11 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

(Ubuntu 16.04)

Description of the problem including expected versus actual behavior:

Note: I'm assuming that both took and the Lucene BooleanQuery time are "wall clock" time based on the ElasticSearch docs.

The Profile API says that the time for an individual Lucene BooleanQuery on a shard is greater than the took time of the total query.

This seems impossible as the BooleanQuery is part of the larger query (so its time should be <=).

It seems like the problem is probably in the computation of the Lucene query times. On the queries I've looked at, the took time while the time on Lucene subqueries are much higher than "reasonable." For example, the original (much more verbose) query I was profiling took about 2 minutes to complete (which was matched by the curl output) while one of the BooleanQuery times said it took ~25 minutes (it did not).

Steps to reproduce:

I am able to consistently reproduce the problem on our production cluster:

• Query: https://gist.github.com/maxshortzp/d27fb0f4b66ea06dc7185089be16c13d
• Profile result: https://gist.github.com/maxshortzp/46e94e9dd75510a21535c2f02586f2f0
• Relevant portion of mapping "person_location_country":{"type":"keyword"}

So far, I haven't been able to reproduce the problem in a standalone Vagrant virtual machine. Any pointers for making that happen are appreciated. If I figure it out, I'll update this bug.

Also happy to provide additional information if necessary.

Provide logs (if relevant):

Can't think of any relevant logs but happy to provide if necessary.

[jimczi]

The profiling is done by checking the relative time of each function call in the query. We use System.nanoTime to measure the time and this adds a significant overhead to the performance of the query. In order to mitigate the performance impact we've decided to sample the profiling for each function call so the final timing is an approximation (starting in 5.6.0):
#25772
The took time is not an approximation so it is possible that the profile time returns a value greater than the total time of the query. For small queries the difference should be small but it can get bigger for long running query that returns millions of documents. This shouldn't be an issue though because the comparison should be done with other timings in the profiling in order to give you an estimate of the cost of each part of the query.

[elasticmachine]

Pinging @elastic/es-search-aggs

[polyfractal]

++ to what @jimczi said :)

Also note that there is an open bug where profiled requests can interact poorly with caching. That can lead to confusing/surprising combinations of took and profile timing: #29024

[maxshortzp]

Thanks for everyone's help.

It sounds like even though the profile times may not match actual times (due to sampling) I can still compare them with each other to understand what parts of the query are costly.