Repository: kubernetes
Issue: Defrag on etcd node causing API 500s
Labels: kind/bug,sig/scalability,lifecycle/rotten,needs-triage,sig/etcd

On one of our large clusters (k8s 1.16) under a steady load of write calls, there was a brief period of ~1 min when all write requests were being heavily stalled. Meaning, the write call latencies spiked to upwards of 5s and many of those API calls got back HTTP 500 failures due to kube-apiserver seeing “timed out” or “too many requests” errors from etcd. See:

![Screen Shot 2020-07-15 at 11 50 23 PM](https://user-images.githubusercontent.com/4333971/88018758-355b9900-cadd-11ea-8846-b7514ed8c366.png)

From the kube-apiserver logs during that time, there were a bunch of such errors:

```
E0630 11:18:05.681970       1 status.go:71] apiserver received an error that is not an metav1.Status: rpctypes.EtcdError{code:0x8, desc:"etcdserver: too many requests"}
E0630 11:18:05.783734       1 status.go:71] apiserver received an error that is not an metav1.Status: rpctypes.EtcdError{code:0x8, desc:"etcdserver: too many requests"}
...
I0630 11:18:09.607116       1 trace.go:116] Trace[1288751478]: "GuaranteedUpdate etcd3" type:*core.Node (started: 2020-06-30 11:18:02.604604723 +0000 UTC m=+21828.371115177) (total time: 7.002491708s):
Trace[1288751478]: [7.002491708s] [7.001801958s] END
E0630 11:18:09.607144       1 status.go:71] apiserver received an error that is not an metav1.Status: rpctypes.EtcdError{code:0xe, desc:"etcdserver: request timed out"}
I0630 11:18:09.607265       1 trace.go:116] Trace[275938462]: "Patch" url:/api/v1/nodes/ip-10-3-252-116.ec2.internal/status (started: 2020-06-30 11:18:02.604455155 +0000 UTC m=+21828.370965584) (total time: 7.002799756s):
Trace[275938462]: [7.002799756s] [7.002149015s] END
```

The 7s above comes from the default request timeout set on etcdserver. And FMU as etcd does locking for writes, slowness in writes leads to head of line blocking for reads that are waiting behind those writes. Consequently, we also observed very high read latencies during the above spike:

![Screen Shot 2020-07-16 at 12 14 55 AM](https://user-images.githubusercontent.com/4333971/88019093-d34f6380-cadd-11ea-9dbd-8615f75668d5.png)

There were 2 main problems to dig into here:

#### Why were writes timing out in etcd?

There was a spike in `etcd_server_slow_apply_total` during that time, which confirms that etcd was taking a long time to apply the incoming requests:

![image](https://user-images.githubusercontent.com/4333971/88019246-34773700-cade-11ea-834c-6181b1f1d545.png)

I spoke to @gyuho about this issue and found out that the "etcdserver: too many requests" errors comes from [here](https://github.com/etcd-io/etcd/blob/ae5942523563b21940c0d69ec6de65d5faf67290/etcdserver/v3_server.go#L619-L624) which is when etcd's applied index lags behind the committed index by more than 5k requests. There was no CPU starvation for etcd, but there was a large spike in `WriteBytes` to the underlying disk:

![image](https://user-images.githubusercontent.com/4333971/88019914-971d0280-cadf-11ea-81f0-043364158a4c.png)

Digging a bit more, I observed that both the pink and the blue spike corresponded to a defrag operation on their respective etcd instances. The pink one was a follower instance and it's defrag happened bit earlier, and there were no errors seen from around that time. However, the blue one was a leader and its defrag caused write requests to be heavily stalled (which is expected given etcd seems to lock the whole DB while doing the defrag). So,

- Why were API errors seen only during leader defrag and not follower defrag?
This is because leader is necessary for writes and is the one responsible for propagating those to the followers. When the follower was having issues, writes could still happen through quorum on the other two instances.

- Should we trigger a defrag on a leader instance?
Sooner or later we will have to call defrag on each instance. But causing defrag on a leader in a busy cluster is causing above performance issue. One approach is to try forcing a leader change before calling defrag for that instance. Not sure if this is the best way.. any suggestions?

#### Should kube-apiserver indeed return 500s in such cases?

There seem to be two concerns at the apiserver level here IMO:

- Is HTTP 500 (Internal Server Error) the right response code to send to clients in such cases?
If we argue that the reason for above issue is a mismanagement of defrag calls, then HTTP 500 makes sense. However, a similar issue **might** happen if etcd was bombarded with a ton of writes or it had a very slow disk (only a hypothesis atm, I haven't tested), in such cases it might make more sense for apiserver to return 429 (Too Many Requests), when it itself is receiving such an error from etcd.

- Should it be throttling new requests as soon as it sees such errors from etcd?
Again here, does it make sense for kube-apiserver to throttle write requests in some form (maybe for few seconds or something) after it receives the initial few “etcdserver: too many requests” errors, to safeguard from bombarding etcd further? (disclaimer - this is again something I'm not sure can happen outside of the defrag case we saw above, but I can try reproducing using some heavy write load if you think it's worth)

@wojtek-t @liggitt @lavalamp @xiang90 @jpbetz - would love to hear your thoughts on the above

/sig scalability
/sig api-machinery