My feeling is that it might be related to some watch issues.

BTW - since I wouldn't be able to work on it today, feel free to pick it up. If noone picks it up, I can start looking into it on Monday.

/sub

However, looking into scheduler logs, the first time when it attempts to schedule any of those pods is related to the log:

I can only reproduce tail latency (#3954). @wojtek-t are your performance tests checked in so I can play with them (preferably with cluster setup instructions)?

Edit: Oh, did you just run @satnam6502 's soak test?

I've seen similar problem but in my case scheduler never noticed new pods. Investigating...

AFAIU @wojtek-t has a similar setup to mine:

• e2e cluster with 50 nodes n1-standard-1, master n1-standard-4.
• running density test with 30 pods per node.

Yes - I Filip wrote, I'm using Density e2e test, to start 30 pods per node (see also #6051).

Also note that this is not happening all the time - it's just kind of "flakiness"

To isolate the performance kubelet more, I ran a simple test which resized the RC to create pods with PodSpec.Host set to a specific node. This bypassed the scheduler completely.

In short, it took ~30 seconds for 30 pods to be reported running on one node. This includes:

• RC creates 30 pods
• Kubelet receives pod updates from watch
• Kubelet starts containers (I used kubernetes/pause images, so there should be no pulling time).
• Kubelet reports the status back to the apiserver

The cluster size is irrelevant in this case, since only one node is being tested.

I was running a very similar experiments (i.e. 1-node cluster) some time ago and also didn't observe it at all. Thus my feeling is that it might be not related neither to scheduler not kubelet, but probably to etcd and/or apiserver which cannot handle a bigger load.

In fact I think this is related to watch [I think that from some reason some changes come to the component through watch with some significant delay]

@yujuhong I don't think cluster size is irrelevant in this experiment, because all the data is read from apiserver/etcd which performance is strictly related with the size of the cluster. As @wojtek-t said we suspect that the problem is somewhere close to watch itself, but we need to dig deeper to understand the problem better.

I've added some logging and I can confirm that this problem is not related to the scheduler or kubelet themself - the issue is (as I thought) that some changes come to those component through watch with a significant delay (e.g. 1 minute). I will continue investigating if it's related to watch itself or maybe some high load on apiserver or etcd.

@fgrzadkowski, I meant for the kubelet startup time alone, the cluster size was irrelevant (which was the case in my test). As for when kubelet receives the update for the first time, that's a different story :)
My test was to simply provide another data point to potentially rule out the possibility that kubelet's performance is the bottleneck.

@zmerlynn reported an issue through #6139. After debugging, I think we ran into this issue a lot:

#6139 (comment)

I observed both scheduler and kubelet doesn't pick up the work immediately. The only common pattern used by both components are using watcher.

1500 writes to etcd is a lot. It's enough to expire the 1000 change history. This could mean that if scheduler happens to be doing a re-list when the writes start, it won't be able to watch when it's done with the list, so it will have to do another list.

We should measure how long a list takes the scheduler.

How sure are you that the clocks on your local system and the scheduler are relatively well synchronized?

@dchen1107 : thanks for looking into it too - what you observed in #6139 (comment) is exactly what I also observed for bigger clusters. I didn't observe it in e2e tests, but I also didn't try to find it in e2e tests. But my feeling is that it's much easier to replicate it in bigger clusters.

@lavalamp : yes I agree that this generates high load on etcd - I will try to look deeper at how long "listing pods" lasts - thanks for suggestion!
Also - I'm pretty sure it's not related to the time skew (I also had this hypothesis at some point but verified that it's not the case)

I tried to debug it deeper and have few more findings about it. I've added a bunch of different logs and here is what is happening:

1. Scheduler (or Kubelet) is "opening" watch for pods.
2. For some time (say 3 minutes) nod pods are changing, so there are no writes with pods in etcd.
3. In the meantime, a bunch of other writes to etcd is happening (e.g. we're updating NodeStatus once per ~2 seconds). In 50 node cluster, it's clear than more than 1000 writes can happen during that time.
4. Then new pods are created (by replication controller). However, they are not send through this watch to scheduler [this is something that I still don't understand why]
5. After 5 minutes since the watch was opened it expires. So we reopen it (still with the previous resourceVersion).
6. Etcd reports an error: "The event in requested index is outdated and cleared","cause":"the requested history has been cleared"
7. After that we "start from the beginning": we list all pods, update the internal storage and open watch from the beginning. From that point everything starts to work fine.

So the thing that we need to understand is the point 4, i.e. why the changes are not delivered through watch that was opened some time ago and there were more than 1000 other changes in the meantime (because this is the reason of it) (I'm not 100% sure that those 1000 other changes are not a red herring, but this seems to be the most probable cause)

cc/ @xiang90 coreos etcd expert.

Xiang, is this the same / similar issue as etcd-io/etcd/issues/2048? We are running etcd 2.X, and go-etcd client is 0.4.6.

This is the same issue.

I don't think item 4 in his sequence is the same issue...

After 5 minutes since the watch was opened it expires. So we reopen it (still with the previous resourceVersion).

This has been fixed in etcd2 I think. @wojtek-t

@smarterclayton and @derekwaynecarr I think it is the same issue with some fixes, but not fully in etcd 2.X, and item 4 is the new symptoms.

@xiang90 Thanks a lot for fixing it. Regarding canceling - yes we are aware of it. There is already a code that handles it.
One more thing - IIUC in order to this change be effective, we need a new release of etcd, right? So when can we expect the new release?

Yeah getting dropped due to high load should be handled correctly already.

@wojtek-t Yes. I will have a release early next week. You can try with the current master though.

@wojtek-t Can you take responsibility for testing the new version of etcd (once it is released) to verify that it fixes this problem? You should also roll back @lavalamp 's workaround (#6381)

@davidopp Sure - will take care of it.

@xiang90 Can you please ping this thread/me when the new etcd release will be built? Thanks!

@xiang90 since the fix the very simple, can we have a patch release here?

@wojtek-t @dchen1107 We are doing it. We will release it later today or early tomorrow.

Please let us know as it is ready. We can rebuild our docker image with the release and start the test again.

@dchen1107 We just cut the etcd v2.0.9: https://github.com/coreos/etcd/tree/v2.0.9
It contains the bug fix for watcher issue.

Great. I will build our docker image for this, @wojtek-t you can pick up tonight PCT for your performance validation. Thanks @yichengq!

@wojtek-t You can upgrade your cluster with 2.0.9 and validate the fix now.

@dchen1107 Will do it today. Thanks for creating the image.

I wasn't able to reproduce this problem with the new version of etcd (it was very easy to reproduce with the previous version).
So I'm going to revert the temporary workaround done by @lavalamp and close this issue.

Yay!