Segment merging for deleted documents on upgrade causing 100% CPU usage.

[gibrown]

Elasticsearch Version

8.14.1

Installed Plugins

analysis-icu, analysis-kuromoji, analysis-nori,analysis-smartcn,analysis-stempel,analysis-ukrainian,ltr,mapper-size,repository-hdfs

Java Version

bundled

OS Version

Debian GNU/Linux 11 (bullseye)

Problem Description

We upgraded our main cluster this past week from 8.6.1 to 8.14.1 and it was a lot rockier than we expected.

The cluster has: 3 masters (one per data center); 96 nodes (32 per data center); 8 servers in each DC with 4 ES instances running on each (these aren't in VMs btw); 8b documents across 4820 primary shards (which all have 2x replication to have one in each DC).

Our upgrade procedure (which we've used many times in the past) is to do a rolling restart of 4-8 nodes at a time, waiting for the cluster to go back to green in between. The last time we did this (last year) it took about 30 minutes.

This time the nodes we restarted immediately went to 100% CPU and became unresponsive. It broke our stats/graphana tracking from ES, and made applying cluster updates or debugging quite difficult. The CPU usage was all from a huge spike of merge activity. We were eventually able to complete the upgrade over the course of 12 hours by going much more slowly and only restarting one node on a server at a time rather than doing batches. That node is effectively dead as the merges happen, but we have enough redundancy to handle it. The load graph across all nodes tells the story pretty well:

We are pretty certain that the cause of this behavior was this change in Lucene that lowered the deleted docs percentage from 33% to 20%: apache/lucene#11761. This was then applied to ES in https://github.com/elastic/elasticsearch/pull/93188/files#diff-4d10666b14a73c580bcbf7f20ec482e7c661878caac568c720391e0fde8efe6aR113

I think those are good changes, we saw disk usage decrease from 48% to 42% and our overall search latency decreased: median 24.6ms -> 16.3ms; 99th percentile 64.2ms -> 52.9ms.

Given the decrease in disk usage and our applications are constantly doing lots of delete and update operations on documents I think the deleted docs percentage change makes sense as the root cause. Even after the upgrade the cluster has a high number of deleted docs:

    "docs": {
      "count": 8192053102,
      "deleted": 1220829287,
      "total_size_in_bytes": 49435305941551
    },

We attempted to set "index.merge.scheduler.max_thread_count": 1 in order to lower how much CPU was being used by the merge process, but that didn't make any difference. Plus once things get this broken it is tough to adjust these types of settings.

I think the bug here is that there is no way to control the amount of CPU getting consumed during this upgrade process. Ideally the merges should have been better spread out over time, but even if not, there doesn't seem to be a way to limit these types of merges.

Steps to Reproduce

1. Create an index on ES 8.6.1
2. Trigger lots of update operations on that index so that the number of deleted documents is close to 33% of the index
3. Upgrade to ES 8.14.1
4. Watch the CPU spike.

Logs (if relevant)

No response

[trakos]

Just to add to this, it's only somewhat vaguely described in release notes here. It only mentions Adjust range of allowed percentages of deletes in an index, but doesn't mention that it changes the default value as well. It's fine for new indices, but for existing ones it's a bit unexpected.

This could be considered a breaking change if that's what caused the problems with increased load after the update. The issue can likely be avoided by setting the config value explicitly before the update, so there's value in highlighting that change better in docs.

[gbanasiak]

I'm tagging the issue for the relevant team to take a look.

The load graph across all nodes tells the story pretty well

This requires some description to be readable. What is represented on the Y axis in the chart? When did the upgrade start, after 16:00? Does the very low values prior to that mean that CPUs were almost idle? Where were you in the upgrade sequence when the Y values reached 400? Are the subsequent increases to the value of 100 marking the start of an upgrade of the next node once you fell back to one-by-one upgrade? Why are there overlaps?

That node is effectively dead as the merges happen, but we have enough redundancy to handle it.

Were you able to capture Java thread dumps at the time of high CPU usage?

As a side note, we do recommend one-by-one rolling upgrade instead of batches, as per https://www.elastic.co/guide/en/elastic-stack/8.14/upgrading-elasticsearch.html#rolling-upgrades.

[elasticsearchmachine]

Pinging @elastic/es-distributed (Team:Distributed)

[gibrown]

Thanks for taking a look!

What is represented on the Y axis in the chart?

Linux system load across all data nodes. One line per node.

When did the upgrade start, after 16:00?

Yep that was the first upgrade.

Does the very low values prior to that mean that CPUs were almost idle?

Not really idle. We're doing about 3500 queries per second and 300+ index and update operations per second. Our typical load is between 10-15 which is about 20-40% cpu utilization.

Are the subsequent increases to the value of 100 marking the start of an upgrade of the next node once you fell back to one-by-one upgrade?

Why are there overlaps?

The graph has multiple nodes, the first case we restarted multiple nodes on the same server and later we restarted at most one per server at a time. Having a load of 100 is still very broken, but we have enough redundancy for an entire data center to be down.

Were you able to capture Java thread dumps at the time of high CPU usage?

We did look at hot threads while debugging. We didn't save too many logs, but I did find one:

hot-threads.txt

In general everything looked like it was about merging or about compression (for a while we thought it was a compression change).

As a side note, we do recommend one-by-one rolling upgrade instead of batches

Ya, it's slow enough as is, and in general it was worked well for us to upgrade ES in batches for probably 10 years. ;) But even a single node ending up using that much CPU seems fairly broken.

[gbanasiak]

Thank you for additional details. Hot threads snippet indeed shows a long list of Lucene merge threads (70+).

Linux system load across all data nodes.

And the corresponding CPU graph is 20-40% baseline before the upgrade, and 100% (saturation) once the node is upgraded, correct?

How many CPU cores on each server? What type of disks - fast local SSDs or something else?

[..] we restarted multiple nodes on the same server [..]

How many nodes per server? 4? Are you adjusting node.processors as per suggestion in docs? @elastic/es-distributed Can you comment if this would help here at all?

Potentially related: #51140

[gbanasiak]

One more ask: is @timestamp field present in global-11-* indices?

[gibrown]

And the corresponding CPU graph is 20-40% baseline before the upgrade, and 100% (saturation) once the node is upgraded, correct?

Correct. Zooming in on a single server we have about 50% CPU usage typically and then when we did the first upgrade we completely saturated to 100%:

That server has 48 CPUs, 500GB RAM, and NVMe SSDs.

How many nodes per server? 4? Are you adjusting node.processors as per suggestion in docs?

Hmmm. There are 4 per server and we are not using that setting so the node stats api tells us each node has 48 processors. It still feels like restarting all 4 nodes at once could have overloaded the server but maybe not as badly?

I'm not sure there is a way to test this on the cluster we just upgraded since all the deleted docs are now merged. We can test this on one of our other clusters though we won't be ready to upgrade them for a month or so.

One more ask: is @timestamp field present in global-11-* indices?

We don't have that field on this index. And I don't think on any of the indices on this cluster. Pretty much none of the data on this cluster is time series data. Most of it is blog posts, comments, or information about websites and users.

Thanks for the help!

[gbanasiak]

It still feels like restarting all 4 nodes at once could have overloaded the server but maybe not as badly?

node.processors setting affects the sizing of various thread pools so it's recommended to reduce it below server core count in case of server sharing, but I would prefer @elastic/es-distributed to comment whether it would help here at all.

One more ask: is @timestamp field present in global-11-* indices?

We don't have that field on this index. And I don't think on any of the indices on this cluster.

Then indeed #93188 is a likely explanation.

We acknowledge the problem exists. Lucene ensures that merges cannot consume all CPU, but this only works at the Lucene index (shard) level, so if you have multiple indexes this no longer works. We should look into having a mechanism that can understand that there are multiple Lucene indexes running in the same JVM. The same was asked for in #51140. cc @jpountz

[henningandersen]

We discussed this in the distributed indexing team and agree that the primary cause here is likely that we treat merging of shards independently rather than through a central thread pool (or otherwise per node level resource control).

[gibrown]

Great, thanks for the update. When we get around to upgrading our next cluster we'll adjust node.processors and update here how much of a difference we see. It's for different applications, but has some similarities.

The overall performance improvement from this upgrade is still really big for us. FYI, we now think some of the performance improvement is also from spending less time in GC (maybe half as much), so probably not all due to fewer deleted docs.