KObj: avoid reflection

[pohly]

/kind feature

Describe the solution you'd like

klog/klog.go

Lines 1575 to 1577 in 84f3ebd

	if val := reflect.ValueOf(obj); val.Kind() == reflect.Ptr && val.IsNil() {
	return ObjectRef{}
	}

is used to detect whether using the KMetadata instance is likely to crash. This targets one particular case (nil pointer to Kubernetes object), but isn't a generic solution.

It also might be slower that simply calling the Name and Namespace functions and handling any failure with recover, which is the approach taken in #299 for other user supplied objects.

We should write a benchmark for this and then pick the faster approach.

/cc @serathius

[serathius]

/help

[k8s-ci-robot]

@serathius:
This request has been marked as needing help from a contributor.

Guidelines

Please ensure that the issue body includes answers to the following questions:

• Why are we solving this issue?
• To address this issue, are there any code changes? If there are code changes, what needs to be done in the code and what places can the assignee treat as reference points?
• Does this issue have zero to low barrier of entry?
• How can the assignee reach out to you for help?

For more details on the requirements of such an issue, please see here and ensure that they are met.

If this request no longer meets these requirements, the label can be removed
by commenting with the /remove-help command.

In response to this:

/help

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.

[dharmjit]

/assign

[dharmjit]

Thanks @pohly for providing more context in the slack convo. Below are the benchmark results for existing/newerKObj implementation. I see that the results do not reflect what is expected. Am I missing something?

--- klog_test.go
func BenchmarkKObjNil(b *testing.B) {
	var a *test.KMetadataMock
	var r ObjectRef
	for i := 0; i < b.N; i++ {
		r = KObj(a)
	}
	result = r
}

Existing implementation:

> go test -benchmem -count=5 -run=^$ -bench ^BenchmarkKObjNil$ k8s.io/klog/v2 > old.txt
goos: linux
goarch: amd64
pkg: k8s.io/klog/v2
cpu: Intel(R) Xeon(R) Gold 6138 CPU @ 2.00GHz
BenchmarkKObjNil-4   	183096483	         7.116 ns/op	       0 B/op	       0 allocs/op
BenchmarkKObjNil-4   	170539461	         6.721 ns/op	       0 B/op	       0 allocs/op
BenchmarkKObjNil-4   	189434904	         6.617 ns/op	       0 B/op	       0 allocs/op
BenchmarkKObjNil-4   	169627648	         6.374 ns/op	       0 B/op	       0 allocs/op
BenchmarkKObjNil-4   	192950755	         6.608 ns/op	       0 B/op	       0 allocs/op
PASS
ok  	k8s.io/klog/v2	9.442s

Updated implementation:

--- klog.go
func KObj(obj KMetadata) (objref ObjectRef) {
	if obj == nil {
		return ObjectRef{}
	}
	defer func() {
		if err := recover(); err != nil {
			objref = ObjectRef{}
		}
	}()
	return ObjectRef{
		Name:      obj.GetName(),
		Namespace: obj.GetNamespace(),
	}
}
> go test -benchmem -count=5 -run=^$ -bench ^BenchmarkKObjNil$ k8s.io/klog/v2 > new.txt
goos: linux
goarch: amd64
pkg: k8s.io/klog/v2
cpu: Intel(R) Xeon(R) Gold 6138 CPU @ 2.00GHz
BenchmarkKObjNil-4   	 1671920	       702.1 ns/op	     128 B/op	       2 allocs/op
BenchmarkKObjNil-4   	 1681357	       742.2 ns/op	     128 B/op	       2 allocs/op
BenchmarkKObjNil-4   	 1655552	       756.1 ns/op	     128 B/op	       2 allocs/op
BenchmarkKObjNil-4   	 1623291	       714.5 ns/op	     128 B/op	       2 allocs/op
BenchmarkKObjNil-4   	 1529310	       746.0 ns/op	     128 B/op	       2 allocs/op
PASS
ok  	k8s.io/klog/v2	9.721s

Benchstat Results

>benchstat old.txt new.txt 
name       old time/op    new time/op    delta
KObjNil-4    6.69ns ± 6%  732.18ns ± 4%  +10848.98%  (p=0.008 n=5+5)

name       old alloc/op   new alloc/op   delta
KObjNil-4     0.00B        128.00B ± 0%       +Inf%  (p=0.008 n=5+5)

name       old allocs/op  new allocs/op  delta
KObjNil-4      0.00           2.00 ± 0%       +Inf%  (p=0.008 n=5+5)

[pohly]

This isn't entirely unexpected. Instead of avoiding a nil pointer access (current approach) the new approach is to let the access happen and then recover from it. That is expensive.

But it may still be worthwhile if it makes the common case of not hitting a nil pointer faster. Can you post the results for the existing KObj benchmark, too?

[dharmjit]

Can you post the results for the existing KObj benchmark, too?

Results for existing implementation for nil pointer are already posted in the above comment. Below are the results with well-formed parameters for both the implementations.

Existing implementation:

> go test -benchmem -count=5 -run=^$ -bench ^BenchmarkKObj$ k8s.io/klog/v2 | tee old-params.txt
goos: linux
goarch: amd64
pkg: k8s.io/klog/v2
cpu: Intel(R) Xeon(R) Gold 6138 CPU @ 2.00GHz
BenchmarkKObj-4         100000000               11.77 ns/op            0 B/op          0 allocs/op
BenchmarkKObj-4         100000000               12.00 ns/op            0 B/op          0 allocs/op
BenchmarkKObj-4         100000000               11.63 ns/op            0 B/op          0 allocs/op
BenchmarkKObj-4         100000000               10.74 ns/op            0 B/op          0 allocs/op
BenchmarkKObj-4         100000000               11.18 ns/op            0 B/op          0 allocs/op
PASS
ok      k8s.io/klog/v2  5.807s

Updated Implementation:

> go test -benchmem -count=5 -run=^$ -bench ^BenchmarkKObj$ k8s.io/klog/v2 | tee new-params.txt
goos: linux
goarch: amd64
pkg: k8s.io/klog/v2
cpu: Intel(R) Xeon(R) Gold 6138 CPU @ 2.00GHz
BenchmarkKObj-4         87020683                14.37 ns/op            0 B/op          0 allocs/op
BenchmarkKObj-4         75794769                15.51 ns/op            0 B/op          0 allocs/op
BenchmarkKObj-4         80299812                13.94 ns/op            0 B/op          0 allocs/op
BenchmarkKObj-4         77973676                16.56 ns/op            0 B/op          0 allocs/op
BenchmarkKObj-4         85203490                15.54 ns/op            0 B/op          0 allocs/op
PASS
ok      k8s.io/klog/v2  7.051s

Benchstat Results

benchstat old-params.txt new-params.txt 
name    old time/op    new time/op    delta
KObj-4    11.5ns ± 6%    15.2ns ± 9%  +32.45%  (p=0.008 n=5+5)

name    old alloc/op   new alloc/op   delta
KObj-4     0.00B          0.00B          ~     (all equal)

name    old allocs/op  new allocs/op  delta
KObj-4      0.00           0.00          ~     (all equal)

[pohly]

KObj-4 11.5ns ± 6% 15.2ns ± 9% +32.45% (p=0.008 n=5+5)

So it's not faster for the well-formed calls either. Looks like the reflect.ValueOf call is cheaper than the defer + recover() combination.

That leaves "more complete solution" as the only reason for using the second approach. Given that it has been shown to be slower, that IMHO isn't sufficient to change anything.

[dharmjit]

Looks like the reflect.ValueOf call is cheaper than the defer + recover() combination

Anything else you wanted me to take a look at.

[pohly]

I think we can close this issue here. kubernetes/kubernetes#106945 is kind of related (also about performance).

/close

[k8s-ci-robot]

@pohly: Closing this issue.

In response to this:

I think we can close this issue here. kubernetes/kubernetes#106945 is kind of related (also about performance).

/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.