Simple queries takes lots of time and uses 100% cpu

[aimarjg]

@DavidTurner: that's exactly what I'm saying - queries executed in devtools are done in seconds, while in discovery tab it takes ~10 times more.

Test done right now:

1. Query in discovery tab:
Request code: https://raw.githubusercontent.com/aimarpl/kb_queries/master/query_discovery
While executing, all CPUs at 100%:

Result after ~15 seconds (first query failed after two minutes, so I had to re-run it and then got response in 15 secs):

2. Query in devtools tab:
Request code: https://raw.githubusercontent.com/aimarpl/kb_queries/master/query_devtools

While executing & result (result provided almost instantly with almost 0 CPU load):

It's crazy...

[aimarjg]

I have even disabled highlighting in kibana settings to check on performance then, but... it has no impact at all (it was suggested in one of answers above).

[Mark_Harwood]

I see the discover vs console examples are querying different date ranges and timestamps - to further diagnose we need to get these requests as close to each other as possible.
The other thing to ensure is that caching is not taking effect. In console you can do this:

  GET myindex/_search?request_cache=false

Another difference between Discover and Console is that Discover will route user requests to the same choice of replica using the preference parameter (you can see this value using the Browser's network tools).
In your Console test, set ?preference=xxxx with the same session id used by the Discover tab.

[aimarjg]

Good catch, indeed timestamps were a little bit different...

I just did another test applying your suggestions into it:

1. Query from Discovery
   Request code: https://raw.githubusercontent.com/aimarpl/kb_queries/master/discovery_query2

Execution:

Result:

It took 16 seconds

2. Query from dev tools:
   Request code: https://raw.githubusercontent.com/aimarpl/kb_queries/master/devtools_query2

Result:

It took around 1-2 seconds

---

about replicas used - It's a single node with 5 shards and just 1 replica so I believe it does not matter, does it?

[Mark_Harwood]

Indexes are created daily (winlogbeat-YYYY-MM-dd) wi with 1 shard, 0 replicas.

It's a single node with 5 shards and just 1 replica

Are we talking about a different setup now?

[aimarjg]

No, yes... a little Few posts above I tried to reconfigure it from 1 shard and 0 replicas to 5 shards and 1 repl - I thought that maybe then it will run some search jobs in pararell increasing the overall performance, but... it had no impact.

@aimarjg

I had an idea of enabling more shards (now i have 5 instead of 1) for this index so then it does search in 5 threads in parallel instead of 1, but I don't know if it actually helps on single node ES instance. Does it?

[Mark_Harwood]

@aimarjg

about replicas used - It's a single node with 5 shards and just 1 replica so I believe it does not matter, does it?

If you only have a single node you'll never get any replicas (there's no added resilience or throughput benefits in allocating replica shards to the same node as the primary shard).

So I guess we can rule out any preference difference between Discover and Console.

It might be worth noting Kibana's description of timings. I wonder if there's added overhead in the unpacking of all that JSON in the 500 doc results (did we already establish performance was linear with the size setting for hits?)

[aimarjg]

ah, then, basing on last query output it looks like
ES query takes only 54ms - super fast
and then preparing all json docs takes 16460ms ...correct?

I would test that with different sizes as you proposed, but doing that in devtools/console would not give me results I'm looking for (preparing docs).
If I do that from the discovery tab in kibana I can change size in advanced settings, but.... results are cached and each subsequent query for same data is faster. How do I disable cache over there?

[Mark_Harwood]

If the suspicion is that it's all the JSON marshalling that takes the time the elasticsearch caches may be somewhat irrelevant. That said, there's an API you can use to clear the caches

[aimarjg]

ok, good hint

first query, 500 results

• query time: 170ms
• request time: 27339ms

second query after clearing the cache with following:
POST /winlogbeat-2019.11.14/_cache/clear
POST /winlogbeat-2019.11.13/_cache/clear

Result:
# POST /winlogbeat-2019.11.14/_cache/clear
{
"_shards" : {
"total" : 5,
"successful" : 5,
"failed" : 0
}
}

# POST /winlogbeat-2019.11.13/_cache/clear
{
  "_shards" : {
    "total" : 5,
    "successful" : 5,
    "failed" : 0
  }
}

Query time: 129ms
Request time: 634ms

so... even after clearing cache, second query is very fast (for the same data); how is that possible?!

[Mark_Harwood]

There's OS-level filesystem caches to consider too but that does look like a suspiciously large difference.

[Alfredo5520]

After analyzing the website type and traffic, we tweak the key settings in MySQL servers that helps to ensure optimal resource usage. This includes connection limits, buffer size and query cache size, and more.

[aimarjg]

@Mark_Harwood, @DavidTurner - first of all, thank for you all your hints here finally some good news here
Got it fixed - I have disabled filterEditor:suggestValues in Kibana settings so KQL won't suggest values in discovery search and problem is gone.

filterEditor:suggestValues enabled:
|Query time|271ms|
|Request time|53354ms|

filterEditor:suggestValues disabled:
|Query time|380ms|
|Request time|1718ms|

Finally it all works as it should, question is - shouldn't this feature get reported as a buggy? As I read in other threads it looks up all indicies instead of those specified in time range picker which causes such CPU load.

Anyway - I hope that this workaround will help others having same issue with ELK 7.

[Mark_Harwood]

Glad to hear you identified the bottleneck. I added a note to the relevant Kibana issue.