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 · 8 comments

Comments

Projects
None yet
5 participants
@daskol

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 this to the Go1.12 milestone Aug 7, 2018

@ianlancetaylor ianlancetaylor changed the title from Wrong function location in stacktrace to cmd/compile: wrong function location in stacktrace Aug 7, 2018

@ianlancetaylor

This comment has been minimized.

Contributor

ianlancetaylor commented Aug 7, 2018

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

CC @griesemer

@odeke-em

This comment has been minimized.

Member

odeke-em commented Oct 18, 2018

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

This comment has been minimized.

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

This comment has been minimized.

Contributor

randall77 commented Dec 10, 2018

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

This comment has been minimized.

Contributor

ianlancetaylor commented Dec 10, 2018

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

This comment has been minimized.

Contributor

randall77 commented Dec 10, 2018

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

This comment has been minimized.

gopherbot commented Dec 10, 2018

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

@gopherbot

This comment has been minimized.

gopherbot commented Dec 10, 2018

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

@gopherbot gopherbot closed this in f64385b Dec 10, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment