terminate_after uses heuristic hits value instead of actual

[travisby]

tl;dr:

I believe there's a regression with using terminate_after in searches from es6->7 because of the changes to track_total_hits and hits.total.value now being a heuristical value.

---

Hello!

I've been looking into why kibana filter autocomplete has been so slow after our transition from an es/logstash/kibana-6.4 stack to an es/logstash/kibana-7.6 stack. We had also made some sharding decisions that were different so we weren't sure if it was us or an ES regression.

I've reverse-engineered the query kibana sends to roughly be:

POST /index-pattern-*/_search?request_cache=false
{
  "size": 0,
  "timeout": "1000ms",
  "terminate_after": "100000",
  "query": {
    "bool": {
      "filter": []
    }
  },
  "aggs": {
    "suggestions": {
      "terms": {
        "field": "<fieldname>",
        "include": ".*",
        "execution_hint": "map",
        "shard_size": 10
      }
    }
  }
}

In our case, index-pattern is something like 30 indices. In 6 it's 750 shards and 7 220ish, and is a keyword field where everything is ~10 characters (this is all the same data that we've cloned between the two)

With "profile": true we were able to get some interesting results in the head of the request:

in elasticsearch6:

{
  "took": 4034,
  "timed_out": false,
  "terminated_early": true,
  "num_reduce_phases": 2,
  "_shards": {
    "total": 751,
    "successful": 751,
    "skipped": 0,
    "failed": 0
  },
  "hits": {
    "total": 75100000,
    "max_score": 0,
    "hits": []
  },

in es7:

{
  "took" : 17771,
  "timed_out" : true,
  "terminated_early" : false,
  "_shards" : {
    "total" : 228,
    "successful" : 228,
    "skipped" : 0,
    "failed" : 0
  },
  "hits" : {
    "total" : {
      "value" : 10000,
      "relation" : "gte"
    },
    "max_score" : null,
    "hits" : [ ]
  },

So, we've taken much longer and we're timing out instead of terminating early, and that's leading to us taking 4x longer. We even noticed individual profiles are having us reading one shard taking ~seconds. I'm surprised, and would have expected that we should have been able to read each individual shard at roughly the same speed (thus, terminating_after happening), even if our concurrency was down.

The hits.total.value only being 10k instead of something like terminate_after * num_shards seemed suspect.

I wanted to see if we were getting anywhere near the same results, and added "track_total_hits": true, to our query. Hopefully with this we can get records/s from each shard and know exactly where our bottleneck is.

{
  "took" : 1761,
  "timed_out" : false,
  "terminated_early" : true,
  "_shards" : {
    "total" : 228,
    "successful" : 228,
    "skipped" : 0,
    "failed" : 0
  },
  "hits" : {
    "total" : {
      "value" : 21095801,
      "relation" : "eq"
    },
    "max_score" : null,
    "hits" : [ ]
  },

!!!! that was a lot faster! And we're terminating_early now. the only change was we added track_total_hits: true to our query

My theory is that the circuit breaker for terminate_after is using the heuristical value, which now stops counting after 10k, and ends up searching the whole shard instead of respecting terminate_after.

[elasticmachine]

Pinging @elastic/es-search (:Search/Search)

[jimczi]

Are you sure of the timing difference ? What happens if you run the same query several times, are you still seing a 10x diff ? That shouldn't be the case since you have an aggregation in your request so we should evaluate the same number of docs no matter what the value of track_total_hits is. I also don't think that your pr changes anything #57772, the handling of terminate_after is done here and we set the forceTermination to true.
So something is odd in your reproduction, can you share the entire boolean query that you're running ?

[travisby]

I still see roughly a 10x diff even after a few reruns.

The boolean query is empty. I believe that's the actual query kibana runs to search for its autocomplete.

Our non-redacted query that reproduces:

POST /*apps-*/_search?request_cache=false
{
  "size": 0,
  "timeout": "1000ms",
  "terminate_after": "100000",
  "query": {
    "bool": {
      "filter": []
    }
  },
  "aggs": {
    "suggestions": {
      "terms": {
        "field": "app.keyword",
        "include": ".*",
        "execution_hint": "map",
        "shard_size": 10
      }
    }
  }
}

And

POST /*apps-*/_search?request_cache=false
{
  "size": 0,
  "timeout": "1000ms",
  "terminate_after": "100000",
  "track_total_hits": true,
  "query": {
    "bool": {
      "filter": []
    }
  },
  "aggs": {
    "suggestions": {
      "terms": {
        "field": "app.keyword",
        "include": ".*",
        "execution_hint": "map",
        "shard_size": 10
      }
    }
  }
}

For each query, I fired off three requests serially (~5s downtime in between or so, human speed)
And the timings we received were:

first query: 24147ms, 21307ms, 23462ms all with terminated_early: false
second query: 3772ms, 3822ms, 1361ms

(So, not quite 10x but close enough)

[travisby]

For #57772 I included the whole reproduction (although there isn't any interesting timing difference since the sample size is so small, I think it's helpful to look at the timed_out vs terminated_after results and how they change).

After looking at the LOC you pointed out I'm.. surprised that my fix works, but the results seem to show the fix. I'll try to dig in and see why a bit more

[jimczi]

Thanks @travisby, I was able to reproduce the issue and opened a pr for the fix. Your assumption is correct, terminate_after is not handled correctly on requests that set the size to 0 and track_total_hits to a value smaller than terminate_after. In such case we early terminate the tracking of total hits but that also removes the checks for terminate_after.
As you already figured out, the workaround until the fix is released is to set track_total_hits to true in the search request.