Bug 2038275: *: Use --v=2 logging to drop client-side throttling noise #723
Conversation
|
@jottofar: No Bugzilla bug is referenced in the title of this pull request. In response to this:
Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. |
|
/hold |
openshift-ci
bot
added
the
do-not-merge/hold
openshift-ci
bot
added
the
approved
We've been using --v=5 since 88c222c (install/0000_00_cluster-version-operator_03_deployment: Bump to --v=5, 2020-08-30, openshift#448). But it leads to large quantities of noise from client-side throttling [1], and that throttling is V(3): $ grep -n . vendor/k8s.io/client-go/rest/request.go | grep -B7 -A6 '^597:' 589: switch { 590: case len(retryInfo) > 0: 591: message = fmt.Sprintf("Waited for %v, %s - request: %s:%s", latency, retryInfo, r.verb, r.URL().String()) 592: default: 593: message = fmt.Sprintf("Waited for %v due to client-side throttling, not priority and fairness, request: %s:%s", latency, r.verb, r.URL().String()) 594: } 596: if latency > longThrottleLatency { 597: klog.V(3).Info(message) 598: } 599: if latency > extraLongThrottleLatency { 600: // If the rate limiter latency is very high, the log message should be printed at a higher log level, 601: // but we use a throttled logger to prevent spamming. 602: globalThrottledLogger.Infof("%s", message) 603: } Auditing: $ git --no-pager grep 'klog.V([3-5])' vendor I don't see much that I'd miss. I liked having vendor/github.com/openshift/library-go/pkg/verify's logging back when we made that pivot, but now that that code is old and stable, I'm ok losing it. I've shifted the lib/ stuff down to V(2) using: $ sed -i 's/klog[.]V([3-5])/klog.V(2)/g' $(git grep -l klog.V lib) It's mostly hotloop-detection since 40d0a4e (Log object updates and show existing/required diff, 2021-06-03, openshift#561, [2]), and isn't all that noisy since 05e1af7 (Bug 1984414: Log resource diffs on update only in reconcile mode, 2021-07-22, openshift#628, [3]). I've shifted the pkg/ stuff down to V(2) using: $ sed -i 's/klog[.]V([3-5])/klog.V(2)/g' $(git grep -l klog.V pkg) It's mostly fairly core stuff, and low-noise except for the per-manifest "Running sync for ..." and "Done syncing for ..." messages [1]. The per-manifest messages can be useful to identify where the CVO is in the sync cycle, so I'm keeping them for now. We may be able to punt them up to higher levels if we get an alternative mechanism for identifying sync cycle positions (e.g. events for task-node completion or task failure). [1]: https://bugzilla.redhat.com/show_bug.cgi?id=2034493#c1 [2]: https://bugzilla.redhat.com/show_bug.cgi?id=1879184 [3]: https://bugzilla.redhat.com/show_bug.cgi?id=1984414
|
/unhold |
openshift-ci
bot
removed
the
do-not-merge/hold
wking
changed the title
openshift-ci
bot
added
bugzilla/severity-medium
|
@jottofar: This pull request references Bugzilla bug 2038275, which is valid. The bug has been moved to the POST state. The bug has been updated to refer to the pull request using the external bug tracker. 6 validation(s) were run on this bug
Requesting review from QA contact: In response to this:
Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. |
|
/label backport-risk-assessed |
openshift-ci
bot
added
the
backport-risk-assessed
|
[APPROVALNOTIFIER] This PR is APPROVED This pull-request has been approved by: jottofar, LalatenduMohanty, wking The full list of commands accepted by this bot can be found here. The pull request process is described here
Needs approval from an approver in each of these files:
Approvers can indicate their approval by writing |
|
/retest-required Please review the full test history for this PR and help us cut down flakes. |
|
sandboxes are orthogonal: /override ci/prow/e2e-agnostic-upgrade |
|
@wking: Overrode contexts on behalf of wking: ci/prow/e2e-agnostic-upgrade In response to this:
Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. |
|
/retest-required Please review the full test history for this PR and help us cut down flakes. |
2 similar comments
|
/retest-required Please review the full test history for this PR and help us cut down flakes. |
|
/retest-required Please review the full test history for this PR and help us cut down flakes. |
|
@jottofar: all tests passed! Full PR test history. Your PR dashboard. Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here. |
|
/label cherry-pick-approved |
openshift-ci
bot
added
the
cherry-pick-approved
|
@jottofar: All pull requests linked via external trackers have merged: Bugzilla bug 2038275 has been moved to the MODIFIED state. In response to this:
Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. |
|
/cherry-pick release-4.8 |
|
@sdodson: #723 failed to apply on top of branch "release-4.8": In response to this:
Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. |
We've been using --v=5 since 88c222c
(install/0000_00_cluster-version-operator_03_deployment: Bump to
--v=5, 2020-08-30, #448). But it leads to large quantities of noise
from client-side throttling 1, and that throttling is V(3):
$ grep -n . vendor/k8s.io/client-go/rest/request.go | grep -B7 -A6 '^597:'
589: switch {
590: case len(retryInfo) > 0:
591: message = fmt.Sprintf("Waited for %v, %s - request: %s:%s", latency, retryInfo, r.verb, r.URL().String())
592: default:
593: message = fmt.Sprintf("Waited for %v due to client-side throttling, not priority and fairness, request: %s:%s", latency, r.verb, r.URL().String())
594: }
596: if latency > longThrottleLatency {
597: klog.V(3).Info(message)
598: }
599: if latency > extraLongThrottleLatency {
600: // If the rate limiter latency is very high, the log message should be printed at a higher log level,
601: // but we use a throttled logger to prevent spamming.
602: globalThrottledLogger.Infof("%s", message)
603: }
Auditing:
$ git --no-pager grep 'klog.V([3-5])' vendor
I don't see much that I'd miss. I liked having
vendor/github.com/openshift/library-go/pkg/verify's logging back when
we made that pivot, but now that that code is old and stable, I'm ok
losing it.
I've shifted the lib/ stuff down to V(2) using:
$ sed -i 's/klog[.]V([3-5])/klog.V(2)/g' $(git grep -l klog.V lib)
It's mostly hotloop-detection since 40d0a4e (Log object updates and
show existing/required diff, 2021-06-03, #561, 2), and isn't all
that noisy since 05e1af7 (Bug 1984414: Log resource diffs on update
only in reconcile mode, 2021-07-22, #628, 3).
I've shifted the pkg/ stuff down to V(2) using:
$ sed -i 's/klog[.]V([3-5])/klog.V(2)/g' $(git grep -l klog.V pkg)
It's mostly fairly core stuff, and low-noise except for the
per-manifest "Running sync for ..." and "Done syncing for ..."
messages 1. The per-manifest messages can be useful to identify
where the CVO is in the sync cycle, so I'm keeping them for now. We
may be able to punt them up to higher levels if we get an alternative
mechanism for identifying sync cycle positions (e.g. events for
task-node completion or task failure).