The difference doesn't really seem very visible in load test:

and for density we're seeing the difference, but sadly we're missing points in the graph whenever density test failed due to high latency (likely some bug in it):

On the good side, we're noticing the increase in kubemark-5000 also. Here's how the graph looks there for density, which is clearly indicating the regression:

From kubemark-5000 load test, there seems to be even clearer indication (the increase likely is b/w 860 -> 862):

I'm looking at the diff 50e28a5...a8060ab, and my suspicion is currently on #56717 which seems to add some extra processing on the way of creates/reads to subresource objects (so codepath is likely to be touched by node/status?)

cc @wojtek-t

#56717 is changing only client implementation. Latencies are measure server side, so this is unlikely that it's that PR (unless it's not adding additional requests).

Good point about that being client-side - it's probably sth else.
Let me see if I can find some more info from smaller kubemark.

@jberkus - FYI as this is definitely scalability regression

The range 860-862 of kubemark-5000 is suspiciously close to that PR: #59953
[which was discovered to be reason for regression]

@shyamjvs - I looked into range that you mentioned above:
#59685 - unrelated
#59797 - unrelated
#57445 - unrelated
#59523 - unrelated (only removing some metrics gathering in CM)
#59090 - unrelated (only e2e tests changes)
#59697 - unrelated (docs)
#59489 - unrelated (only test changes)
#59716 - unrelated (only Azure changes)
#59761 - unrelated (only e2e test changes)
#59837 - unrelated (only juju changes)
#59103 - unlikely, but possible
#58433 - unrelated (only change to mount_linux file, can't regress kubemark)
#59749 - unrelated (only openstack changes)
#59832 - potentially
#59825 - unrelated (only removes unused code)
#59800 - unrelated (only benchmark-related changes)
#59817 - unrelated (potentially removes some retries)
#59711 - unlikely (changes how flags are used by hollow-node)
#59788 - unrelated (typos)
#59846 - unrelated (renames)
#59792 - unrelated (just juju)
#59666 - unlikely (changes to kubelet initialization, shouldn't affect kubemark)
#56717 - unlikely but possible
#59440 - unrelated (vsphere changes)
#59878 - unrelated (typos)
#59852 - unrelated (hack/lib/etcd, not used in tests)
#59335 - unrelated (only changes in scheduler algorithm)
#59872 - unrelated (only e2e test changes)
#59646 - unlikely (re-revert of #59523 also from this batch)

@shyamjvs So there are only 6 PRs here and all of them are quite unlikely to cause that problems in my opinion.
So maybe something happened slightly before (and we were lucky in one run) or slightly after?

Actually, take a look at this graph - this also proves where the regression was.
And it unfortunately gives the same range.

So I think the suspicious PRs are (but neither of them looks like it could cause such things)
#59103 - unlikely, but possible
#59832 - potentially
#59711 - unlikely (changes how flags are used by hollow-node)
#59666 - unlikely (changes to kubelet initialization, shouldn't affect kubemark)
#56717 - unlikely but possible
#59646 - unlikely (re-revert of #59523 also from this batch)

BTW - this may be kubemark-specific regression, because we don't see similar effects in 5k-node clusters.
So it may be something different than the initially reported one.

So I looked deeper into that issue, and I strongly believe that the reason for kubemark regression is:
#59832

Before that change, all pods had exactly the same IP-address, which meant Endpoint objects consisted of pretty much only a single entry - due to repacking we are doing in endpoint controller:
https://github.com/kubernetes/kubernetes/blob/master/pkg/api/v1/endpoints/util.go#L35

After this change, pod IPs should be generally different one from another, and thus the Endpoints objects are much bigger, because of that.

Looking into memory profiles, this theory seem to be confirmed, becuase starting with run 862 of kubemark-5000, we started observing, a singinifcant percetage of memory to be allocated from:

k8s.io/kubernetes/pkg/apis/core
(*EndpointAddress)
DeepCopyInto
zz_generated.deepcopy.go
1274210.05MB (8.18%)

It would be probably good to confirm my theory, but I'm 99% sure this is the case here.

In that case, this kubemark regression is a valid one and that makes the setup close to real cluster setup and we shouldn't worry about that.

That also means, that regression reported by @shyamjvs originally is something different.

As for the originally reported regression, I think the only thing we can say is that happened somewhere
between runs: 115 and 118:
https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-kubernetes-e2e-gce-scale-performance/115
https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-kubernetes-e2e-gce-scale-performance/118

and unfortunately that's hell a lot of commits...

@shyamjvs had a hypothesis that the regression happened between runs of 884 and 885 of kubemark-5000 (which is within this time period).

I looked into corresponding diff:
07240b7...46f05b0

#59495 - unlikely, but possible
#60173 - unrelated (doc changes)
#60595 - unrelated (owners changes)
#60524 - unrelated (only changes leader election for scheduler)
#60385 - unrelated (only kubeadm changes)
#60615 - unrelated (only integration test changes)
#60580 - potentially possible
#60557 - unrelated (only e2e test changes)
#60362 - unrelated (only test changes)
#60629 - unrelated (only typos)
#60572 - unrelated (only docs)
#60623 - unrelated (only azure changes)
#60625 - unrelated (only azure changes)
#60520 - unlikely (retries in test framework)

@shyamjvs So here there are only 3 potential PRs that may have affected that - see above.

Since there isn't much there, i went one more run before (so commits from 883 to 884):

b1ef631...07240b7

#60376 - unrelated (changes docker calls for setup things)
#55584 - unrelated (simple fix)
#60358 - unrelated (docs changes)
#54631 - potentially (Quobyte library bump)
#60291 - unrelated (healthz changes in cloud-controller-manager)
#60470 - unrelated (scheduling api group)
#59149 - unrelated (examples and e2e tests)
#56075 - potentially
#60280 - unrelated (cleanup)
#60504 - retry EOFs (unlikely)
#60342 - unlikely
#60505 - unrelated (log changes)
#59218 - unrelated (e2e test changes)
#52900 - unrelated (cleanup)
#60486 - unrelated (?) bug fix in service controller
#60475 - unrelated (test changes)
#60514 - unrelated (integration tests)
#60506 - unrelated
#59903 - unrelated (e2e test changes)
#60319 - unrelated (e2e test changes)
#59345 - unrelated (e2e test changes)
#58171 - unrelated (e2e test changes)
#58036 - unlikely
#60540 - unlikely
#60555 - unrelated (test changes)

Thanks for looking into this @wojtek-t.
So like I mentioned in yesterday's offline discussion, there indeed seems to be different regression around run 884 of kubemark-5k (besides the other one b/w 860 and 862). Few reasons to believe it was around that time is:

• there's increase in 90%ile latency b/w 884-885 as you can see in the first graph in 'PATCH node-status' latency slo violations #62064 (comment)
• there's increase in 99% latency b/w runs 116-118 of gce-5k (which was around the same time as 884-884). Here's the latency graph I generated for gce-5k (along with points that were missing on perf-dash):

And wrt your #62064 (comment) - I also agree with you that it's most likely because of my pr #59832. Some of those points about endpoints having single entries earlier and the apiserver mem-usage increasing after the change - I explained them earlier under #44701 (comment) and #59823.

Another thing (like we were discussing) is that only kubemark seeing this rise even more strongly suggests it's that change.
Since that's as expected, I'll now try to find the other one.

And wrt your #62064 (comment) - I also agree with you that it's most likely because of my pr #59832. Some of those points about endpoints having single entries earlier and the apiserver mem-usage increasing after the change - I explained them earlier under #44701 (comment) and #59823.

That was different thing - they were empty because of validation problems.
Though that doesn't really matter now.

Since that's as expected, I'll now try to find the other one.

Yeah - thanks for looking into that.
The only think that I'm not convinced is that the regression was between 116-118 (not 115-118).

As you see, above I analyzed changes from between 883-885 kubemark runs. There are only 9 pontential PRs that may have cause that.

@shyamjvs The more I look into it, the more doubts I have that the regression is not between 115 and 116. If you look into metrics for replicactioncontrollers, the increased between 115 and 116. And I think this might actually be the same thing that is causing increase of patch nodes.

Or maybe (looking into longer time horizon) these are only fluctuations...

The reason why I'm less willing to believe it's fluctuations is because there are >10 consecutive runs where the latency was b/w 800-900ms - and then this started.

We've talked offline about that and decided that we will start with running 2-3 time from commit at which run 116 was run. That should tell us if the point 116 was good or bad.

With that information, we will try to discover the left end for the potential bisection (confirm that it really happened before run 118).

I ran once against 116, and it looked like this:

    {
      "data": {
        "Perc50": 7.915,
        "Perc90": 171.342,
        "Perc99": 805.786
      },
      "unit": "ms",
      "labels": {
        "Count": "7134625",
        "Resource": "nodes",
        "Scope": "cluster",
        "Subresource": "status",
        "Verb": "PATCH"
      }
    },

Will run again later.

We need one or two more runs, but this seems like "before-regression" to me.

Ran once more against 116 and have the following values - 9.66ms (50%), 414.091ms (90%), 877.327ms (99%)
I believe we can now try to confirm that 118 is the right end.

I've ran against 118 and seems like it indeed is a bad one:

INFO: WARNING Top latency metric: {Resource:nodes Subresource:status Verb:PATCH Scope:cluster Latency:{Perc50:10.244ms Perc90:627.37ms Perc99:1.004515s Perc100:0s} Count:4357372}

it's only 1.00s, so it would be good to have one more run.

I've run once more and it turned out bad again:

INFO: WARNING Top latency metric: {Resource:nodes Subresource:status Verb:PATCH Scope:cluster Latency:{Perc50:11.16ms Perc90:645.185ms Perc99:1.020599s Perc100:0s} Count:4359913}

So continuing with assumption that 118 was bad, I ran the test against the mid-commit 249ecab and result was: 9.599 (50%), 573.99 (90%), 921.448 (99%)
I think this isn't super-clear, so I'm re-running against it.

For rerun against the same commit and it seems good:

"data": {
        "Perc50": 5.804,
        "Perc90": 173.217,
        "Perc99": 822.677
      },

And then I reran against the next commit f82b38c and it seems unclear to me if it's bad:

1st try:

11.104ms, 572.727ms, 915.371ms

2nd try:

8.078ms, 552.669ms, 955.312ms

The 3rd try gave me:

"data": {
        "Perc50": 5.519,
        "Perc90": 212.198,
        "Perc99": 869.305
      },

So I'm going to proceed by assuming this was a good commit (and the earlier higher values were some variations).

I would say that there might be a second (smaller?) regression in the first half.
But +1 for assuming for now this was a good one and proceeding with that assumption.

So commit b888415 seems bad :

INFO: WARNING Top latency metric: {Resource:nodes Subresource:status Verb:PATCH Scope:cluster Latency:{Perc50:12.52ms Perc90:598.967ms Perc99:1.005133s Perc100:0s} Count:4565870}

Current range is f82b38c...b888415

So from the ones we were suspecting yesterday, the following remain in the diff:

• Make Scale() for RC poll-based until #31345 is fixed #56075 move rc-scaling to polling
• Fix nested volume mounts for read-only API data volumes #60342 nested volume mounts
• client-go: add an exec-based client auth provider #59495 exec-based client auth provider

There are only 4 potentially suspicious PRs in that range:
#56075
#60342 (highly unlikely, as it touches only kubelet and doesn't increase API calls IIUC)
#58171 (highly unlikely, as we're not using flex volumes in our tests)
#59495

b2f1b3d is also bad:

WARNING Top latency metric: {Resource:nodes Subresource:status Verb:PATCH Scope:cluster Latency:{Perc50:11.16ms Perc90:593.827ms Perc99:1.001812s Perc100:0s} Count:4358862}

Current range is f82b38c...b2f1b3d

[EDIT: This leaves us with #56075 and #60342 as the remaining suspects]

@shyamjvs - so let's run on commit with one of them and without the other

Running it against 98eb5cb gave me:

WARNING Top latency metric: {Resource:nodes Subresource:status Verb:PATCH Scope:cluster Latency:{Perc50:11.679ms Perc90:643.619ms Perc99:1.022355s Perc100:0s} Count:4418914}

which leaves us only with my PR #56075 as the cause :)

Thank @shyamjvs
That means we should prioritize: #50102 because that will unblock getting back to watch-based solution there.

Going back to the 'PATCH node-status' latency graph I posted earleir in #62064 (comment).. copying again:

We now understand the cause for bump above threshold of 1s before run-119. This is caused by my PR #56075 that moved Scale() method for RCs from watch-based to poll-based.

The other part that remains is to figure why so much variance in the latency was introduced after run-119. Currently I'm trying to confirm that 119 is stable (so we can use it as left-end for bisection).

Running against 119 gave:

{Resource:nodes Subresource:status Verb:PATCH Scope:cluster Latency:{Perc50:9.408ms Perc90:697.499ms Perc99:1.062004s Perc100:0s} Count:5137540}

and against 120 gave:

{Resource:nodes Subresource:status Verb:PATCH Scope:cluster Latency:{Perc50:11.792ms Perc90:615.898ms Perc99:1.012838s Perc100:0s} Count:4692243}

I'm now planning to confirm if 121 sees the problem (even though the graph says it should) just to confirm right-end is correct.

Running against 121 confirmed that it's a bad one:

{Resource:nodes Subresource:status Verb:PATCH Scope:cluster Latency:{Perc50:10.811ms Perc90:546.962ms Perc99:1.240708s Perc100:0s} Count:4569021}

And bisecting at df3d8bc in b/w 120 and 121 seems to be good:

{Resource:nodes Subresource:status Verb:PATCH Scope:cluster Latency:{Perc50:12.704ms Perc90:641.654ms Perc99:1.011261s Perc100:0s} Count:4838682}

This is the current diff - df3d8bc...17d69c2
I have suspicion on my etcd-revert to 3.1.11 (#60891), so I'm currently running against it.

This is the current diff - df3d8bc...17d69c2

If you believe in that diff, there isn't anything else that may caused regression other than your PR...

That's true. But I want to ensure that I don't get a good run flakily (as that might mean I missed bad commits earlier in the commit history while bisecting by chance).

Confirmed it's my etcd change:

{Resource:nodes Subresource:status Verb:PATCH Scope:cluster Latency:{Perc50:10.822ms Perc90:428.997ms Perc99:1.214079s Perc100:0s} Count:7565564}

From an initial thought it seems to be like there's a variance in latencies that was introduced when we moved from 3.2.16 -> 3.1.11.
Based on all this I feel we should try to understand what exactly is happening with different etcd versions (i.e run density test (probably multiple times) against HEAD with each etcd version that's doubtful).

Based on all this I feel we should try to understand what exactly is happening with different etcd versions (i.e run density test (probably multiple times) against HEAD with each etcd version that's doubtful).

That would be extremely useful.
As I already mentioned to you offline, we should also try to run etcd on tmpfs as an experiment. But understanding first impact of individual versions sounds more important.

Given that we hopefully debugged and fixed the regressions (at least we are in much better shape now) and the fact that there are no concrete action items here, I'm closing this one.

Yes, we seem to be in a good shape now. FTR I'm pasting below perf-dash showing latencies are back to normal values:

We can reopen this if we find some issue later.
/close