optimize KObj and KObjs

[pohly]

What would you like to be added?

Some small KObj performance improvement is possible by making it return a simple struct that converts the actual object only on demand - see kubernetes/klog#261

For KObjs, two optimizations are possible:

• the proxy approach above
• using Go generics

The benefit there might be even higher. I haven't measured it, but I am concerned that the current implementation:
https://github.com/kubernetes/klog/blob/7fa0f3b6c7f8269e5b2f296b038d3bf1532e9146/klog.go#L1716-L1731

is slower than the code that it could replace, for example:

kubernetes/pkg/controller/replicaset/replica_set.go

Lines 222 to 228 in cc6f125

	if klog.V(2).Enabled() {
	var relatedNames []string
	for _, r := range relatedRSs {
	relatedNames = append(relatedNames, r.Name)
	}
	klog.InfoS("Found related ReplicaSets", "replicaSet", klog.KObj(rs), "relatedReplicaSets", relatedNames)
	}

We cannot do that in klog (v2 API is frozen, having differently named functions would be confusing) but we can and should investigate this when moving the code (see kubernetes/enhancements#3078).

/sig instrumentation
/wg structured-logging
/assign

Why is this needed?

Better performance. Whether it is worthwhile needs to be measured.

[dashpole]

/triage accepted

[pohly]

See also kubernetes/klog#300

[pohly]

/unassign
/assign @dharmjit

Thanks for your help, please also look at KObjs.

[k8s-ci-robot]

@pohly: GitHub didn't allow me to assign the following users: dharmjit.

Note that only kubernetes members, repo collaborators and people who have commented on this issue/PR can be assigned. Additionally, issues/PRs can only have 10 assignees at the same time.
For more information please see the contributor guide

In response to this:

/unassign
/assign @dharmjit

Thanks for your help, please also look at KObjs.

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.

[pohly]

For KObjs, we need benchmark variants that iterate over slices of different lengths (1, 10, 100, ....).

[pohly]

We cannot do that in klog (v2 API is frozen, having differently named functions would be confusing) but we can and should investigate this when moving the code

Moving the code is no longer planned. If we find that the current KObjs has severe performance drawbacks, we need to consider what we can do about this in klog itself.

[dharmjit]

Thanks @pohly , I will take a look.

/assign

[dharmjit]

Sorry I got late on this. Below are the benchmarks for the proxy approach.

--- k8s_references.go
type ObjectRef2 struct {
	KMetadata
}

func (ref ObjectRef2) String() string {
	namespace := ref.GetNamespace()
	if namespace != "" {
		return fmt.Sprintf("%s/%s", namespace, ref.GetName())
	}
	return ref.GetName()
}

func (ref ObjectRef2) MarshalLog() interface{} {
	type or ObjectRef2
	return or(ref)
}

var _ logr.Marshaler = ObjectRef2{}

// KObj returns ObjectRef2 from ObjectMeta
func KObj2(obj KMetadata) ObjectRef2 {
	if obj == nil {
		return ObjectRef2{}
	}
	if val := reflect.ValueOf(obj); val.Kind() == reflect.Ptr && val.IsNil() {
		return ObjectRef2{}
	}

	return ObjectRef2{KMetadata: obj}
}

--- klog_test.go
func BenchmarkKObjs(b *testing.B) {
	arg := make([]KMetadata, 0)

        // to create different length KMetadata slices 
	for i := 0; i < 1000; i++ {
		a := test.KMetadataMock{Name: "a" + strconv.Itoa(i), NS: "a"}
		arg = append(arg, a)
	}
	var r []ObjectRef
	for i := 0; i < b.N; i++ {
		r = KObjs(arg)
	}
	results = r
}

Below are the benchmarks with different slice lengths. KObjs and BenchmarkKObjs are updated to capture newer KObj2 benchmarks

$ benchstat old-1.txt new-1.txt
name     old time/op    new time/op    delta
KObjs-4     182ns ± 5%     158ns ±10%  -13.48%  (p=0.008 n=5+5)

name     old alloc/op   new alloc/op   delta
KObjs-4     56.0B ± 0%     40.0B ± 0%  -28.57%  (p=0.008 n=5+5)

name     old allocs/op  new allocs/op  delta
KObjs-4      2.00 ± 0%      2.00 ± 0%     ~     (all equal)


$ benchstat old-10.txt new-10.txt
name     old time/op    new time/op    delta
KObjs-4     695ns ±11%     552ns ± 9%  -20.53%  (p=0.008 n=5+5)

name     old alloc/op   new alloc/op   delta
KObjs-4      344B ± 0%      184B ± 0%  -46.51%  (p=0.008 n=5+5)

name     old allocs/op  new allocs/op  delta
KObjs-4      2.00 ± 0%      2.00 ± 0%     ~     (all equal)


$ benchstat old-100.txt new-100.txt
name     old time/op    new time/op    delta
KObjs-4    5.02µs ±10%    4.14µs ± 5%  -17.69%  (p=0.008 n=5+5)

name     old alloc/op   new alloc/op   delta
KObjs-4    3.22kB ± 0%    1.82kB ± 0%  -43.67%  (p=0.008 n=5+5)

name     old allocs/op  new allocs/op  delta
KObjs-4      2.00 ± 0%      2.00 ± 0%     ~     (all equal)


$ benchstat old-1000.txt new-1000.txt
name     old time/op    new time/op    delta
KObjs-4    48.6µs ±10%    36.7µs ± 8%  -24.46%  (p=0.008 n=5+5)

name     old alloc/op   new alloc/op   delta
KObjs-4    32.8kB ± 0%    16.4kB ± 0%  -49.96%  (p=0.000 n=5+4)

name     old allocs/op  new allocs/op  delta
KObjs-4      2.00 ± 0%      2.00 ± 0%     ~     (all equal)

[pohly]

It sounds like you kept KObjs mostly unchanged and just changed the return value from []KObjectRef to []KObjectRef2. Is that correct? Posting a PR with your patch would clarify this.

It's interesting that this already shows an improvement. Where does that come from?

What I had in mind was different: if we change KObjs so that it just stores its parameters and analyses it only when needed, then we should see a huge performance improvement for the common case of calling a logging function without actually logging anything. Let me write that down as code, this might be faster than English prose.

[pohly]

When you post such a PR, don't bother introducing a second version of some function. Just pretend that breaking the klog API is okay and modify the existing functions.

[pohly]

For example, here's what I had in mind: kubernetes/klog#322

[dharmjit]

It sounds like you kept KObjs mostly unchanged and just changed the return value from []KObjectRef to []KObjectRef2

That is correct and it uses KObj2. dharmjit/klog

It's interesting that this already shows an improvement. Where does that come from?

Not sure but I suspect it could be from returning the interface type(KMetadata)

[pohly]

I've taken your commit and split it up for a before/after comparison: kubernetes/klog@main...pohly:kobjs-benchmark

Because ObjectRef changes, some additional tests had to be removed.

I can confirm that performance improves, but an API break for KObj doesn't seem worthwhile (IMHO).

[dharmjit]

Hi @pohly, Got caught up in the work so couldn't spend time on this. Is there anything else to look into for this issue?

[pohly]

I think we are done.

/close

[k8s-ci-robot]

@pohly: Closing this issue.

In response to this:

I think we are done.

/close

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.