FTR - Some runs which failed due to exceeding our thresholds:

• https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-kubernetes-e2e-gci-gce-scalability/11169
• https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-kubernetes-e2e-gci-gce-scalability/11170
• https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-kubernetes-e2e-gci-gce-scalability/11171
• https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-kubernetes-e2e-gci-gce-scalability/11172
• https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-kubernetes-e2e-gci-gce-scalability/11173

@crassirostris @sttts

So it indeed seems to be the audit-logging change. I looked at the memory allocation profiles from the density test before and after the change. And the allocations made by k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/filters.audit.go: WithAudit() went from ~6.4GB to ~23GB.

cc @liggitt @tallclair
(looping in some more audit-logging folks)

#60076 does only introduce the buffered backend, but does not wire it in anyway. #60237 is still not merged.

Yup, #60076 doesn't add any dependency on the new package anywhere

I see.. I'm not sure though how that explains the increase of memory allocations from 6GB -> 24GB related to audit-logging. As I mentioned in #60500 (comment).

@shyamjvs I doesn't, there has to be something else. Note, that memory allocation changed 20GB -> 50GB, not 20GB -> 37GB, so the problem is not isolated in audit logging

Looking into PR itself indeed it seems like a code that is not used anywhere.

@shyamjvs - let me take a look into that too.

Sure.. Let me verify if it was some false positive (though at least 5 runs seemed to fail continuously in a row due to it).

Ok.. So from perf-dash, I'm seeing that there was a transient spike in the mem-usage for few runs during that time, but it went down later.

So the spike went down later somewhere b/w this diff, which makes it look random to me (probably sth that doesn't have much to do with k8s code).

@wojtek-t I believe we can close the issue - WDYT?

If you look into graph for load test:

• there is also a spike
• but this is shifted a little bit (it started at run 1165)
• and there is another spike that is happening now

I think this may be something real - I wouldn't close that now.

Ok.. Let's wait to gather some more evidence.

See this:

Since this is looking relatively severe, as ya'll continue to triage please add a priority and labels for milestone v1.10 to the issue and any PRs as applicable since the indicated problem commit range is in the 1.10 branch.

Update: It seems like we saw a couple of spikes around that range, following that things seem to have gone back to normal (for about 40 runs). That said, I'd like to wait a bit more to gather more confidence. Here are apiserver mem usage graphs for density and load test resp. :

Note that we're seeing flaky failures for that job from time to time, with the following reason:

Error while waiting for replication controller density-latency-pod-69 pods to be running: Timeout while waiting for pods with labels "name=density-latency-pod-69,type=density-latency-pod" to be running

That 'might' be unrelated to this particular issue, but it seems like a regression. Still, it needs fixing.

Adding a real priority:

/priority critical-urgent

If this is going to be in the milestone until we have more evidence, it should have status/approved-for-milestone. So please decide one way or the other on the next test run. Thanks!

@shyamjvs given the results in #60589, can we consider this a confirmed problem for 1.10?

Looking at the diff b/w runs 10868 and 10870 (which seems to be where the regression happened), I'm not really sure which one would cause this. Though this seems potential to me:

Try longer to fetch initial token. #56394

While it's making some POST requests internally and storing the response, it seems to be called as a one-off in the cloud-provider pkg (so not sure if it should increase mem-usage - maybe it's allocating some memory). I'll need to verify.

I've changed the issue title to more accurately represent the situation. Turns out it's not as bad as 1.5-2x increase (as was originally noted).

@shyamjvs

Could you confirm that and also how much bound wrt memory can we expect, so we can change our thresholds?

Depends on the request sizes. Assuming each request in ~2.5KB (something I observed in e2e correctness tests), that's at least +25MB for buffering. Accounted for the different size internally, gc and the fact that a copy of audit logging request is stored in context for each request, +100-200 MB sounds reasonable.

Thanks @crassirostris - I'll update our thresholds correspondingly. Could you please make a release-note mentioning this (if not already done) as this can affect end users?

@shyamjvs

Could you please make a release-note mentioning this (if not already done) as this can affect end users?

To clarify, advanced audit logging is enabled by default everywhere but in scale tests since 1.9 (or 1.8 even). That's not a new change per se. However, I created a PR to address this point in the documentation: kubernetes/website#7725

To clarify, advanced audit logging is enabled by default everywhere but in scale tests since 1.9 (or 1.8 even).

I'm aware of that :) However, note that for our 100-node scalability jobs we did not disable advanced audit-logging (unlike for our larger jobs). IIUC that's the reason why we caught this issue.

That's not a new change per se.

While I agree that advanced audit-logging is not a new change, the buffering change (#60237) which caused this increase was introduced in 1.10, no?

I'm aware of that :) However, note that for our 100-node scalability jobs we did not disable advanced audit-logging (unlike for our larger jobs). IIUC that's the reason why we caught this issue.
While I agree that advanced audit-logging is not a new change, the buffering change (#60237) which caused this increase was introduced in 1.10, no?

Oh, OK. I got confused with all different scale tests, sorry :) I agree, PR in question did increase memory consumption on its own. Not sure it requires a separate release note or a piece of documentation, since the memory consumption is extremely dependent on the configuration. For example, buffering existed in webhook audit backend, so e.g. in GKE memory consumption shouldn't have changed.

unlike for our larger jobs

BTW, I think this is a mistake, we can enable audit logging everywhere now, similarly to kubernetes/test-infra#7000

No problem :). Few thoughts:

Not sure it requires a separate release note or a piece of documentation, since the memory consumption is extremely dependent on the configuration.

The documentation PR you created is definitely useful. However, my feeling is this also warrants a release-note. If it SGTY, I can add a release-note in the PR where I'll bump our test thresholds.

since the memory consumption is extremely dependent on the configuration.

That's true. Maybe a rough idea of the upper bound (200MB?) with default config (i.e 10k events?) is enough.

For example, buffering existed in webhook audit backend, so e.g. in GKE memory consumption shouldn't have changed.

For GKE, yup. One question though - did we change the k8s apiserver default to buffering mode in 1.10?

BTW, I think this is a mistake, we can enable audit logging everywhere now, similarly to kubernetes/test-infra#7000

Yeah, seems like the *-performance jobs got left out. I'll send out a PR later enabling it.

If it SGTY, I can add a release-note in the PR where I'll bump our test thresholds

SG, thanks!

did we change the k8s apiserver default to buffering mode in 1.10?

For log backend, no. Or, rather yes, but there's a PR to revert it and re-introduce it in 1.11

I'll send out a PR later enabling it.

Thanks!

So the apiserver mem issue is sorted now - I've sent #61118 to bump the threshold.

And wrt the controller-manager mem issue, I've confirmed (by running density test few times against 100-node cluster) that it's being caused by this PR:

fix fluentd-gcp-scaler to look at correct fluentd-gcp version #59921

While running only density test,

• before that PR, the mem-usage is consistently ~300MB
• after that PR, the mem-usage is consistently ~330MB

@x13n @crassirostris - Any leads here? Maybe the fluentd-scaler wasn't doing any real scaling earlier due to wrong deployment name (just a guess though)?

@x13n should know more about the connection between scaler and controller-manager. I though all work is performed by a dedicated controller running in the cluster, not controller-manager

@shyamjvs Yes, before that PR it wasn't doing anything useful. Between #59657 and #59921, fluentd-gcp had no resource request nor limit set. Was there a 30MB drop in memory usage in #59657?

Seems both those PRs were merged 27 days ago. However, we started seeing the increase only after #59921 (which IIUC is when the scaler actually started scaling sth?)
In general, do you have a reason to expect controller-manager to be affected by your addon?

@x13n and me discussed about this offline and there are a bunch of possibilities why this might be happening (possibly some bad behaviour of the scaler).
I've shared instructions on how to run the 100-node tests with him and he'll dig deeper into this.

@x13n Btw - you might find useful the following controller-manager logs:

• before your change: https://storage.googleapis.com/kubernetes-jenkins/logs/ci-kubernetes-e2e-gci-gce-scalability/10865/artifacts/e2e-big-master/kube-controller-manager.log
• after your change: https://storage.googleapis.com/kubernetes-jenkins/logs/ci-kubernetes-e2e-gci-gce-scalability/10870/artifacts/e2e-big-master/kube-controller-manager.log

Searching for 'fluentd', shows a bunch of such logs in the latter:

I0215 17:38:32.683798       1 controller_utils.go:590] Controller fluentd-gcp-v2.0.14 deleting pod kube-system/fluentd-gcp-v2.0.14-qkbsq
I0215 17:38:32.684117       1 controller_utils.go:590] Controller fluentd-gcp-v2.0.14 deleting pod kube-system/fluentd-gcp-v2.0.14-p4t52
I0215 17:38:32.684277       1 controller_utils.go:590] Controller fluentd-gcp-v2.0.14 deleting pod kube-system/fluentd-gcp-v2.0.14-gs956
I0215 17:38:32.684444       1 controller_utils.go:590] Controller fluentd-gcp-v2.0.14 deleting pod kube-system/fluentd-gcp-v2.0.14-xcqzw
I0215 17:38:32.684595       1 controller_utils.go:590] Controller fluentd-gcp-v2.0.14 deleting pod kube-system/fluentd-gcp-v2.0.14-tmt9n
I0215 17:38:32.684736       1 controller_utils.go:590] Controller fluentd-gcp-v2.0.14 deleting pod kube-system/fluentd-gcp-v2.0.14-6js9l

which doesn't seem too normal to happen in b/w the test.

The first PR removed resource requests and limits from the manifest file used by addon manager. The second PR caused the scaler to set them again. Current hypothesis is that sometimes, when the scaler runs kubectl set resources, the resource is updated even though it shouldn't. This in turn causes controller-manager to receive data via watch on the DaemonSet resource, which causes the increase in memory usage.
I'm going to verify this and if this is the case, will add a check to the scaler so that set resources call is used only when necessary.

We did some debugging with @shyamjvs. What we found out is: addon manager and fluent-scaler are both sending PATCH requests to apiserver, to update fluentd-gcp. All these patches are no-ops, the only thing that is changing is the resource version. That unfortunately doesn't prevent the deamonset controller from killing & recreating identical pods, which is what causes increased memory usage of controller-manager.

Short term, I will change fluentd-scaler to send resource update requests only when there is actual change that needs to be PATCHed. However, empty patches shouldn't cause daemonset-controller to kill any pods. The latter is probably not a release blocker (?), but should still be investigated.

All these patches are no-ops, the only thing that is changing is the resource version.

true no-op patches should not change resource version or trigger watch events. that is verified in https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/apiserver/pkg/registry/generic/registry/store_test.go#L674-L728

can you describe the behavior you are seeing?

@liggitt Even my feeling is the same that we shouldn't be changing RVs for no-ops. There's sth else in play here - needs more digging.

To summarize, here's what we observed:

1. PATCH daemonset calls coming every minute from both fluentd-scaler and addon-manager (verified this by individually turning them on/off). Things we need to understand here:

• Is the daemonset object continuously toggling b/w 2 states? (we know here that it's RV is increasing continuously)
• If yes, what field(s) in the object are changing? IIRC value of some label/annotation (I think 'UpdatedPodsScheduled') is changing (probably related to 2 below)
• Also, why/should the fluentd-scaler send any api request if the resources are already set to the right value?

2. Fluentd pods are getting deleted and recreated by daemonset-controller when the scaler is enabled (as was also seen in Increase in apiserver/c-m mem usage by 100-200 MB in 100-node cluster #60500 (comment)). Why this is happening? One thing to note here - all those delete calls are preceded by PUT pod-status calls from respective kubelets (but maybe that's expected).

Summarizing the entire issue:

• Apiserver mem-usage increased: We found the reason and it's expected (ref). I sent a PR increasing the threshold for our scalability tests along with a release note explaining the effect (Increase apiserver mem-threshold in density test #61118) - it's now merged.
• Controller-manager mem-usage increased: We found the reason (ref) and it exposed a bug with fluentd-scaler. I've filed Fluentd-scaler causing fluentd pod deletions and messes with ds-controller #61190 against sig-instrumentation to separately track this (as a release-blocker).
• Flakes we're generally seeing with our density test: I've filed Flaky timeouts while waiting for RC pods to be running in density test #61189 to separately track it (currently a non-blocker).

IMO we can now close this issue and follow-up individually on those.

@jdumars @jberkus