Query efficiency (kibana/time based patterns)

Elastic Stack Elasticsearch
#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.

#21

Ahhh, thanks. We're already looking at upgrading (probably 6.8.3, that was current last I looked), in prep for moving to 7.x.

#22

Question: Do we need 6.7.2 on all nodes, or just the coordinating node?

(just the coordinating doesn't seem to help. It will take me a few days to get the entire cluster upgraded.)

#23

I think it'd be best to upgrade everything before drawing any conclusions.

#24

Sorry for the delay. We finally got everything updated. (it's production, there were issues.)

We're seeing a minor improvement, but doubling our open indices still doubles our search time.

Any ideas?

#25

Thanks for getting back to us.

My best idea for a next step is to start looking at the timings of the individual messages that make up a search using the transport tracer. This will help to clarify exactly where the time is going, although it is sometimes tricky to get a clean trace from a busy production system, and trace logging can slow things down a bit too so proceed with caution. Ideally you want to use a coordinating node that's not being used by anything else. I'm not going to be available for the next few days to give more detailed guidance, but will be back later next week if nobody else has stepped in.

#26

Thanks. I'll take a look at that.

We do have a coordinating node (two, actually), which makes things a bit more consistent.

#27

Hi @darkmoon,

I tried the following settings on a 6.8.3 cluster:

PUT /_cluster/settings
{
  "transient": {
    "transport.tracer.include": "indices:data/read/search*",
    "logger.org.elasticsearch.transport.TransportService.tracer": "TRACE"
  }
}

This enables logging for the transmission and receipt of every message involved in a search, like this:

[2019-10-09T08:39:31,242][TRACE][o.e.t.T.tracer           ] [node-0] [12012][indices:data/read/search[phase/query]] sent to [{node-3}{unhUmLKIRMS55s6dBS2qPQ}{e09vwfZhTuWicQyWzeuk-Q}{127.0.0.1}{127.0.0.1:9303}{ml.machine_memory=17179869184, ml.max_open_jobs=20, xpack.installed=true, ml.enabled=true}] (timeout: [null])
[2019-10-09T08:39:31,243][TRACE][o.e.t.T.tracer           ] [node-3] [12012][indices:data/read/search[phase/query]] received request
[2019-10-09T08:39:31,244][TRACE][o.e.t.T.tracer           ] [node-3] [12012][indices:data/read/search[phase/query]] sent response
[2019-10-09T08:39:31,244][TRACE][o.e.t.T.tracer           ] [node-0] [12012][indices:data/read/search[phase/query]] received response from [{node-3}{unhUmLKIRMS55s6dBS2qPQ}{e09vwfZhTuWicQyWzeuk-Q}{127.0.0.1}{127.0.0.1:9303}{ml.machine_memory=17179869184, ml.max_open_jobs=20, xpack.installed=true, ml.enabled=true}]

Here node-0 is the coordinating node and node-3 is one of the data nodes. I'd like to look at the timings of these messages for a single problematic search. The best way to isolate a single search is to use a coordinating node that isn't being used for any other searches at the time. Ideally do this when there aren't too many other searches happening elsewhere either, because the data nodes will be logging messages about all ongoing searches. We can pick out the bits we need, but the less noise there is the better. Once the search has completed you can disable the tracer again:

PUT /_cluster/settings
{
  "transient": {
    "transport.tracer.include": null,
    "logger.org.elasticsearch.transport.TransportService.tracer": null
  }
}

Then could you share the log lines matching o.e.t.T.tracer from that search, from the coordinating node and every one of the data nodes?

#28

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