Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

cmd/compile: wrong function location in stacktrace #26839

Closed
daskol opened this issue Aug 7, 2018 · 9 comments
Closed

cmd/compile: wrong function location in stacktrace #26839

daskol opened this issue Aug 7, 2018 · 9 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@daskol
Copy link

daskol commented Aug 7, 2018

What version of Go are you using (go version)?

$ go version
go version go1.10.3 linux/amd64

Does this issue reproduce with the latest release?

Yep.

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/daskol/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/daskol/proj"
GORACE=""
GOROOT="/usr/lib/go"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build715124347=/tmp/go-build -gno-record-gcc-switches"

What did you do?

https://play.golang.org/p/JefU2uAc-17

What did you expect to see?/What did you see instead?

The issue is how Golang prints location of callable objects. The snippet below descibres the issue.

main.(*A).Foo-fm()
	/tmp/sandbox285241419/main.go:13 +0x40

It says that it calls object located at main.go:13. The first of all that object in other function. And the second it is the function with the reveiver. So, I expect to see main.go:18 or main.go:19.

@ianlancetaylor ianlancetaylor added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Aug 7, 2018
@ianlancetaylor ianlancetaylor added this to the Go1.12 milestone Aug 7, 2018
@ianlancetaylor ianlancetaylor changed the title Wrong function location in stacktrace cmd/compile: wrong function location in stacktrace Aug 7, 2018
@ianlancetaylor
Copy link
Contributor

We've been getting this wrong since at least Go 1.3. gccgo gets it right. Odd.

CC @griesemer

@odeke-em
Copy link
Member

Thanks for filing this issue @daskol and thanks for checking on it @ianlancetaylor!

I think I have an idea on what the problem is just from the stacktrace and I'll hopefully work on this in the next couple of weeks when free.

@odeke-em odeke-em self-assigned this Oct 18, 2018
@odeke-em
Copy link
Member

odeke-em commented Dec 5, 2018

I got sometime to examine this issue this morning and as I had suspected,
the issue seems to be because:

Given a program https://play.golang.org/p/P1jZbt4zV-m or inlined below:

package main

type a int

func (_ a) do() {
	panic("panic")
}

func foo() {
	var x a
	_ = x.do
}

func bar() {
	var m a
	f := m.do
	f()
}

func main() {
	bar()
}

TL;DR:

when performing a partial call on assignment of a method as a variable and after the rewrite of struct { F uintptr; R <type> }, we create
a symbol with a name of the form <PACKAGE_NAME>.<SYMBOL_NAME> where <SYMBOL_NAME> is just <METHOD_NAME>. This causes a clash and you'll notice that even for any other usages of an assignment then invocation e.g.

var f = (a)(0).do
f()

will refer to the first occurance of the similar code usage i.e. line 11 and then line 6, as reported in the bug report

Long wind and investigation

The above symbol name generation is well and good until we have to link symbols, in which case every similar invocation or assignment will link to the first encountered and linked symbol because Linksym

return Ctxt.Lookup(sym.LinksymName())

retrieves names by the mechanism of <PACKAGE_NAME> + "." + <SYMBOL_NAME>

if sym.IsBlank() {
return "_"
}
if sym.Linkname != "" {
return sym.Linkname
}
return sym.Pkg.Prefix + "." + sym.Name
}

and this can be confirmed by tracing through the repro and on running go run -gcflags='-W' main.go
which produces https://gist.github.com/odeke-em/a6cbd219e9e07e963cd5c0092d788113

but most importantly notice

after walk foo
...
.   .   BLOCK l(11)
.   .   BLOCK-list
.   .   .   AS l(11) tc(1) hascall
.   .   .   .   DOT l(11) x(0) tc(1) assigned hascall main.F uintptr
.   .   .   .   .   DEREF l(11) tc(1) assigned hascall STRUCT-struct { F uintptr; R a }
.   .   .   .   .   .   NAME-main..autotmp_1 a(true) l(11) x(0) class(PAUTO) esc(N) tc(1) assigned used PTR-*struct { F uintptr; R a }
.   .   .   .   CFUNC a(true) l(11) tc(1) uintptr
.   .   .   .   .   NAME-main.a.do-fm a(true) l(11) x(0) class(PFUNC) tc(1) used FUNC-func()

and then also

after walk bar
...
.   .   BLOCK l(16)
.   .   BLOCK-list
.   .   .   AS l(16) tc(1) hascall
.   .   .   .   DOT l(16) x(0) tc(1) assigned hascall main.F uintptr
.   .   .   .   .   DEREF l(16) tc(1) assigned hascall STRUCT-struct { F uintptr; R a }
.   .   .   .   .   .   NAME-main..autotmp_2 a(true) l(16) x(0) class(PAUTO) esc(N) tc(1) assigned used PTR-*struct { F uintptr; R a }
.   .   .   .   CFUNC a(true) l(16) tc(1) uintptr
.   .   .   .   .   NAME-main.a.do-fm a(true) l(11) x(0) class(PFUNC) tc(1) used FUNC-func()

where only the line positions vary i.e. l(11) vs l(16) and of course the temporary struct rewrites that become variables and have names autotmp_1 and autotmp_2

So therefore when ssa.go is now evaluating expressions and getting addresses for these values

case OCFUNC:
aux := n.Left.Sym.Linksym()
return s.entryNewValue1A(ssa.OpAddr, n.Type, aux, s.sb)

Linksym for the first case will be invoked with name "".a.do-fm and then any subsequent refetch of a similarly declared variable/assignment will also use "".a.do-fm which will always return the previously cached value and so forth throughout the whole program.

Proposed fix

Perhaps also include a helper or add the complementary to methodSymSuffix called methodSymPrefix which will instead take a prefix (the caller function name) and if the prefix is non blank will ensure that the name of the symbol is <PACKAGE_NAME>.<PREFIX e.g. the calling function name>.<METHOD_NAME> so will generate:

  • "".foo.a.do
  • "".bar.a.do

which will always disambiguate between any clashing names or generate Linkname once perhaps using the same strategy to ensure that they never clash since function names are guaranteed to be unique lest we'd have a parse error.

I could kindly use some extra eyes and perhaps a partnered CL, if you please @griesemer @ianlancetaylor @randall77, or feel free to take it away since y'all more familiar with this section of code but it touches upon different parts of the compiler and linker. Thank you.

@randall77
Copy link
Contributor

I don't think we should generate multiple symbols = more code. We should just pick the right line to use for this generated code. Probably the line of the start of the declared function (line 7 in the OP's code) would work.

@ianlancetaylor : When you say gcc gets it right, what's right here? Which line?

Possibly the right answer is to declare that the -fm functions are wrappers and thus should not be shown in the traceback at all.

@ianlancetaylor
Copy link
Contributor

gccgo prints

0x7f94f7cacf30
--- FAIL: TestBar (0.00s)
panic: here [recovered]
	panic: here

goroutine 6 [running]:
panic
	../../../gccgo3/libgo/go/runtime/panic.go:588
testing.tRunner..func1
	../../../gccgo3/libgo/go/testing/testing.go:765
panic
	../../../gccgo3/libgo/go/runtime/panic.go:535
command..z2dline..z2darguments.A.Foo
	/home/iant/foo_test.go:8
command..z2dline..z2darguments.TestBar
	/home/iant/foo_test.go:19
testing.tRunner
	../../../gccgo3/libgo/go/testing/testing.go:827
created by testing.T.Run
	../../../gccgo3/libgo/go/testing/testing.go:878 +1156
FAIL	command-line-arguments	0.144s

Looking at this again, the difference is that the gc toolchain is interposing an additional stack frame:

command-line-arguments.(*A).Foo-fm()
	/home/iant/foo_test.go:13 +0x39

I guess that is the generated wrapper for the method value, but the line number for that is clearly meaningless.

gccgo does produce an internal call frame that it doesn't print in the traceback. The line number for that internal call frame is line 7, the declaration of (*A).Foo. That is imperfect but clearly better than line 13.

@randall77
Copy link
Contributor

I guess there are two fixes here then.

  1. Modify makepartialcall to use the line number of the method we're making a function out of, instead of just the random line where we happened to first trigger the generation of the wrapper.
  2. Modify the traceback to skip the -fm functions as wrappers.

The latter I can fix as part of fixing #28640.
Then the former might not matter. Low-priority, we should fix it though (e.g. it will still show up with GOTRACEBACK=2).

@gopherbot
Copy link

Change https://golang.org/cl/153477 mentions this issue: runtime: proper panic tracebacks with mid-stack inlining

@gopherbot
Copy link

Change https://golang.org/cl/153498 mentions this issue: cmd/compile: set correct line number for method wrappers

@odeke-em
Copy link
Member

Cool, thank you @randall77 for the fixes!

gopherbot pushed a commit that referenced this issue Jan 4, 2019
As a followon to CL 152537, modify the panic-printing traceback
to also handle mid-stack inlining correctly.

Also declare -fm functions (aka method functions) as wrappers, so that
they get elided during traceback. This fixes part 2 of #26839.

Fixes #28640
Fixes #24488
Update #26839

Change-Id: I1c535a9b87a9a1ea699621be1e6526877b696c21
Reviewed-on: https://go-review.googlesource.com/c/153477
Reviewed-by: David Chase <drchase@google.com>
SimonRichardson added a commit to SimonRichardson/loggo that referenced this issue May 29, 2019
Depending on the runtime version, we'll use a different callstack
depth size. This change is required because golang fixed a bug[1]
that reported the wrong function location in the stacktrace.

Fixing this requires changing the depth of Logf depending on the
runtime employed.

1. golang/go#26839
@golang golang locked and limited conversation to collaborators Dec 18, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

5 participants