Increased memory usage with 3.6 event reuse

[tjungblu]

Bug report criteria

• This bug report is not security related, security issues should be disclosed privately via security@etcd.io.
• This is not a support request or question, support requests or questions should be raised in the etcd discussion forums.
• You have read the etcd bug reporting guidelines.
• Existing open issues along with etcd frequently asked questions have been checked and this is not a duplicate.

What happened?

@mcornea has been load testing 3.6.5 with OpenShift 4.21 on AWS lately and found we have a memory regression with large clusters and kube density tests.

Cluster Size	etcd 3.5 Avg RSS	etcd 3.6 Avg RSS	Avg Change	etcd 3.5 Max RSS	etcd 3.6 Max RSS	Max Change
24 nodes	359 MiB	360 MiB	+0.3%	468 MiB	541 MiB	+15.6%
120 nodes	550 MiB	601 MiB	+9.3%	893 MiB	1.24 GiB	+42.2%
250 nodes	682 MiB	974 MiB	+42.8%	1.13 GiB	2.96 GiB	+162%

We eventually were able to bisect this and found #17563 as the culprit.
Marius has kindly tested this in a running cluster where you can see the difference in memory:

There is a pprof and an SVG render for your convenience:

heap_10-0-24-15_0008.pb.gz

What did you expect to happen?

In #17563 we expected that memory would decrease drastically, it seems that it has the opposite effect on the density workload.

How can we reproduce it (as minimally and precisely as possible)?

• Deploy a larger 1.34 Kubernetes cluster with etcd 3.6
• Run the kubeburner cluster-density-v2 workload, observe RSS memory metrics

Compare the same using etcd 3.5.

Anything else we need to know?

No response

Etcd version (please run commands below)

3.6.5

Etcd configuration (command line flags or environment variables)

https://github.com/openshift/cluster-etcd-operator/blob/829dc42af533b060d38d31e9728e20bc36b4c5d7/bindata/etcd/pod.gotpl.yaml#L190-L207

Etcd debug information (please run commands below, feel free to obfuscate the IP address or FQDN in the output)

No response

Relevant log output

[serathius]

Was a little worried that will happen when we started seeing OOMs in robustness tests after introducing high watch traffic. The OOMs mostly happen on main and release-3.6 branches.

They can be seen in https://testgrid.k8s.io/sig-etcd-robustness#ci-etcd-robustness-main-amd64 by looking at incomplete runs. Complete run should run 120 tests, independent flakes appear as 119/120, OOMs appear as 118/119 (lower the second number).

[serathius]

We eventually were able to bisect this and found #17563 as the culprit.

If you are able to bisect so accurately could you provide traffic parameters to reproduce the issue?

For testing improvements I used the following benchmark go run ./tools/benchmark/main.go watch-latency --watch-per-stream 1000 --streams 1 --put-total 200 --val-size 100000 code https://github.com/etcd-io/etcd/blob/main/tools/benchmark/cmd/watch_latency.go

Any suggestions about parameters or benchmark code?

[mcornea]

We've observed the issue more clearly on large scale clusters(at 120 nodes) with one of our more intensive workloads simulating a build system which creates 10k large manifests kuberentes jobs and controllers which run aggressive LIST and WATCH operations on the Job objects.

The issue can also be observed at a smaller scale for the maximum values (though the differences are not that significant) with 24 nodes clusters using cluster-density-v2 workload which creates several hundreds of Kubernetes objects.

Same cluster-density-v2 workload for 120 nodes(the amount of created objects grows proportionally with the number of nodes):

Same cluster-density-v2 workload for 250 nodes(the amount of created objects grows proportionally with the number of nodes):

[tjungblu]

Thanks Marek for jumping on this so quickly. I've chatted with Marius on slack for a bit, let's see whether we can repro this with the bench cmd...

So his density test basically spawns 3 pods of his controller, which then creates 6 watch clients as a separated goroutine. Each of those goroutines has a label selector to only list a n/32 subset of the jobs.

Then 10k jobs are created, 80% are small jobs (20kb), 20% are large jobs (60kb) - possibly smaller in etcd with CBOR. Each watcher would then get the subset of about 312 jobs with all status updates and whatnot.

[serathius]

Ok, that's on object sizes. What about number of watches and object churn?

[serathius]

Experimenting with improving benchmark to handle traffic with watches with revision set. https://github.com/etcd-io/etcd/compare/main...serathius:etcd:watch-benchmark-regression?expand=1

[serathius]

Did some benchmarking for watch being created continuously on revision "0" and revision "1". In almost every case the v3.6 uses lower memory than v3.5. Not sure if this is purely a watch issue or there is some other factor.

You mentioned that do you LIST request, maybe the Watch itself is ok and the problem is with combination of List&Watch? Guessing at this point.

[ahrtr]

thx for reporting this issue.

Compare the same using etcd 3.5.

One memory improvement in 3.6 is that we reduce the default value of --snapshot-count to 10K. So If you set the same/consistent value for --snapshot-count in the test (defaults to 10K in 3.6, 100K in 3.5), I think the memory usage difference might be even bigger. Could you double confirm this?

one of our more intensive workloads simulating a build system which creates 10k large manifests kuberentes jobs and controllers which run aggressive LIST and WATCH operations on the Job objects.

Is it possible to convert this tool into an etcd benchmark test tool? I expect it simulates exactly the same way as how apiserver communicates with etcd. But it should be self-contained, which means it shouldn't depend on Kubernetes. In other words, we don't need to create a K8s cluster to test etcd. One example is I created a tool which simulates exactly the same way as how cluster-api upgrades K8s cluster, and I reproduced a 3.5 -> 3.6 upgrade issue using this tool.

We eventually were able to bisect this and found #17563 as the culprit.

I just had a quick review the PR again. Most likely it's due to the introduction of the cache which is permanently resident in memory.

etcd/server/storage/mvcc/watchable_store.go

Line 228 in b3fa375

var evs []mvccpb.Event

[mcornea]

One memory improvement in 3.6 is that we reduce the default value of --snapshot-count to 10K. So If you set the same/consistent value for --snapshot-count in the test (defaults to 10K in 3.6, 100K in 3.5), I think the memory usage difference might be even bigger. Could you double confirm this?

Yes, I can confirm in 3.5 we use --snapshot-count=10000 while in 3.6 we use the default value.

one of our more intensive workloads simulating a build system which creates 10k large manifests kuberentes jobs and controllers which run aggressive LIST and WATCH operations on the Job objects.

Is it possible to convert this tool into an etcd benchmark test tool? I expect it simulates exactly the same way as how apiserver communicates with etcd. But it should be self-contained, which means it shouldn't depend on Kubernetes. In other words, we don't need to create a K8s cluster to test etcd. One example is I created a tool which simulates exactly the same way as how cluster-api upgrades K8s cluster, and I reproduced a 3.5 -> 3.6 upgrade issue using this tool.

Cool, thank you for the example. I'll try to convert the workload using a similar approach and get back with my results. Thanks!

[tjungblu]

Thanks @mcornea - sorry I'm a bit bogged down with other things again.

Most likely it's due to the introduction of the cache which is permanently resident in memory.

yeah, you see it pretty well in the pprof. I initially thought it was a memory leak, maybe the slicing logic keeps a hold of the underlying array for too long and it accumulates?

[mcornea]

Following up on @ahrtr 's suggestion, I've built a self-contained tool that reproduces the issue without a Kubernetes cluster. Please note that it is a rapid vibe coded prototype, but it effectively demonstrates a similar pattern to what I was observing on the OpenShift cluster.

It simulates the build-farm workload directly against etcd: creates namespaces with secrets/configmaps, runs job lifecycles (pods, events, metadata patches) and drives watchers through reconnect cycles that trigger the syncWatchers code path.

The tool is easy to run:

make run-quick-v35      # quick workload, v3.5 (~3.5 min)
make run-quick-v36      # quick workload, v3.6 (~3.5 min)
make compare-quick      # chart from quick run metrics
make run-full-v35        # full workload, v3.5 (~5.5 min)
make run-full-v36        # full workload, v3.6 (~5.5 min)
make compare-full        # chart from full run metrics
make svgs               # generate heap SVGs from peak profiles
make clean              # kill etcd, remove all generated files

Hope this helps with debugging the memory usage increase.