# Profile API \`time\_in\_nanoseconds\` value higher than \`took\` time

**URL:** <https://discuss.elastic.co/t/profile-api-time-in-nanoseconds-value-higher-than-took-time/146748>\
**Category:** Elasticsearch\
**Created:** [August 30, 2018, 4:50pm UTC](https://discuss.elastic.co/t/profile-api-time-in-nanoseconds-value-higher-than-took-time/146748 "2018-08-30T16:50:43Z")\
**Posts on this page:** 6\
**Page:** 1

<div class="post-metadata">

**Author:** ![maxshortzp](https://avatars.discourse-cdn.com/v4/letter/m/ce73a5/32.png) [@maxshortzp](https://discuss.elastic.co/u/maxshortzp)\
**Post date:** [August 30, 2018, 4:50pm UTC](https://discuss.elastic.co/t/profile-api-time-in-nanoseconds-value-higher-than-took-time/146748/1 "2018-08-30T16:50:43Z")

</div>

Full disclosure: I posted a similar question at [https://stackoverflow.com/questions/52088298/elasticsearch-profile-api-time-in-nanoseconds-value-higher-than-took-time](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:

```auto
{
  "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://discuss.elastic.co/t/profile-api-took-time/56776)
- [https://github.com/elastic/elasticsearch/issues/18693](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:

```auto
"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?

---

<div class="post-metadata">

**Author:** ![maxshortzp](https://avatars.discourse-cdn.com/v4/letter/m/ce73a5/32.png) [@maxshortzp](https://discuss.elastic.co/u/maxshortzp)\
**Post date:** [September 4, 2018, 1:05am UTC](https://discuss.elastic.co/t/profile-api-time-in-nanoseconds-value-higher-than-took-time/146748/2 "2018-09-04T01:05:36Z")

</div>

This looks very similar to [ElasticSearch ProfileAPI](https://discuss.elastic.co/t/elasticsearch-profileapi/75817/3). Not sure the version on that since it didn't say.

---

<div class="post-metadata">

**Author:** ![spinscale](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/spinscale/32/25011_2.png) [@spinscale](https://discuss.elastic.co/u/spinscale)\
**Post date:** [September 4, 2018, 8:12am UTC](https://discuss.elastic.co/t/profile-api-time-in-nanoseconds-value-higher-than-took-time/146748/3 "2018-09-04T08:12:42Z")

</div>

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!

---

<div class="post-metadata">

**Author:** ![maxshortzp](https://avatars.discourse-cdn.com/v4/letter/m/ce73a5/32.png) [@maxshortzp](https://discuss.elastic.co/u/maxshortzp)\
**Post date:** [September 7, 2018, 1:35am UTC](https://discuss.elastic.co/t/profile-api-time-in-nanoseconds-value-higher-than-took-time/146748/4 "2018-09-07T01:35:23Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![maxshortzp](https://avatars.discourse-cdn.com/v4/letter/m/ce73a5/32.png) [@maxshortzp](https://discuss.elastic.co/u/maxshortzp)\
**Post date:** [September 7, 2018, 5:21pm UTC](https://discuss.elastic.co/t/profile-api-time-in-nanoseconds-value-higher-than-took-time/146748/5 "2018-09-07T17:21:00Z")

</div>

Wanted to update this with [the answers I got](https://github.com/elastic/elasticsearch/issues/33489) 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.

---

<div class="post-metadata">

**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\
**Post date:** [October 5, 2018, 5:21pm UTC](https://discuss.elastic.co/t/profile-api-time-in-nanoseconds-value-higher-than-took-time/146748/6 "2018-10-05T17:21:05Z")

</div>

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.