perf(logging): prevent unnecessary processing for debug logging

[jayzhudev]

The debug logging calls can consume significant amount of CPU resources at scale because many of them use function call returns directly as arguments. This resulted in expensive functions being called anyway regardless of the value of debugLibrary. This commit prevents such unnecessary processing.

This commit also includes performance improvements from reducing expensive string split calls and using more performant int/uint to ascii conversions.

Here are some rough reference numbers from e2e testing sending 2000 leaf-list updates in a SetRequest:

Version	Time
Before #828	~2,300 ms
After #828	~1,600 ms

[google-cla]

Thanks for your pull request! It looks like this may be your first contribution to a Google open source project. Before we can look at your pull request, you'll need to sign a Contributor License Agreement (CLA).

View this failed invocation of the CLA check for more information.

For the most up to date status, view the checks section at the bottom of the pull request.

[jayzhudev]

Note: I'm working on getting my username added to our CLA group. Will keep you posted : )

[jayzhudev]

Update: the CLA check is passing now.

[coveralls]

Coverage: 88.89% (-1.2%) from 90.12% when pulling ad55b2f on jayzhudev:logging-perf into cbef8ea on openconfig:master.

[wenovus]

can change the last case to

case !util.IsValueMap(reflect.ValueOf(root)):

[jayzhudev]

If I understand the context correctly, rvis used in the code block after the switch and if statements:

	switch {
	case schema.Key == "":
		return nil, status.Errorf(codes.InvalidArgument, "unkeyed list can't be traversed, type %T, path %v", root, path)
	case len(path.GetElem()) == 0:
		return nil, status.Errorf(codes.InvalidArgument, "path length is 0, schema %v, root %v", schema, root)
	}

	rv := reflect.ValueOf(root)
	if !util.IsValueMap(rv) {
		return nil, status.Errorf(codes.InvalidArgument, "root has type %T, expect map", root)
	}

	var matches []*TreeNode

	listKeyT := rv.Type().Key()
	listElemT := rv.Type().Elem()
	for _, k := range rv.MapKeys() {
		listElemV := rv.MapIndex(k)

...

I think the thought process when this change was made was to reuse rv so reflect.ValueOf is not called twice.

[wenovus]

I see, thanks for pointing it out.

[wenovus]

Does this actually improve performance? Split and Contains both do a full scan of the string right? I'm ok with keeping this, just it does make the code slightly harder to read.

[jayzhudev]

Thanks for the question. Yes, strings.Split is much more expensive than Contains since it does heap allocation. Here's the result from a simple benchmark test:

goos: linux
goarch: amd64
pkg: perf_testing/string_split
BenchmarkSplitString
BenchmarkSplitString-4      	 4926440	       256.6 ns/op	     160 B/op	       1 allocs/op
BenchmarkContainsString
BenchmarkContainsString-4   	243211302	         4.925 ns/op	       0 B/op	       0 allocs/op
PASS
ok  	perf_testing/string_split	3.246s

func splitString(s string) {
	_ = len(strings.Split(s, "/"))
}

func containsString(s string) {
	_ = strings.Contains(s, "/")
}

var testStr = "abc/def/abc/def/abc/def/abc/def/abc/def"

func BenchmarkSplitString(b *testing.B) {
	for i := 0; i < b.N; i++ {
		splitString(testStr)
	}
}

func BenchmarkContainsString(b *testing.B) {
	for i := 0; i < b.N; i++ {
		containsString(testStr)
	}
}

[jayzhudev]

Here's the genSplit code. It also must pass through the entire string as oppose to strings.Contains can early stop at the first occurrence:

// Generic split: splits after each instance of sep,
// including sepSave bytes of sep in the subarrays.
func genSplit(s, sep string, sepSave, n int) []string {
	if n == 0 {
		return nil
	}
	if sep == "" {
		return explode(s, n)
	}
	if n < 0 {
		n = Count(s, sep) + 1
	}

	if n > len(s)+1 {
		n = len(s) + 1
	}
	a := make([]string, n)
	n--
	i := 0
	for i < n {
		m := Index(s, sep)
		if m < 0 {
			break
		}
		a[i] = s[:m+sepSave]
		s = s[m+len(sep):]
		i++
	}
	a[i] = s
	return a[:i+1]
}

[wenovus]

I was considering the case where no separators "|" or "/" were present, since that is the only case where the early return does save time. In this case I think not much heap allocations need to be made for adding new path elements, but I agree it still saves that allocation. So I'm good with keeping it. LGTM

[wenovus]

@robshakir for any comments before merge. The coverage decreased because the the debugging statements inside the if statements are not covered. Since these are debugging statements I'm ok with them being uncovered.