'took' field on the ES response

[yiliang]

Hi,
I have a question on the 'took' filed from ES response. I run a profile request to one specific index And get following response(partial).

{
"took": 944,
"timed_out": false,
"_shards": {
"total": 5,
"successful": 5,
"skipped": 0,
"failed": 0
},
"hits": {.... },
"profile": {
"shards": [
{
"id": "[-xxx][xxx][0]",
"searches": [
{
"query": [
{
"type": "BooleanQuery",
"description": "",
"time": "1048.008013ms",
"time_in_nanos": 1048008013,
"breakdown": {
"score": 271966,
"build_scorer_count": 10,
"match_count": 477947,
"create_weight": 171001,
"next_doc": 660148889,
"match": 386081410,
"create_weight_count": 1,
"next_doc_count": 477991,
"score_count": 2278,
"build_scorer": 376520,
"advance": 0,
"advance_count": 0
},
"children": [ ]
....
},

You can see that time on one shard is 1048.008013ms, but the overall 'took' field only takes 944ms.
I just wonder this 'took' filed is not so accurate. It should larger then time spent on one shard.

Thanks

[yiliang]

@Igor_Motov, Sorry to ping you, but I saw you reply similar message. Could you help to take a look at above topic. I just wonder why the processing time on one shard larger than the time on 'took' field, which might be the processing time for whole index. Thanks

[polyfractal (Zachary Tong)]

Hi @yiliang. I'm not entirely sure what's going on here, but I suspect it's a caching issue. Unfortunately, profiled queries are eligible for request caching. So the first time you try to profile, it takes a long time and the response is cached. The second time you profile, the response is served from the cache which gives a small(er) took time... but the profile response itself is from before when it was slower.

It's a bug... we shouldn't let profiled queries enter the cache. You can fix this issue by clearing the cache manually before running the profile.

There's an issue on github tracking this, if you want to watch it: https://github.com/elastic/elasticsearch/issues/29024