structured-logging: replace KObjs with KObjSlice for logging #110747

harshanarayana · 2022-06-23T15:37:41Z

What type of PR is this?

/kind feature

What this PR does / why we need it:

This Pull request replaces the KObjs with their better performing counter part KObjSlice. Since build: update to klog v2.70.0 #110724 is now merged, We can reap the benefits of the change that went into the klog via replace KObjs with KObjSlice klog#322
As part of the changes done to address Kubelet JSON logging performance test #102430, there was a Pull request that got merged (log message verbosity #106978) which made some changes to how the klog.V(x).Enabled checks were being made. This PR also takes second look at some of those changes to see if the if klogV := klog.V(x); klogV.Enabled() wrapping is actually required or they can simply be replaced with the klog.V(x).Info{f|S}. Currently this PR only replaces those items that do not have additional computation done for the logging artifacts under the if klogV := klog.V(x); klogV.Enabled() check with their counter part of klog.V(x) calls directly.

Which issue(s) this PR fixes:

Fixes #110737

Special notes for your reviewer:

Benchmark for `getReplicaSetsWithSameController` under `replca_set.go`

Original changes were retained as is for the if condition wrapping for better performance

# With Changes
BenchmarkGetReplicaSetsWithSameController
BenchmarkGetReplicaSetsWithSameController-12    	 3291576	       355.9 ns/op	     184 B/op	       6 allocs/op
BenchmarkGetReplicaSetsWithSameController-12    	 3359475	       360.1 ns/op	     184 B/op	       6 allocs/op
BenchmarkGetReplicaSetsWithSameController-12    	 3335294	       368.1 ns/op	     184 B/op	       6 allocs/op
BenchmarkGetReplicaSetsWithSameController-12    	 3296937	       361.2 ns/op	     184 B/op	       6 allocs/op
BenchmarkGetReplicaSetsWithSameController-12    	 3275090	       389.7 ns/op	     184 B/op	       6 allocs/op

# Without Changes
BenchmarkGetReplicaSetsWithSameController
BenchmarkGetReplicaSetsWithSameController-12    	 5501926	       202.4 ns/op	      48 B/op	       2 allocs/op
BenchmarkGetReplicaSetsWithSameController-12    	 5227614	       200.0 ns/op	      48 B/op	       2 allocs/op
BenchmarkGetReplicaSetsWithSameController-12    	 6073863	       196.5 ns/op	      48 B/op	       2 allocs/op
BenchmarkGetReplicaSetsWithSameController-12    	 6055270	       199.4 ns/op	      48 B/op	       2 allocs/op
BenchmarkGetReplicaSetsWithSameController-12    	 6022762	       195.6 ns/op	      48 B/op	       2 allocs/op

Does this PR introduce a user-facing change?

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

[Usage]: https://github.com/kubernetes/community/pull/6719

TODO

Attach Benchmarking results for the changes

k8s-ci-robot · 2022-06-23T15:37:43Z

Skipping CI for Draft Pull Request.
If you want CI signal for your change, please convert it to an actual PR.
You can still manually trigger a test run with /test all

leilajal · 2022-06-23T16:40:49Z

/remove-sig api-machinery

harshanarayana · 2022-06-24T06:55:34Z

staging/src/k8s.io/apiserver/pkg/util/flowcontrol/fairqueuing/queueset/queueset.go

@@ -951,9 +951,7 @@ func (qs *queueSet) boundNextDispatchLocked(queue *queue) {
 	}
 	var virtualStartBound = oldestReqFromMinQueue.arrivalR
 	if queue.nextDispatchR < virtualStartBound {
-		if klogV := klog.V(4); klogV.Enabled() {


Working on benchmarking this function. Will update once i have the details here.

I had no success in getting a clean way to write a benchmark test for this function. Any suggestion on this @pohly ?

If the SIG doesn't already have benchmarks, then writing one is hard because it depends on domain knowledge.

When in doubt, leave the if check in place.

dims · 2022-06-24T12:36:08Z

/test all

harshanarayana · 2022-06-27T16:12:33Z

/test pull-kubernetes-conformance-kind-ga-only-parallel

harshanarayana · 2022-06-27T16:12:41Z

/test pull-kubernetes-e2e-gce-storage-snapshot

harshanarayana · 2022-06-27T18:33:54Z

/test pull-kubernetes-e2e-gce-storage-snapshot

harshanarayana · 2022-06-29T03:35:15Z

@pohly Sure. Let me update the title of the PR accordingly. Is the current description in PR good enough or do you want me to add a bit more context ?

pohly · 2022-06-29T06:10:42Z

The PR description is perfect. Lots of context and additional information.

dgrisonnet · 2022-06-30T16:36:16Z

/assign @pohly
/triage accepted

leilajal · 2022-06-30T16:45:50Z

/remove-sig api-machinery

pohly · 2022-07-01T05:49:28Z

pkg/controller/replicaset/replica_set.go

 	if klogV := klog.V(2); klogV.Enabled() {
-		klogV.InfoS("Found related ReplicaSets", "replicaSet", klog.KObj(rs), "relatedReplicaSets", klog.KObjs(relatedRSs))
+		klogV.InfoS("Found related ReplicaSets", "replicaSet", klog.KObj(rs), "relatedReplicaSets", klog.KObjSlice(relatedRSs))


Here you can simplify the code and remove the if check.

There was an existing benhmark for this already. Doing the check removal made it worse.

# With Changes BenchmarkGetReplicaSetsWithSameController BenchmarkGetReplicaSetsWithSameController-12 3291576 355.9 ns/op 184 B/op 6 allocs/op BenchmarkGetReplicaSetsWithSameController-12 3359475 360.1 ns/op 184 B/op 6 allocs/op BenchmarkGetReplicaSetsWithSameController-12 3335294 368.1 ns/op 184 B/op 6 allocs/op BenchmarkGetReplicaSetsWithSameController-12 3296937 361.2 ns/op 184 B/op 6 allocs/op BenchmarkGetReplicaSetsWithSameController-12 3275090 389.7 ns/op 184 B/op 6 allocs/op # Without Changes BenchmarkGetReplicaSetsWithSameController BenchmarkGetReplicaSetsWithSameController-12 5501926 202.4 ns/op 48 B/op 2 allocs/op BenchmarkGetReplicaSetsWithSameController-12 5227614 200.0 ns/op 48 B/op 2 allocs/op BenchmarkGetReplicaSetsWithSameController-12 6073863 196.5 ns/op 48 B/op 2 allocs/op BenchmarkGetReplicaSetsWithSameController-12 6055270 199.4 ns/op 48 B/op 2 allocs/op BenchmarkGetReplicaSetsWithSameController-12 6022762 195.6 ns/op 48 B/op 2 allocs/op

@pohly Do you want me to remote the entire logging bit here ?

I wonder whether this is related to KObjSlice and/or KObj at all. In other words, what is the performance difference between

klog.V(2).InfoS("Some key/value pairs", "a", 1, "b", "x")

and

if klogV := klog.V(2); klogV.Enabled() { klogV.InfoS("Some key/value pairs", "a", 1, "b", "x") }

It is clear that we pay some price for using the simpler one-line version, but how high is that price? I don't know.

Can you perhaps investigate? That'll put the slowdown for passing KObj and KObjSlice into perspective. If they are still "more expensive", then keeping the if check makes sense. If they are equally expensive, then it probably doesn't.

/ack . Let me do that and update back.

I had a look and came to the conclusion that the if klogV := klog.V(2); klogV.Enabled() variant is always faster. It matters a little bit more for KObjSlice than normal scalars because it needs additional memory allocations.

So lets keep the if check here.

yangjunmyfm192085

/retest

pohly

/lgtm

pohly · 2022-10-28T08:19:16Z

/assign @Random-Liu @smarterclayton

For approval.

smarterclayton · 2022-11-02T20:23:20Z

/approve

k8s-ci-robot · 2022-11-02T20:23:57Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: harshanarayana, pohly, smarterclayton

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:

~~pkg/controller/replicaset/OWNERS~~ [smarterclayton]
~~pkg/controller/volume/attachdetach/OWNERS~~ [smarterclayton]
~~pkg/kubelet/OWNERS~~ [smarterclayton]
~~staging/src/k8s.io/component-base/logs/OWNERS~~ [pohly,smarterclayton]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

pacoxu · 2022-11-03T02:46:44Z

This may need a release note. Would you add in the pr description?

pohly · 2022-11-03T06:47:31Z

/release-note-none

The only difference is some slight performance improvement.

k8s-ci-robot requested review from chrishenzie and krmayankk June 23, 2022 15:38

k8s-ci-robot removed the sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. label Jun 23, 2022

harshanarayana force-pushed the cleanup/GIT-110737/logging-improvements branch from bdca75c to 711364b Compare June 24, 2022 06:54

harshanarayana commented Jun 24, 2022

View reviewed changes

k8s-ci-robot added the sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. label Jun 24, 2022

harshanarayana marked this pull request as ready for review June 28, 2022 15:49

harshanarayana changed the title ~~GIT-110737: replace KObjs with KObjSlice for logging~~ structured-logging: replace KObjs with KObjSlice for logging Jun 29, 2022

k8s-ci-robot assigned pohly Jun 30, 2022

k8s-ci-robot added triage/accepted Indicates an issue or PR is ready to be actively worked on. and removed needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Jun 30, 2022

k8s-ci-robot removed the sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. label Jun 30, 2022

structured-logging: replace KObjs with KObjSlice for logging

c3cbc44

harshanarayana force-pushed the cleanup/GIT-110737/logging-improvements branch from 711364b to c3cbc44 Compare July 1, 2022 04:22

pohly suggested changes Jul 1, 2022

View reviewed changes

SergeyKanzhelev added this to Triage in SIG Node PR Triage Sep 19, 2022

pohly mentioned this pull request Oct 1, 2022

update logtools to support verbosity Zero Check #112215

Closed

yangjunmyfm192085 reviewed Oct 2, 2022

View reviewed changes

pohly approved these changes Oct 28, 2022

View reviewed changes

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Oct 28, 2022

k8s-ci-robot assigned Random-Liu and smarterclayton Oct 28, 2022

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Nov 2, 2022

k8s-ci-robot added release-note-none Denotes a PR that doesn't merit a release note. and removed do-not-merge/release-note-label-needed Indicates that a PR should not merge because it's missing one of the release note labels. labels Nov 3, 2022

k8s-ci-robot merged commit 98742f9 into kubernetes:master Nov 3, 2022

SIG Node PR Triage automation moved this from Triage to Done Nov 3, 2022

k8s-ci-robot added this to the v1.26 milestone Nov 3, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

structured-logging: replace KObjs with KObjSlice for logging #110747

structured-logging: replace KObjs with KObjSlice for logging #110747

harshanarayana commented Jun 23, 2022 •

edited

k8s-ci-robot commented Jun 23, 2022

leilajal commented Jun 23, 2022

harshanarayana Jun 24, 2022

harshanarayana Jun 28, 2022

pohly Jun 28, 2022

harshanarayana Jun 29, 2022

dims commented Jun 24, 2022

harshanarayana commented Jun 27, 2022

harshanarayana commented Jun 27, 2022

harshanarayana commented Jun 27, 2022

harshanarayana commented Jun 29, 2022

pohly commented Jun 29, 2022

dgrisonnet commented Jun 30, 2022

leilajal commented Jun 30, 2022

pohly Jul 1, 2022

harshanarayana Jul 1, 2022

harshanarayana Jul 1, 2022

pohly Aug 19, 2022

harshanarayana Aug 19, 2022

pohly Oct 28, 2022

yangjunmyfm192085 left a comment

pohly left a comment

pohly commented Oct 28, 2022

smarterclayton commented Nov 2, 2022

k8s-ci-robot commented Nov 2, 2022

pacoxu commented Nov 3, 2022

pohly commented Nov 3, 2022

structured-logging: replace KObjs with KObjSlice for logging #110747

structured-logging: replace KObjs with KObjSlice for logging #110747

Conversation

harshanarayana commented Jun 23, 2022 • edited

What type of PR is this?

What this PR does / why we need it:

Which issue(s) this PR fixes:

Special notes for your reviewer:

Benchmark for getReplicaSetsWithSameController under replca_set.go

Does this PR introduce a user-facing change?

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

TODO

k8s-ci-robot commented Jun 23, 2022

leilajal commented Jun 23, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dims commented Jun 24, 2022

harshanarayana commented Jun 27, 2022

harshanarayana commented Jun 27, 2022

harshanarayana commented Jun 27, 2022

harshanarayana commented Jun 29, 2022

pohly commented Jun 29, 2022

dgrisonnet commented Jun 30, 2022

leilajal commented Jun 30, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yangjunmyfm192085 left a comment

Choose a reason for hiding this comment

pohly left a comment

Choose a reason for hiding this comment

pohly commented Oct 28, 2022

smarterclayton commented Nov 2, 2022

k8s-ci-robot commented Nov 2, 2022

pacoxu commented Nov 3, 2022

pohly commented Nov 3, 2022

harshanarayana commented Jun 23, 2022 •

edited

Benchmark for `getReplicaSetsWithSameController` under `replca_set.go`