/priority important-soon
/sig api-machinery

/sig instrumentation

/cc @logicalhan

/test pull-kubernetes-e2e-gce-ubuntu-containerd

@logicalhan This change doesn't look like it's changing the throttling setting, but rather the log level at which the globalThrottledLogger logs.
This change
https://github.com/kubernetes/kubernetes/blob/f7bd79539240c57bd1a99795526880914e9e228b/staging/src/k8s.io/client-go/rest/request.go#L636
influences which logLevel is used for the this line
https://github.com/kubernetes/kubernetes/blob/f7bd79539240c57bd1a99795526880914e9e228b/staging/src/k8s.io/client-go/rest/request.go#L668
And the origin of the log message is ultimately here:
https://github.com/kubernetes/kubernetes/blob/f7bd79539240c57bd1a99795526880914e9e228b/staging/src/k8s.io/client-go/rest/request.go#L605

And it's true, it was last changed in the PR #88134 that @SataQiu linked. One commit before that the general log level for the globalThrottledLogger was set to 2 here:
https://github.com/jennybuckley/kubernetes/blob/0dfe0c793b5b85bd85cec7b77679ba78c1617357/staging/src/k8s.io/client-go/rest/request.go#L559

Since I updated my kubectl to include commit #88134 in my build I'm getting a lot of logs of the form

Waited for 1.140352693s due to client-side throttling, not priority and fairness, request: GET:https://10.212.0.242/apis/storage.k8s.io/v1beta1?timeout=32s

When querying any resource.

Hope this explanation helps and I give this a +1 to merge because this info is not useful for most api clients. And for the ones that need a bit more verbosity it will still show up when set verbosity to 1.

/triage accept
/assign @logicalhan

@caesarxuchao: The label(s) triage/accept cannot be applied, because the repository doesn't have them.

/triage accepted

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: logicalhan, SataQiu
To complete the pull request process, please assign yliaog after the PR has been reviewed.
You can assign the PR to them by writing /assign @yliaog in a comment when ready.

The full list of commands accepted by this bot can be found here.

/assign @liggitt

/unassign
/assign @lavalamp

looks like #88134 cited #87740 (comment) as the reason for the higher log level

Printing the latency logs by default will break the user's original behavior, especially if they are doing something with the command output.

It prints to stderr, right? There are many things that can print to stderr, I would not expect structured output to be passed via that output

@liggitt Maybe V(1) and V(2) would be appropriate log levels (instead of V(0) and V(2)).

cc @deads2k

TBH, the messages have been useful to us at their current level because component authors find them and wonder why they see them. I'm biased towards keeping delays of over one second as info level messages.

@SataQiu do you have examples of healthy components (no hot or warm loops) with properly configured client-side rate limits seeing this message unnecessarily? It seems like these messages at an info level would be helpful, not harmful.

Printing the latency logs by default will break the user's original behavior, especially if they are doing something with the command output.

It prints to stderr, right? There are many things that can print to stderr, I would not expect structured output to be passed via that output

Emm...
As @liggitt said, there should be a workaround(such as kubectl get pod 2>/dev/null) to shutting out additional output.

/close

@SataQiu: Closed this PR.

My guess is that most people don't know they are using client side rate limits and on average printing this log message saves 10 hours of debugging for every hour it costs someone trying to hide it.

@lavalamp since everyone finds these messages helpful maybe I'm just interpreting them wrong. And rather than wanting to hide them I should figure out what causes them.
What could I do to eliminate the cause for this client-side throttling as a platform owner?

Edit: I know that our clusters have many CRDs (mainly through cloud vendor provisioners like Google Config Connector) and I know it has to do with that amount of CRDs and the discovery cache that kubernetes keeps around. But I don't know how to improve on the situation and how to not constantly run into rate-limiting...

$ kubectl get crd | awk 'NR>1' | wc -l
     225

@jonnylangefeld In code you can modify the rest.Config struct fields QPS and Burst. -1 disables, 0 chooses a default (50qps IIRC). Now that APF is defaulted on, I think most users can just disable client side limits and let the server worry about it (exception is if there are many watchers of the resources you are modifying, e.g. endpoints).

We were going to add these to kubeconfig but didn't because it's only applicable to the standard go client: kubernetes/enhancements#1630

Some binaries (kube-controller-manager) might expose command line flags for these.

Thanks for the explanation! hmm so for kubectl that would mean we maintain our own fork and build ourselves?

How are you hitting this limit with kubectl?

It seems like that has to do with the discovery cache. If I run kubectl get pod -v 8 I see 100s of requests made. They're all of this sort:

GET https://<host>/apis/dns.cnrm.cloud.google.com/v1beta1?timeout=32s
GET https://<host>/apis/templates.gatekeeper.sh/v1alpha1?timeout=32s
GET https://<host>/apis/firestore.cnrm.cloud.google.com/v1beta1?timeout=32s

So it's requests to all the custom resources we have installed on the cluster.
Only the very last request is for the actual pods:

GET https://10.216.64.18/api/v1/namespaces/default/pods?limit=500

I think the many GET requests trigger the client-side throttling.
This reddit post explains the discovery cache behavior, but not how it can be circumvented or at least not rate limited.

OK, that was going to be my guess. How many CRDs do you have? You should need over 100 group versions to trigger this.

Yeah we have a bunch. As mentioned in my comment above it's over 200 individual CRD resources:

$ kubectl get crd | awk 'NR>1' | wc -l
     225

And since you said only distinct group versions matter, I ran the following:

$ kubectl get crd -o json | jq -r '.items[] | "Group: " + .spec.group + "; Version: " + .spec.versions[0].name' | sort | uniq | wc -l
     72

So not quite 100 group versions but close.
We reach that fairly quick with istio, Google's Config Connector, gatekeeper, velero, cert-manager and a few in-house controllers.

Now the question would be: What options do we have to either extend the validity of the cache (so it can rely on it longer), or maybe even better only build the cache if I'm querying for a resource that's not already in the discovery cache?
Do you think that would be feasible?

That jq query is undercounting (need to emit a name for every version, not just the first).

I have filed an issue about this since no one is going to see this buried here :) #105489

Thanks for the report.