Query efficiency (kibana/time based patterns)

Elastic Stack Elasticsearch
1

avencar posted a very good question, that is exactly what we're seeing. I'll quote
here:

Hi Matthew,

I appreciate the response. We do have a time filter field name selected for the index pattern. Also, we have a large number of nodes and data, each of which is carrying a heavy burden (> 1000 active shards / node). I know we're pushing the limits here, but it still bothers me that Kibana isn't restricting the time-based indices it's searching over when we know the data is only contained within those indices.

My main question is why was this feature removed to begin with? More specifically, what changes were made in elasticsearch to make querying over all indices/shards so efficient compared to elastic v2? It seems like we'd still have to iterate over all documents to see if it falls within the requested time range.

Thanks again!

We're running 6.7.1, we have a total of 42 nodes of various types. We currently have below 300 shards per node.

The issue is that too many shards are being hit with these queries. If we do a search for the last 15 minutes, only one index should be hit, not everything that matches the pattern.

And no, we can't turn on the slow query log at the level where it catches everything. We already know this is happening to every query run by Kibana.

(If we use the api, we can duplicate the issue by using log_*. log_2019.09.01 works as expected.)

2

nevermind - typo

The questions in the first post stand.

3

I moved this to the elasticsearch forum since you're describing a query performance problem.

Can you post your query and provide the mapping definition for a given index?

4

Hello Dave!
By default we run a pre-filter phase to determine if an index contains data matching your time filter, but only if you hit more than 128 shards. Is your search request hitting more than 128 shards?

If yes, your response should look something like this. Notice the skipped count:

{
  "took" : 20,
  "timed_out" : false,
  "_shards" : {
    "total" : 129,
    "successful" : 129,
    "skipped" : 128,
    "failed" : 0
  }

Unfortunately this limit is not configurable in kibana. So let me how many shards you hit and then we can go from there and try to find a solution.

1 Like
5

I forgot to mention that you can at least test this by changing the limit with a request in Devtools using the APIs. If a query like this works, then we definitely know what the issue is

GET log_*/_search?pre_filter_shard_size=1
{
  "query": {
    "range": {
      "@timestamp": {
        "gte": "now-15m"
      }
    }
  }
}```
6

It is every query generated by kibana.

And no, it won't let me attach non-image files. Here's the first bit:

{
"log_syslog-2019.09.03": {
"mappings": {
"doc": {
"dynamic_templates": [
{
"string_fields": {
"mapping": {
"doc_values": true,
"index": "true",
"type": "keyword"
},
"match": "*",
"match_mapping_type": "string"
}
}
],
"properties": {
"@timestamp": {
"type": "date"
},
"@version": {
"type": "integer"
},
"beat": {
"properties": {
"hostname": {
"type": "keyword"
},
"name": {
"type": "keyword"
},
"timezone": {
"type": "keyword"
},
"version": {
"type": "keyword"
}
}
},
"category": {
"type": "keyword"
},

7

Kibana uses index patterns, so yes, we're hitting more than 128 shards.

And we get things like this:

"took": 5894,
"timed_out": false,
"_shards": {
"total": 3090,
"successful": 3090,
"skipped": 2775,
"failed": 0
},

We can duplicate the issue via the API, so it's not just Kibana. If we do a dated search, it's 3-5 times faster than using the index pattern. Since our users use Kibana, that's what we're focusing on.

It shouldn't add that much overhead to check which indices contain the time range. It should be cached somewhere, actually. (if this was a user defined field, then yes, it would make sense).

As it is, doing a global search for just the last 15 minutes causes the kibana elasticsearch plugin to time out, causing kibana to restart it, which takes that entire kibana node out for about 10 minutes.

8

The old method where Kibana determined indices to query based on the index name was quite efficient but had a number of limitations.

  • The link between the index name and the timestamp in the documents had to rely on a single set field, @timestamp. This meant that all indices always had to be queried if the index pattern was based on any other timestamp field.
  • It relies on the application(s) indexing into Elasticsearch to set the index name correctly based on the '@timestamp' field, which may not always be guarantees unless Beats or Logstash is used.
  • It does not with more flexible indexing schemes, e.g. rollover.

I therefore think a more flexible solution is required. Caching the min and max value for date fields in each index, probably in the cluster state, would make it a lot faster to determine exactly which indices that need to be queried. This would however cause a lot of cluster state updates, which is not good.

There is however a mechanism to explicitly make indices read-only, and I believe this is supported by ILM. If caching the min and max values of date fields could be done whenever an index is made read-only, this would ensure the cached values stay relevant for longer and dramatically reduce the number of cluster state updates. For use-cases with long retention period it should be possible to make indices read-only after a while and possibly greatly improve query performance as only a small number of indices would need to be always queried.

9

Can you share a specific example of two searches via the API that do the same thing but exhibit the performance difference we're discussing, cutting Kibana out of the equation? Can you then share the results for each (at least the took and _shards fields as above)? Then can you profile those searches to help us see where the time is actually being spent? There'll be more output from that than this forum can cope with, so use https://gist.github.com (or similar) to share it.

The time range for each shard is already (effectively) cached for quick access: this is how the pre-filter phase mentioned above works. In addition, Elasticsearch optimises a range-based search into a match_none search on shards that don't contain any docs that match the range, and match_none searches should run pretty quickly. The profiler output should help to show why these two mechanisms are not doing what we want.

10

Here's the query:

{
"query": {
"bool": {
"must": [
{
"query_string": {
"analyze_wildcard": true,
"query": "+exists:"message""
}
},
{
"range": {
"@timestamp": {
"gte": 1567627030000,
"lte": 1567627040000,
"format": "epoch_millis"
}
}
}
],
"must_not":
}
}
}

curl "https:/loghost:9443/log_*/_search" | jq -S 'del(.hits)'
returns:

{
"_shards": {
"failed": 0,
"skipped": 3096,
"successful": 3174,
"total": 3174
},
"timed_out": false,
"took": 4861
}

and
curl "https:/loghost:9443/log_*-2019.08.04/_search" | jq -S 'del(.hits)'

{
"_shards": {
"failed": 0,
"skipped": 0,
"successful": 75,
"total": 75
},
"timed_out": false,
"took": 201
}

I took out the actual returned docs. I ran both several times, anything that is going to be cached, was.

We only have about a month of indices searchable right now. It gets worse the more we keep open.

11

And no, I can't profile the queries. Apparently that doesn't work when DLS is active.

12

Ok, thanks for trying. I didn't know that about DLS.

Incidentally, as far as I can see skipped shards are also counted as successful ones:

So in your first search we skipped 3096 shards and only actually hit 3174-3096=78 of them with a search.

Also there are 75 shards from the single day 2019.08.04? That seems like a lot. How large is each shard?

13

Also did these two searches yield the same documents? The time range you used, 1567627030000 to 1567627040000, occurred on 2019-09-04 whereas the one-day search you did was for 2019-08-04.

14

A colleague pointed me to #40263 which was merged into 6.7.2 and which might speed up queries that hit a lot of indices. Can you upgrade and see if this helps?

15

Yes, that's about right. 25 indices, three shards each. Sizes vary a lot. We're working on converting to ILM, which will help with that.

Here:

escurlget cat/indices |grep log | grep 2019.09.04
green open log_db-2019.09.04 aZsyYzdeThGMzRpipcYDOw 3 1 39631293 0 49.9gb 25gb
green open log_httpd-2019.09.04 pWW0LDBGS4G1oiLS83M_oQ 3 1 83526892 0 67.6gb 33.7gb
green open log_winevent-2019.09.04 JX5X9lxLTIONTvyM9W1qAw 3 1 12599 0 23.2mb 11.8mb
green open log_winevent_system-2019.09.04 QIa3W_NQRQSiY5CmG9tdcw 3 1 5301323 0 4.9gb 2.5gb
green open log_packetfilter-2019.09.04 p8l7DS0iS4SNHj0DneKIbQ 3 1 12434733 0 23.7gb 11.8gb
green open log_netrecon-2019.09.04 T2X2W9QST3q8RUqa-bTHBQ 3 1 47868237 0 21.2gb 10.5gb
green open log_winevent_security-2019.09.04 FBzpcHdgQkOLtpyFkyXcIQ 3 1 62944427 0 111.8gb 55.8gb
green open log_winevent_application-2019.09.04 J1f-8Nd0QYKOvCcZjF1O5Q 3 1 1178026 0 1.7gb 890.7mb
green open log_aaa-2019.09.04 S5lZRxRCTzWNuRjW4n9VLA 3 1 45763897 0 66.6gb 33.1gb
green open log_filebeat-2019.09.04 ursirM9DRPiCVQooBPmWcQ 3 1 59344 0 51.8mb 25.9mb
green open log_mail-2019.09.04 68IX3FbDTm-1NnrZQTrQdg 3 1 16026509 0 33.1gb 16.5gb
green open log_docker-2019.09.04 -nWnxvS1Q5Kw5v_cLmQnRw 3 1 6677798 0 8.5gb 4.2gb
green open log_syslog_asa-2019.09.04 fQKkWZJyRASwttFAFJvhSg 3 1 283824 0 505.2mb 252.6mb
green open log_syslog_ldap-2019.09.04 Fs9x1osHQTi6wdf_zoq2Kw 3 1 101865433 0 102.6gb 51.2gb
green open log_dns-2019.09.04 rariAEJbQZGSqTwOCKYnVg 3 1 1827543 0 2.2gb 1.1gb
green open log_syslog_sshd-2019.09.04 SvNqdmYeSS60mio0RsAttg 3 1 954557 0 873mb 436.3mb
green open log_ids-2019.09.04 l7Lwp8lkQq2zv-ur07cxnA 3 1 2721 0 6.3mb 3.1mb
green open log_dhcp-2019.09.04 Sf_k74HmRHeZo2pWVAmX0Q 3 1 38135427 0 35.9gb 18gb
green open log_syslog_tmm-2019.09.04 gZINfDU0Scepx0FZO69m9g 3 1 8972058 0 7.2gb 3.6gb
green open log_winevent_powershell-2019.09.04 l37eeTDyTP61Vmb66Qmezg 3 1 226886 0 605.4mb 302.8mb
green open log_uc-2019.09.04 VHsMIq-yQqiBpjg8NfkBJQ 3 1 107085 0 109.5mb 54.8mb
green open log_sbc-2019.09.04 TqJsmixYTuqy-q0NBpZGKw 3 1 37998 0 391.2mb 195.7mb
green open log_tomcat-2019.09.04 lFVUbuJASmanCupCXzf2Gg 3 1 35727 0 29.8mb 14.9mb
green open log_wlan-2019.09.04 frdT2ZuHSrG8cBDy5ZGCOQ 3 1 12507402 0 13.5gb 6.7gb
green open log_syslog-2019.09.04 lTV6lI8XQgOQoMzqH7EwJQ 3 1 34669610 0 43.2gb 21.7gb

16

Yes, that was a typo, sorry.

Not quite the same results - I'm hitting the size limit. (but looks like they'd be the same if I narrowed it down a bit.)

17

I would say that you have too many shards here by about a factor of 4. None of these indices is large enough to warrant three primaries. There's only two that exceed 40GB (suggesting a need for ≥ 2 primaries) and none exceed 80GB (suggesting ≥ 3). Many of them are measured in MB not GB and those could reasonably be monthly indices instead.

18

Yes, and now that we have access to ILM (we've recently updated to 6.x), we'll be able to clean that up. That's not the issue.

The issue is that elastic spends way too much time determining that (for example) the only index that might have documents in the desired time range is log_syslog-2019.09.04. It spends 20 times the time checking all the other log_syslog-* indices, when the pre-search should short circuit that.

If I open two months of logs instead of just one, that is be 40 times longer. After three months, things just time out.

So.... How should we test/fix the pre-search?

19

Oh, when we started, the recommended minimum shard count was 5. We trimmed that down. Some of those indices only have 2.

20

Re-upping this comment:

There was an issue identified in 6.7.1 and fixed in 6.7.2. The first thing I'd suggest is upgrading.