util/log: use runtime.CallersFrames instead of runtime.Callers

[tbg]

http://talks.godoc.org/github.com/davecheney/go-1.9-release-party/presentation.slide#20

[tschottdorf@macts-2 cockroach (node-info)]$ git grep runtime.Caller
pkg/storage/timedmutex.go:                      if pc, _, _, ok := runtime.Caller(2); ok {
pkg/storage/track_raft_protos.go:               if numCallers := runtime.Callers(0, pcs[:]); numCallers == len(pcs) {
pkg/storage/track_raft_protos.go:               frames := runtime.CallersFrames(pcs[:])
pkg/util/caller/resolver.go:// A CallResolver is a helping hand around runtime.Caller() to look up file,
pkg/util/caller/resolver.go:// it's unable to look up its own location via runtime.Caller().
pkg/util/caller/resolver.go:    _, file, _, ok := runtime.Caller(0)
pkg/util/caller/resolver.go:    pc, file, line, ok := runtime.Caller(depth + 1)
pkg/util/caller/resolver.go:                    // "path/filepath" because runtime.Caller always returns unix paths.
pkg/util/caller/resolver_test.go:               // NB: runtime.Caller always returns unix paths.
pkg/util/envutil/env.go:        _, consumer, _, _ := runtime.Caller(depth + 1)
pkg/util/log/clog.go:           if runtime.Callers(2+depth, logging.pcs[:]) == 0 {
pkg/util/log/test_log_scope.go: runtime.Callers(2, pcs[:])
pkg/util/log/test_log_scope.go: frames := runtime.CallersFrames(pcs[:])
pkg/util/smalltrace.go: nCallers := runtime.Callers(skip, pcs[:])
pkg/util/smalltrace.go: frames := runtime.CallersFrames(pcs[:])

[petermattis]

We should do this, but I don't think it is urgent as mid-stack inlining was not enabled by default for go1.9.

[knz]

I think for performance it would do us good to enable mid-stack inlining in CockroachDB.

[petermattis]

I have the same intuition about mid-stack inlining, yet when I enabled it I could not measure a performance difference:

I did a quick test of --gcflags=-l=4. It bumped the binary size by 7.5%, but I couldn't measure a performance impact on a read-only workload. Perhaps I did something wrong. I'll take another look at this later.

[petermattis]

See also golang/go#19348 which mentions that --gcflags=-l=4 is unsupported/untested in go1.9.

[dAdAbird]

Wanted to make it, but there's nothing to do.

As 1.9 release notes state (https://golang.org/doc/go1.9#callersframes):

Users of runtime.Callers should avoid directly inspecting the resulting PC slice and instead use runtime.CallersFrames to get a complete view of the call stack, or runtime.Caller to get information about a single caller.

I haven't found any direct iteration over PC slice in code. All runtime.Callers PCs is used with runtime.CallersFrames.

Anyway runtime.CallersFrames is not a replacement for runtime.Callers, it's a replacement for pc[i] useing.

[knz]

@dAdAbird thanks for the investigation.
What about the code in pkg/util/log/clog.go where the pc[] array is used directly? I think this needs to be changed.

[dAdAbird]

@knz yeah, you're right, I didn't notice it.
Just in case, to use runtime.CallersFrames here, logging.pcs should have size 2 in order to keep runtime.skipPleaseUseCallersFrames pc along with the caller's pc. But I don't think it's a big issue.

Also, it worth to look closer at runtime.FuncForPC(pc) calls. For example here:
https://github.com/cockroachdb/cockroach/blob/v1.1-beta.20170921/pkg/storage/timedmutex.go#L62-L66 - if there are some inlined functions, despite the Caller return right "file" and "line" (for inlined func) pc always points to the "physical" frame:

package main

import (
	"fmt"
	"runtime"
)

func a() {
	b()
}

func b() {
	pc, _, line, _ := runtime.Caller(1)
	fmt.Println(line, runtime.FuncForPC(pc).Name())
}

func main() {
	a()
}

# go run -gcflags '-l=4' main.go
9 main.main

#go run  main.go
9 main.a

I'd like to take this issue if nobody works on it.

[knz]

Please do! That'd be great.