Profile API `time_in_nanoseconds` value higher than `took` time

[maxshortzp]

Full disclosure: I posted a similar question at https://stackoverflow.com/questions/52088298/elasticsearch-profile-api-time-in-nanoseconds-value-higher-than-took-time.

Unexpected results from Profile API

When using the Profile API I'm seeing many time_in_nanoseconds values that are higher than the took time of the whole query.

Example:

{
  "took": 109695,
   ...
  "profile": {
    "shards": [
       {
         "searches": [
           {
             "query": [
               {
                 "type": "BooleanQuery",
                 "time": "1550750.786ms",
                 "time_in_nanos": 1550750786163
                 ...
               }
             ]
           }
         ]
       }
       ...
     ]
  }
}

Regression to previous bug?

This seems similar to the bug described here:

• Profile API - took Time
• https://github.com/elastic/elasticsearch/issues/18693

However, this bug was supposed so be fixed in version 5. We're on version 5.6.

Full version information:

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

Unknowns

Is this behavior a regression? Am I misunderstanding the results of Profile API?

[maxshortzp]

This looks very similar to ElasticSearch ProfileAPI. Not sure the version on that since it didn't say.

[spinscale (Alexander Reelsen)]

the linked PR mentions 5.0.0-alpha5, so this might indeed be a new bug. Can you open an issue in the ES repo, please? Thanks a lot!

[maxshortzp]

Thanks for the response @spinscale. I've filed a bug at https://github.com/elastic/elasticsearch/issues/33489.

[maxshortzp]

Wanted to update this with the answers I got in case anyone else runs into this.

Profile timings are a result of sampling. Because they are sampled, the raw timing numbers may not be accurate for large queries.

However, these numbers can be used to compare parts of the query with other parts of the query to determine the relative expense of the respective parts.