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

debug/gosym: (*Table).PCToLine reports wrong file/line for call site PCs #45900

Closed
eandre opened this issue May 1, 2021 · 7 comments
Closed
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Milestone

Comments

@eandre
Copy link

eandre commented May 1, 2021

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

$ go version
go version go1.16.3 darwin/arm64

Does this issue reproduce with the latest release?

Yes

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

go env Output
$ go env
GO111MODULE="on"
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/eandre/Library/Caches/go-build"
GOENV="/Users/eandre/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/eandre/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/eandre"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/opt/homebrew/Cellar/go/1.16.3/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/opt/homebrew/Cellar/go/1.16.3/libexec/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="go1.16.3"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/opt/homebrew/Cellar/encore/0.13.2/libexec/runtime/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/hc/w9bwjfwd69dd6_6thw6xqmkw0000gn/T/go-build515741722=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I used debug/gosym.(*Table).PCToLine to get the file and line number corresponding to a PC returned from runtime.Callers.

What did you expect to see?

I expected PCToLine to report the same information as runtime.CallersFrames. However, for some PCs they differed.

From runtime.CallersFrames (this is the correct output):

PC=3988140: /Users/eandre/tmp/demo/board/board.go:99: encore.app/board.Get
PC=3952120: /Users/eandre/src/encr.dev/compiler/runtime/storage/sqldb/sqldb.go:320: encore.dev/storage/sqldb.(*Row).Scan
PC=3988264: /Users/eandre/tmp/demo/board/board.go:103: encore.app/board.Get
PC=3988456: /Users/eandre/tmp/demo/board/board.go:105: encore.app/board.Get
PC=3988504: /Users/eandre/tmp/demo/board/board.go:106: encore.app/board.Get

(PC here refers to the address offset from the start of the text segment)

What did you see instead?

From debug/gosym.(*Table).PCToLine:

PC=3988140: /Users/eandre/tmp/demo/board/board.go:99 (encore.app/board.Get)
PC=3952120: /Users/eandre/src/encr.dev/compiler/runtime/storage/sqldb/sqldb.go:320 (encore.dev/storage/sqldb.(*Row).Scan)
PC=3988264: /Users/eandre/tmp/demo/board/board.go:104 (encore.app/board.Get)
PC=3988456: /Users/eandre/src/encr.dev/compiler/runtime/beta/errs/builder.go:23 (encore.app/board.Get)
PC=3988504: /Users/eandre/tmp/demo/board/board.go:106 (encore.app/board.Get)

I compared the implementation of parsing the symbol table in the debug/gosym and runtime packages.

It appears debug/gosym is missing this if statement: https://github.com/golang/go/blob/master/src/runtime/symtab.go#L95-L101

If I add a corresponding if statement to debug/gosym, the issue is resolved on my end, but would be good to verify this fix with somebody who is more familiar with the code.

@cherrymui
Copy link
Member

cherrymui commented May 3, 2021

The PCs you got from runtime runtime.Callers are the function return addresses, which is the instruction immediately after the CALL instruction. The runtime function subtracts the PC by one so it will get the PC of the CALL instruction, which is usually what people want.

The debug/gosym package uses the actual PC instead. It should not do the -1 because it should not assume the input PC is a return PC, nor you're trying to get back to the CALL instruction. If you want that semantic, you'd want to do the -1 yourself. Thanks.

@eandre
Copy link
Author

eandre commented May 3, 2021

That's a bit surprising because the *Func reported corresponds to the correct function, but the file and line do not. Is that ever the expected result for any PC? I'm happy to do the subtraction myself in that case, but the API is a bit awkward since there's no way to avoid the *Func lookup twice (once to determine whether to subtract -1, and then once more within (*Table).PCToLine).

@cherrymui
Copy link
Member

The function is correct because it is the same function.

The runtime function and the debug/gosym package serve different purpose. The runtime function is specific to traceback. The debug/gosym package is not. You can look up for arbitrary PCs. Only for the traceback case the -1 is the right thing to do. If you know you are getting the PCs from a backtrace, you probably can always do the -1 (the runtime function has a condition to handle signals, like if you're taking a traceback from a signal handler triggered by a panic. If you know that's not your case you probably can skip the check). Otherwise never.

@eandre
Copy link
Author

eandre commented May 3, 2021

I'm not sure what you mean by "it is the same function". The file and line information refer to a completely different file, so those don't seem consistent with the *Func in any plausible interpretation. Either way, if you believe this is correct I have no problem doing the subtraction myself.

Based on the documentationruntime.FuncForPC also suggests it supports looking up arbitrary PCs; is that different from the use case for debug/gosym?

@cherrymui
Copy link
Member

With inlining, the file and line number can change, but it is still in the same (machine code) function.

Yes, runtime.FuncForPC can be used to look up arbitrary PCs. But I'm not sure I understand your question.

@cagedmantis cagedmantis added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label May 4, 2021
@cagedmantis cagedmantis added this to the Backlog milestone May 4, 2021
@gopherbot
Copy link

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

@eandre
Copy link
Author

eandre commented Aug 27, 2021

Thanks @cherrymui. I'm still not sure I understand what you mean. Let me give you an example.

In my code I'm calling database/sql/.(*DB).QueryRowContext, which is defined in sql.go#L1777.

I then capture a stack trace (from within this function call, using a custom database driver). If I inspect the stack trace within the Go runtime (using runtime.FuncForPC), I see, as I would expect, a stack frame with:

file: "/path/to/goroot/src/database/sql/sql.go"
func: "database/sql.(*DB).QueryRowContext"
line: 1778

However, when I take the corresponding PC, load the symbol table from the binary, and look it up with debug/gosym.(*Table).PCToLine, I instead get:

file: "/path/to/goroot/src/database/sql/sql.go"
func: "my.module/pkg/path.Foo"
line: 1778

That is, the file and line information is correct, but the func is wrong. The func comes from the parent stack frame, that called database/sql.(*DB).QueryRowContext. This happens regardless of whether or not I subtract 1 from the PC.

What is it about the runtime that allows it to correctly map the PC to the correct function, while debug/gosym cannot? They both get the file and line number correct.

I noticed in FuncForPC (symtab.go#L630) that the runtime looks up inlining information, while I cannot see corresponding code in debug/gosym. Is that the cause? Is this information available in the symbol table but not used by debug/gosym?

@golang golang locked and limited conversation to collaborators Aug 27, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

4 participants