took time value is much larger than that calculated by Profile API

[owenericsson]

Describe the feature: whole time calculation is wrong with took time value

Elasticsearch version (bin/elasticsearch --version): 5.3.2

Plugins installed: []

JVM version (java -version): JDK 1.8 update 132

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

Description of the problem including expected versus actual behavior:
i would like to diagnostic for a query with a term aggregation, and then i added a profile:true to the query. however i see the time took 500+ms while i found out that the maximum time of a shard is just ~10ms.
would you some one please give me some hint that where the 400+ms take place

Provide logs (if relevant):
see attachment, for security reason i skipped the true result and renamed the index name and field name.

result.txt

[bleskes]

The profile api currently only profiles that query and aggregation parts. It doesn't measure the fetch phase nor the network overhead. I suggest you look at those.

IMO I think there are two things to do here:

1. Potentially add a profiler for the fetch phase.
2. Document the above to avoid confusion.

@owenericsson if you have any more questions please open up a thread on discuss.elastic.co and we can dive deeper. We keep github for bugs and features requests.

[elasticmachine]

Pinging @elastic/es-search-aggs

[owenericsson]

hi @bleskes ,
thanks for the reply, and also apologize for posting in the wrong place.

back to this problem

1. i have set the size to 0, so there shouldn't be the fetch overhead.
2. when i remove the "aggs" part, the time cost back to a normal level (< 100ms). So i am sure that the overhead must be from the aggs

BTW. the field type of the term aggregation i used is 'keyword', and do you think this overhead is from the GlobalOrdinals ? anyway i think it is very unlikely this overhead is from the network.

[bleskes]

OK, that changes things (although my comments are still valid in general). I will defer for someone from the search area to pick this up.

[jpountz]

Most likely most execution time is taken by something which is not measured by the profile, like the time it took to build global ordinals, time spent in the queue, time spent merging shard responses on the coordinating node, etc. I agree we shoud at least document this.

[owenericsson]

one more thing need attention
I created my index with 11 shards, by using a routing key which means for the Search above, only one shard owns all the result data.

[cbuescher]

Closing this with adding documentation in #36252, some other improvements to the way the Profile API works are tracked in #21073