Put operation with lease takes linear apply time depending on number of keys already attached to lease

[marseel]

What happened?

Put request with lease takes linear apply time depending on the number of keys already attached to the lease. With the increasing number of keys and constant QPS, it's increasing to the point, where etcd spend almost 100% of time applying put requests making lease renewal fail.

What did you expect to happen?

I would expect put with lease not to depend linearly on number of already attached keys to lease.

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

Run Etcd with:

docker run   -p 2379:2379   -p 2380:2380   --mount type=bind,source=/tmp/etcd-data.tmp,destination=/etcd-data   --name etcd-gcr-v3.5.9   gcr.io/etcd-development/etcd:v3.5.9   /usr/local/bin/etcd   --name s1   --data-dir /etcd-data   --listen-client-urls http://0.0.0.0:2379   --advertise-client-urls http://0.0.0.0:2379   --listen-peer-urls http://0.0.0.0:2380   --initial-advertise-peer-urls http://0.0.0.0:2380   --initial-cluster s1=http://0.0.0.0:2380   --initial-cluster-token tkn   --initial-cluster-state new  --auto-compaction-retention=1 --log-level info   --logger zap   --log-outputs stderr

Test client:

package main

import (
	"context"
	"fmt"
	"strconv"
	"sync"
	"time"

	client "go.etcd.io/etcd/client/v3"
	"go.etcd.io/etcd/client/v3/concurrency"
	"golang.org/x/time/rate"
)

func main() {
	c, err := client.New(client.Config{
		Endpoints:   []string{"localhost:2379"},
		DialTimeout: 5 * time.Second})
	fmt.Println("Opening session")
	session, err := concurrency.NewSession(c, concurrency.WithTTL(int(30)))
	if err != nil {
		return
	}

	limiter := rate.NewLimiter(1000, 20)
	maxDuration := time.Duration(0)
	mu := sync.Mutex{}

	fmt.Println("Starting writes")
	for i := 0; i <= 10000000; i++ {
		i := i
		limiter.Wait(context.Background())
		key := "asdasdasdasdasd" + strconv.Itoa(i)
		go func() {
			leaseID := session.Lease()
			start := time.Now()
			c.Put(context.Background(), key, key, client.WithLease(leaseID))
			duration := time.Since(start)

			mu.Lock()
			defer mu.Unlock()
			if duration > maxDuration {
				fmt.Printf("MAX latency: %v, entries: %d\n", duration, i)
				maxDuration = duration
			}
			if i%1000 == 0 {
				fmt.Printf("latency: %v, entries: %d\n", duration, i)
			}
		}()
	}
}

Apply duration increase linearly:

Anything else we need to know?

The above repro is using quite a significant QPS of 1k, but I've observed a similar issue with ~50k entries attached to the lease and only 20 QPS of put requests:

As you can see above, with sum(rate(etcd_server_apply_duration_seconds_sum[10s])) approaching 1.0 - leases start failing to renew (red line is Lease renewal returning unavailable error)

Etcd version (please run commands below)

I've tested both 3.5.9 (repro) and 3.5.4 (production setup with 20 QPS)

Etcd configuration (command line flags or environment variables)

Provided in reproduction

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

No response

Relevant log output

No response

[marseel]

I just realized that this performance issue was actually a reason why we have seen such a huge improvement in Kubernetes when we started limiting max number of events attached to a single lease (10x CPU reduction of Etcd): kubernetes/kubernetes#98257 (comment)

[tjungblu]

Thanks for the detailed report and repro @marseel :)

I've been quickly running this through a profiler with the following result:

That should be relatively simple to optimize, it's mostly on the creating a slice from a map which is then checked individually per key.

etcd/server/etcdserver/apply/apply_auth.go

Lines 125 to 136 in 004195b

	func (aa *authApplierV3) checkLeasePuts(leaseID lease.LeaseID) error {
	l := aa.lessor.Lookup(leaseID)
	if l != nil {
	for _, key := range l.Keys() {
	if err := aa.as.IsPutPermitted(&aa.authInfo, []byte(key)); err != nil {
	return err
	}
	}
	}
	return nil
	}

This TODO also looks like a nice candidate to optimize:

etcd/server/auth/store.go

Lines 847 to 850 in 004195b

	// TODO(mitake): this function would be costly so we need a caching mechanism
	if !as.IsAuthEnabled() {
	return nil
	}

[marseel]

Thanks for looking into this.

I think it explains why I've seen different results in this repro and our production cluster.
If I understand correctly, my repro doesn't use auth, but the production setup does - that's why I have seen such a big difference in QPS between production and repro.
For our use case, it would make sense to have a "short" path that checks if a user is a root only once instead of for all keys -

etcd/server/auth/store.go

Line 873 in fbed8cb

if hasRootRole(user) {

So maybe something like, isAuthDisabledOrRootUser before this loop:

etcd/server/etcdserver/apply/apply_auth.go

Line 128 in 41ff237

for _, key := range l.Keys() {

[tjungblu]

I spoke a little too soon about the simplicity of the fix, this is actually a much bigger story for the following reasons.

1. Keys() as a string slices

As you can see most of the time we're spending on converting between string and byte slices here. Map keys can't be []byte, so I assume this is why a string key has been chosen instead. The map and its amortized O(1) access also makes sense, especially in the attach/detach scenarios.

Because etcd is only []byte everywhere, there's a significant toll on converting it back and forth here and in many other places around the Lease. What do you folks think about using a different map implementation?

Obviously, the IsPutPermitted would also require a batched version where we pass multiple keys.

2. runtime enable/disable of auth

It's a cool feature, but it seems we have to continuously check for auth. Otherwise we could just switch out the authBackend entirely and skip all the overhead it comes with.

---

I wrote a little mitigation that would (at least) fix it for the cases where auth is not enabled:
tjungblu@dff670b

which I assume would be most relevant for k8s anyway. Let me know if this is too pragmatic 🧷

[tjungblu]

If I understand correctly, my repro doesn't use auth, but the production setup does - that's why I have seen such a big difference in QPS between production and repro.

ah gotcha, how are you configuring etcd in that case?

[marseel]

Similar, but with auth enabled and only the root user is writing keys. As we can see here:

etcd/server/auth/store.go

Line 873 in fbed8cb

if hasRootRole(user) {

permission checks for root user and does not depend on key value so we could have short path for it too.

[tjungblu]

luckily there's a check for that already:

tjungblu@014b17d#diff-85ead21002d52058142cc354a8367cfe808d7a5d7cdc65ff315aa84edb947c48R128-R132

but yeah, let's hear the thoughts of the others. I think this would be a much bigger refactoring otherwise.

[marseel]

lgtm from my point of view. Thanks!

[tjungblu]

Thanks, opened it as a PR then, let's see what the reviewers think.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 21 days if no further activity occurs. Thank you for your contributions.

[serathius]

This was fixed via #16005