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

runtime: bad stack trace when using mid-stack inlining #29007

Open
randall77 opened this Issue Nov 29, 2018 · 16 comments

Comments

Projects
None yet
5 participants
@randall77
Contributor

randall77 commented Nov 29, 2018

package main

import "runtime"

func main() {
	println(f())
}

func f() string {
	return g()
}
func g() string {
	var pcs [1]uintptr
	n := runtime.Callers(3, pcs[:])
	frames := runtime.CallersFrames(pcs[:n])
	frame, _ := frames.Next()
	return frame.Function
}

This program should print main.main. It does on Go 1.11, but not tip. On tip it prints main.f.

Weirdly, if you declare pcs to be [2]uintptr, then it works.
It also works correctly with other skip parameters (1, 2 and 4 all work).

This bug is somehow related to the mid-stack inlining of f.

@davidlazar @aclements

@randall77 randall77 added this to the Go1.12 milestone Nov 29, 2018

@randall77 randall77 self-assigned this Nov 29, 2018

@randall77

This comment has been minimized.

Contributor

randall77 commented Nov 29, 2018

This comment in traceback.go seems relevant:

// if there's room, pcbuf[1] is a skip PC that encodes the number of skipped frames in pcbuf[0]
if n+1 < max {
	n++
	pc := skipPC + uintptr(logicalSkipped)
	(*[1 << 20]uintptr)(unsafe.Pointer(pcbuf))[n] = pc
}

Maybe there's another way to encode the required skips?

@aclements

This comment has been minimized.

Member

aclements commented Nov 29, 2018

Maybe there's another way to encode the required skips?

The API has us rather backed into a corner here. Given that we only have 1 uintptr's worth of space to store information, it's not clear to me how we can store both the PC and the inlining level.

@andybons

This comment has been minimized.

Member

andybons commented Nov 29, 2018

Should this block the beta scheduled for next week?

@ianlancetaylor

This comment has been minimized.

Contributor

ianlancetaylor commented Nov 29, 2018

This could potentially mess up programs that use the log package, if the log package causes mid-stack inlining to occur. And it could potentially mess up other people's log packages as well. I think this probably does block the beta, unless we just give up on it.

@randall77

This comment has been minimized.

Contributor

randall77 commented Nov 29, 2018

A possibility is to find and/or put an instruction that can be used to indicate the outer scope. So for instance:

1: func f() {
2:      g()
3: }
4: func g() {
5:    x++
6: }

We have assembly like (when g is inlined):

TEXT f
    INCQ x(SB)  // marked as line 5, inlining info says "g inside f"

We could instead generate:

TEXT f
    NOP   // marked as line 2, just f
    INCQ x(SB)  // marked as line 5, g inside f

When we need to encode something that is just f, provide the address of that NOP.
Likely, there will be at least one such instruction anyway (the last one in f before the body of g starts) and the NOP is unnecessary.

@randall77

This comment has been minimized.

Contributor

randall77 commented Nov 29, 2018

Then we'd need some info in runtime.inlinedCall to say "in this pc range, an instruction in the immediately containing call is this pc".

@ianlancetaylor

This comment has been minimized.

Contributor

ianlancetaylor commented Nov 29, 2018

If we need a side table anyhow, then we don't necessarily have to use an actual instruction in the function. We could use an address in the inlinedCall structure. That would let us encode 32 skip values.

@aclements

This comment has been minimized.

Member

aclements commented Nov 29, 2018

We could use an address in the inlinedCall structure.

At the time we were designing the current solution, we wanted to give real PCs in case someone was using them as such (e.g., to look something up using nm, to set a debug breakpoint, etc.)

@ianlancetaylor

This comment has been minimized.

Contributor

ianlancetaylor commented Nov 30, 2018

The PC value returned by runtime.Callers is that of the instruction following the call instruction. If we want to preserve the ability to set a debug breakpoint, then I think we really do need to insert a nop instruction after the call. The PC immediately after the call would presumably indicate no skip. Adding one to that value would indicate one skipped frame. Adding two would indicate two skipped frames, etc. There would need to be as many nop instructions as there are potentially skipped frames, which is the number of mid-stack inlined calls. The PCDATA would have to record the number of skipped frames associated with the specific PC.

That sounds workable but fairly complicated, and it adds a cost to all mid-stack inlining. And of course it only matters for the very last entry in the PCs returned by runtime.Callers, when there is a non-zero skip argument.

We should at least consider simply documenting that programs that want to pick out a specific entry should increment the size of the array they pass to runtime.Callers. As far as I can tell nothing in the standard library would have to change, which is of course consistent with the fact that all tests are passing.

@randall77

This comment has been minimized.

Contributor

randall77 commented Nov 30, 2018

If we want to preserve the ability to set a debug breakpoint,

What does this mean, exactly? Are people printing the contents of runtime.Callers and using the result in a break statement in a debugger?

Or are you referencing something programmatic?

@ianlancetaylor

This comment has been minimized.

Contributor

ianlancetaylor commented Dec 1, 2018

I was just quoting Austin.

I don't really know what the restrictions are on the values we store in runtime.Callers. It does seem clear that they should work with the nm program and with runtime.FuncForPC. I don't know how accurate we really need to be with runtime.FuncForPC(nn).FileLine(nn).

@randall77

This comment has been minimized.

Contributor

randall77 commented Dec 1, 2018

I was thinking of something different, which is to do the inlining expansion in runtime.Callers, not in runtime.CallersFrames. That way we don't need to get a skip count from runtime.Callers to runtime.CallersFrames. runtime.Callers can do all the skipping.

Consider the code:

func a() {
    b()
}
func b() {
    c()
}
func c() {
    d()
}
func d()

Where both b and c are inlined into a, and d calls runtime.Callers.

Currently a,b, and c generate only one entry in the result, and CallersFrames uses that entry 3 times to produce three frames of output.

Instead I want to put an entry in the result of runtime.Callers for each of a, b, and c.
The first (highest on the stack) entry would be the PC of some part of a just before (or after?) the parts of b that are inlined into a. Similarly, the next highest entry would be the PC of some part of b just before the parts of c inlined into a. The last entry would be the standard one, the PC just after the call to d.

All three pcs would be in a if someone used runtime.FuncForPC on them. They would all be reasonable breakpoints if you wanted to stop at the call from b to c, say.

@randall77

This comment has been minimized.

Contributor

randall77 commented Dec 3, 2018

Related: #28640 (fixing wrapper elision when mid-stack inlining).

@ianlancetaylor

This comment has been minimized.

Contributor

ianlancetaylor commented Dec 3, 2018

@randall77 I see, that makes sense. That is basically what gccgo does.

@gopherbot

This comment has been minimized.

gopherbot commented Dec 5, 2018

Change https://golang.org/cl/152537 mentions this issue: cmd/compile,runtime: redo mid-stack inlining tracebacks

@gopherbot

This comment has been minimized.

gopherbot commented Dec 7, 2018

Change https://golang.org/cl/153241 mentions this issue: cmd/compile: use innermost line number for -S

gopherbot pushed a commit that referenced this issue Dec 11, 2018

cmd/compile: use innermost line number for -S
When functions are inlined, for instructions in the inlined body, does
-S print the location of the call, or the location of the body? Right
now, we do the former. I'd like to do the latter by default, it makes
much more sense when reading disassembly. With mid-stack inlining
enabled in more cases, this quandry will come up more often.

The original behavior is still available with -S=2. Some tests
use this mode (so they can find assembly generated by a particular
source line).

This helped me with understanding what the compiler was doing
while fixing #29007.

Change-Id: Id14a3a41e1b18901e7c5e460aa4caf6d940ed064
Reviewed-on: https://go-review.googlesource.com/c/153241
Reviewed-by: David Chase <drchase@google.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment