Investigate high cpu/rogue task on certain shard/node

Elastic Stack Elasticsearch
1

for some reason, some nodes/shards doing more "stuff" than others and thus consuming more cpu.

here is setup

  • ES deployed in kubernetes with 40+ data nodes (with different specs)
  • ES version 8.10.4
  • the nodes are partitioned (using node attributes) into 4 separate node-sets
  • the indexes allocation has been set such that certain node-set only contain certain index
  • there are 18 nodes in set2
  • there is only 1 large index allocated to set2
  • shard allocation is fairly balanced, some have 5 and others 6

the issue

  • 2 of the nodes in set2 experienced elevated cpu usage compared to other nodes in the same set
  • both nodes started experiencing this issue during heavy query/aggregation application load.
  • initially, the cpu usage on all 18 nodes were similar, and then after some time those 2 node started having issues
  • even when the application is idle, those 2 ES nodes are still consuming 2~3 cpu cores. while the rest of nodes in set2 are ~0.5 cores

observation

  • couldnt find anything suspicious in _task or nodes/hot_threads. they seem to do query
  • node restart doesnt reduce the cpu usage. (pod was deleted from kubernetes and let it restart itself)
  • when all shards are moved away (auto rebalance is disabled) from 1 of the problematic node, node-0, the cpu usage of that node goes down and no other node experienced cpu increase.
  • when the underlying kubernetes node, node-1, was replaced , cpu usage goes down to normal level, inline with the rest on the set2 nodes. (the node is cordoned off, new node is provisioned and the pod is deleted)

question

  • what sort of logs/metrics/info needed to investigate this issue?
  • anyone experienced similar issue?

thanks in advance

2

Interesting post/puzzle. Surprised no-one has replied. Is it still an issue?

But pretty hard to help with information supplied (and that's not a criticism).

How are you generating (if you are generating) document _id? Or is this being autogenerated by elasticsearch itself at ingest?

8.10.4 was released almost exactly 3 years ago, any reason you have not upgraded?

The "elevated cpu usage" is seen how exactly? Outside this slightly strange observation, what actual problem does it create for you? And if I've understood correctly, you "solved" the issue by excluding node-0 and replacing node-1? But, I guess, you are then 2 nodes down so add a new node-98 and a new node-99, and you're golden, right? Probably not, but why not?

3

Hi @dna01

Like @RainTown could be many things

I would look at the Hot Threads on the nodes that are experiencing it.

I would also look at the Thread Pool

We have all seen uneven nodes / hot nodes ... could be indexing, could be merges, queries etc. Uneven HW can put uneven load in strange ways... There are so many things ... slow IO on some nodes can back up merges, etc...

Poke around ....

4

Hi Kevin,

thanks for the interest.
it was production issue. i'm doing post-mortem analysis while the logs/telemetry are still there.
to answer your question

  • document_id is guid, generated by application
  • this env is running an older application version. the ES will be upgraded to match the application
  • the elevated cpu usage is quite visible from kubernetes metrics, where it records pod cpu utilisation, since it was 5-6x the rest of the nodes. similar level observed through ES monitoring
  • this issue impacted the response time of all calls to that index. queries that normally took <100ms can took >15s. because those 2 nodes hits 100%, while the rest of the nodes are still at ~30% cpu
  • we tried 2 different approach to resolve the issue (trying to determine whether it was infrastructure/vm related or purely ES)
    • by moving shards to other nodes - issue is resolved as the issue, fortunately, didnt travel with the shards
    • by recycling the underlying vm - somehow recycling the underlying nodes clears up the issue
  • we have tried just restarting the pod, but the issue still remain. previously similar issue has happen (on other env, same ES version) and we resolved it just by restarting each affected nodes one-by-one.

this investigation is more to answer

  • how did the issue started
  • how to prevent
  • how to detect - since the only indicator we saw is elevated cpu and slow response time. which are too generic to be used to detect this issue

based on my observation, here is my hypothesis: certain "tasks/process" got stuck and replayed the same query akin to infinite loop.

  • only query related tasks are shown in _tasks (taken during the event, before issue is resolved and while application is idle). also no task took longer than 500s.
  • nodes/hot_threads also mostly shows "[search_worker]"
  • 1 index with 48 primary shards are evenly spread across 18 nodes (some have 5 others have 6) and no custom routing. so search requests would've gone to all nodes and the load should be somewhat equal
  • the fact that the issue is resolved when the shard is moved elsewhere. makes hot nodes issue unlikely
  • also, there is no common shard between those 2 nodes

is there other logs/traces other than _tasks and nodes/hot_threads that can could be useful to look at (in case it happen again)?
would running nodes/hot_threads with different parameters be useful? e.g., longer/shorter interval or higher number of threads

5

Are documents ever overwritten? Do you do any lookups/searches based on the _id? i.e. either

GET /index/_doc/<something>

or

GET /index/_search
{
  "query": {
    "term": {
      "_id": "something"
    }
  }
}

Are any documents, or set of documents, significantly more queried/aggregated than any others?

Understood. But you have logs and data/graphs from the various monitoring tools. I doubt they will be enough to resolve the mystery, although I hope I’m wrong.

I half remember that long time ago on this forum someone posted something similar. IIRC there was a stray cron job they had forgotten about.

I suggest to accelerate this.

I’d push to accelerate the upgrade particularly as the same issue has occurred elsewhere with same version.

btw newer versions have query logging which I suspect would assist you significantly.

The terminology pods, nodes, underlying vm aka underlying kubernetes node are of course the multiple layers that make these sort of issues hard to troubleshoot. As of right now I'm not at all certain you even have an elasticsearch problem per se. I can easily imagine a (buggy) application that "sticks" to a specific node or nodes sometimes.

Honestly, I'd not aim so high. Only if or when you understand the issue, can either the 2nd or 3rd goals are achievable for that particular type of issue. If there was a general purpose way to prevent a node getting slow, Elastic would have put it into the application :slight_smile:

I am not at all sure this is right, but ever if so, that would very possibly be some sort of bug, either in elasticsearch or the application. And the first thing you would be asked to do is upgrade to the latest 8.x version to see if that bug persists.

Well, paste that into any AI tool and it'll tell you at length about different options to those APIs, that you can also poll _cat/nodes/.... with various fields,, /_nodes/<node_id>/stats/jvm, enable and capture slow logs, ... You will get a lot of data to analyse, whether the "problem" jumps out is far from certain.

If you have a paid license, you can open a support ticket. If you are supporting this yourself, then I'd push to upgrade ASAP. You've done the right things IMO so far. Maybe others in the forum have different views on your best way forward given where you are now.

6

Not to mention that when you generate your document IDs
As The index / shards gets bigger each index operation takes longer because elastic has to check every single document in that index to make sure That GUID / ID does not exist...
This can definitely cause problems as indecx / shards get larger the mean indexing time gets longer..

I've observed that often. You don't notice this until you get to some tipping point where just even the smallest amount of lag can start to back up the system.

7

this index may get update (overwritten) and the application sometimes use _doc/{id} or ids query to get specific records.

why do you ask about the id? are you suspecting something related to the id?
is this related to scenario mentioned by @stephenb ?

noted. yea, at this point, i think upgrade is the only tentative solution. given i have no lead to continue the investigation. thanks for the inputs

Hi @stephenb

wouldnt this also happen even if i use automatic id? is the automatic id somehow sequenced, such that it never conflict?
also the application require consistent id, i.e., the same record should only exists once and can be updated/overwritten.

8

No it does not the _id generating algorithm ensures uniqueness across an index and therefore does not have to check.

9

Pattern is to often to put your id in a different field which you can still access not directly by PUT or GET but by update by query or query etc

Example a keyword where you need uniqueness is up to you

10

Mmm.

When people post "interesting puzzles", and share a fair bit of information to help people like me to answer, as you did, even with that info it's just really hard to get a clear and full understanding of the entirety of the issue you face. Particularly when, as in your case, a simple "likely explanation" doesn't leap out of the page.

So though I knew of the scenario that @stephenb mentioned, I wasn't myself particularly thinking of that when asking. Just collecting a bit more info. Same with whether you do a lot of updates/deletes on that index - doing updates is perfectly fine, but its different pattern to indices full of immutable docs. The hope is that maybe some new information gives a new idea, or support or eliminate some "hunch".

Yes, this is unfortunately what I would think too. Post-mortem analysis here is going to be hard even with newer versions. If you can get to point where you can enable query logging that will help, but generic "load" can come in many guises. Your cluster-within-a-cluster already sits inside a k8s solution, probably itself reasonably complex. There could even be back pressure from somewhere else, e.g. I/O on the affected nodes gets slower due to 101 other reasons. The forgotten about cron job, the antivirus scanner, the other pods running on same compute, etc.