proposal: runtime: support tracking goroutine ancestor tracebacks

[edaniels]

Currently, collecting a stack trace via runtime.Stack captures the stack for the
immediately running goroutines. I'd like to propose a change that extends those tracebacks to include the tracebacks of their ancestors. The goal of this would be to use as little memory as possible while accounting for the cost with a GODEBUG option of tracebackancestors set to 1.

Description of the option

tracebackancestors: setting tracebackancestors=1 adds traceback information for goroutines
and their ancestor's tracebacks. This extends the information returned by runtime.Stack.
Ancestor's goroutine ids will refer to the id of the goroutine at the time of creation;
there may exist a new goroutine with the same id.

Approach

As this option is enabled at startup the of the runtime, any new g that is created via newproc will reference the callergp in order to derive a trace and attach it to the new g. It will also copy the callergp's traces as well. This has a non-negligible cost to store as goroutines grow to a large number depending on the source of the goroutines.

Example

The following file demonstrates the output of the proposed change with multiple goroutine invocations:

package main

import (
	"fmt"
	"runtime"
)

func printstackall() {
	buf := make([]byte, 1024)
	for {
		n := runtime.Stack(buf, true)
		if n < len(buf) {
			fmt.Print(string(buf[:n]))
			return
		}
		buf = make([]byte, 2*len(buf))
	}
}

func main() {
	fmt.Println("Trace from main, 0 depth")
	printstackall()

	fmt.Println("\nTrace from multiple goroutines")
	timesToCallGo := 5
	w := make(chan struct{})
	go foo(w, timesToCallGo)
	<-w
	printstackall()
	close(w)
}

const maxStackDepth = 5

func foo(w chan struct{}, timesToCallGo int) {
	if timesToCallGo == 0 {
		w <- struct{}{}
		<-w
		return
	}
	if timesToCallGo%2 == 0 {
		d1(func() { foo(w, timesToCallGo-1) }, maxStackDepth)
	} else {
		d1(func() { bar(w, timesToCallGo-1) }, maxStackDepth)
	}
}

func bar(w chan struct{}, timesToCallGo int) {
	if timesToCallGo == 0 {
		w <- struct{}{}
		<-w
		return
	}
	if timesToCallGo%2 == 0 {
		d1(func() { foo(w, timesToCallGo-1) }, maxStackDepth)
	} else {
		d1(func() { bar(w, timesToCallGo-1) }, maxStackDepth)
	}
}

func d1(fn func(), timesToRecurse int) {
	if timesToRecurse == 0 {
		go fn()
		return
	}
	d1(fn, timesToRecurse-1)
}

Running it with the flag on produces:

Trace from main, 0 depth
goroutine 1 [running]:
main.printstackall()
	/Users/eric/Downloads/test.go:11 +0xa7
main.main()
	/Users/eric/Downloads/test.go:22 +0x66

Trace from multiple goroutines
goroutine 1 [running]:
main.printstackall()
	/Users/eric/Downloads/test.go:11 +0xa7
main.main()
	/Users/eric/Downloads/test.go:29 +0x106

goroutine 10 [chan receive]:
main.bar(0xc420078060, 0x0)
	/Users/eric/Downloads/test.go:51 +0x166
main.foo.func2()
	/Users/eric/Downloads/test.go:44 +0x37
created by main.d1
	/Users/eric/Downloads/test.go:63 +0x3d
[originating from goroutine 9]:
main.d1(0xc42000a160, 0x0)
	/Users/eric/Downloads/test.go:63 +0x3d
main.d1(0xc42000a160, 0x1)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a160, 0x2)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a160, 0x3)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a160, 0x4)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a160, 0x5)
	/Users/eric/Downloads/test.go:66 +0x5d
main.foo(0xc420078060, 0x1)
	/Users/eric/Downloads/test.go:44 +0x116
main.bar.func1()
	/Users/eric/Downloads/test.go:55 +0x37
created by main.d1
	/Users/eric/Downloads/test.go:63 +0x3d
[originating from goroutine 8]:
main.d1(0xc42000a140, 0x0)
	/Users/eric/Downloads/test.go:63 +0x3d
main.d1(0xc42000a140, 0x1)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a140, 0x2)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a140, 0x3)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a140, 0x4)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a140, 0x5)
	/Users/eric/Downloads/test.go:66 +0x5d
main.bar(0xc420078060, 0x2)
	/Users/eric/Downloads/test.go:55 +0x9c
main.foo.func2()
	/Users/eric/Downloads/test.go:44 +0x37
created by main.d1
	/Users/eric/Downloads/test.go:63 +0x3d
[originating from goroutine 7]:
main.d1(0xc42000a120, 0x0)
	/Users/eric/Downloads/test.go:63 +0x3d
main.d1(0xc42000a120, 0x1)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a120, 0x2)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a120, 0x3)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a120, 0x4)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a120, 0x5)
	/Users/eric/Downloads/test.go:66 +0x5d
main.foo(0xc420078060, 0x3)
	/Users/eric/Downloads/test.go:44 +0x116
main.bar.func1()
	/Users/eric/Downloads/test.go:55 +0x37
created by main.d1
	/Users/eric/Downloads/test.go:63 +0x3d
[originating from goroutine 6]:
main.d1(0xc42000a100, 0x0)
	/Users/eric/Downloads/test.go:63 +0x3d
main.d1(0xc42000a100, 0x1)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a100, 0x2)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a100, 0x3)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a100, 0x4)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a100, 0x5)
	/Users/eric/Downloads/test.go:66 +0x5d
main.bar(0xc420078060, 0x4)
	/Users/eric/Downloads/test.go:55 +0x9c
main.foo.func2()
	/Users/eric/Downloads/test.go:44 +0x37
created by main.d1
	/Users/eric/Downloads/test.go:63 +0x3d
[originating from goroutine 5]:
main.d1(0xc42000a0e0, 0x0)
	/Users/eric/Downloads/test.go:63 +0x3d
main.d1(0xc42000a0e0, 0x1)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a0e0, 0x2)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a0e0, 0x3)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a0e0, 0x4)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(0xc42000a0e0, 0x5)
	/Users/eric/Downloads/test.go:66 +0x5d
main.foo(0xc420078060, 0x5)
	/Users/eric/Downloads/test.go:44 +0x116
created by main.main
	/Users/eric/Downloads/test.go:27 +0xea
[originating from goroutine 1]:
main.main()
	/Users/eric/Downloads/test.go:27 +0xea

Assumptions

There is no problem allocating memory on the heap from within a systemstack call with respect to garbage collection (I haven't looked far enough to prove that we're still in a typical goroutine while doing newproc1.

[gopherbot]

Change https://golang.org/cl/70993 mentions this issue: runtime/traceback: support tracking goroutine ancestor tracebacks with GODEBUG="tracebackancestors=1"

[edaniels]

@ianlancetaylor I totally goofed on https://go-review.googlesource.com/#/c/70992/. Abandoned that change and followed up here.

[ianlancetaylor]

CC @aclements

[edaniels]

Any updates on this?

[ianlancetaylor]

It does seem like the storage costs could get rather high. And it also seems like the output could get quite confusing for a large program. But on the other hand, it's optional.

You have a clear proposal and a change, but it might help to have a clearer use case. What is the kind of problem that would be more easily solved with this additional information?

[edaniels]

So the use case is derived from an issue we hit in production with using a library like https://github.com/10gen/mgo. The readers and writers of MongoDB operation cursor are goroutines that are created from other goroutines. The issue we hit was that we were connecting to MongoDB on behalf of customers in one part of code as well as connecting to our own MongoDB for our backing database. It turned out a leak was present in our customer code. Nailing this down took a while but this new option would allow us to immediately identify the customer code that "spawned" that goroutine.

Another example which is totally not real is the usage of http.DefaultClient from a library that doesn't let you pass a http.Client in and another http.Client in your own code and figuring out which part of your code is not closing http.Responses.

Finally, complete visibility of a server that isn't behaving well via this option is beneficial in a situation where you have no clue what could be wrong. JVM thread dumps have been very beneficial for me for this reason in the past.

[edaniels]

@ianlancetaylor How is that for a use case? Hoping to get this in during the 1.11 cycle :)

[aclements]

Nailing this down took a while but this new option would allow us to immediately identify the customer code that "spawned" that goroutine.

Out of curiosity, how much would it help to simply know the ID of the goroutine that spawned the goroutine? If the spawning goroutine hasn't exited, that would let you find it in the stack trace and at least see what it's currently doing. That's something we could easily do all the time.

Finally, complete visibility of a server that isn't behaving well via this option is beneficial in a situation where you have no clue what could be wrong. JVM thread dumps have been very beneficial for me for this reason in the past.

Could you elaborate on this? I didn't think JVM thread dumps included the stack trace of spawning threads.

[edaniels]

For the first question: It would only help marginally since in this use case, the concern is not with what the goroutine is doing now, but with what it was doing at the time of the child goroutine being spawned.

For the second question: Correct, the JVM thread dumps do not do this. I was just saying how having more information can make debugging unknown issues easier in some scenarios like the one I outlined above. From Go I have seen and written, it seems more common to liberally spawn goroutines from other goroutines than it does in a JVM based language like Java. I'd imagine a similar type of pattern being useful for event loops as well where you would see where each event originated from and so on. The absence of this can make callback oriented code very hard to debug in certain cases when the originating code is the source of the issue.

[aclements]

Thanks. A few more questions:

I see in your prototype that you capture the entire textual stack trace, including arguments. Would it be okay to just capture the PCs and not the arguments? This would be significantly less data, since we could delay symbolizing those until printing the traceback.

How far up the "goroutine stack" do you need to go? There are obviously potential asymptotic problems with capturing all the way up to main. What if, for example, the number passed to GODEBUG=tracebackancestors=x was the number of parent goroutines to track? This would bound the more troubling dimension of the space requirements, while still giving you a fair amount of debugging power.

[edaniels]

Yeah, only PCs are just fine. There's honestly probably not too much value in having the arguments there as those are much more likely to refer to garbage data.

Having the ability to pass a depth limit seems like a good idea. Are you open in accepting a value like -1 to make it unbounded or would you prefer the user to just pass a high value in that case?

[aclements]

I think I'd rather the user just pass a high value. For example, even if the user passes, say, 100, that's practically infinite for debugging purposes, but it still bounds the damage that can be done by a huge chain of goroutines.

Would you mind updating your proposed CL to do just the PCs and add the bound? It looked like it was already in reasonably good shape.

[edaniels]

Yeah makes sense. Sure. Will add the bound as well as the deferred symbolization of pcs. Will result in a little more net added code since i was relying on the simple backtraces. I'm going to work on this today since I'm going to mostly be out this Wednesday-Friday (PAX East!).

[aclements]

Thanks! I suspect you're right that it will be slightly more code, but I don't think by much. Printing will take a little more effort, since I don't think we have a way to print traceback from a PC slice right now.

[edaniels]

@aclements put up a new patchset just in time before travel! Not much more code was added.
Capturing information at goroutine spawn time has been simplified but the printing has been complicated. printAncestorTraceback follows the form of traceback and printAncestorTracebackFuncInfo steals (duplicates) some code from gentraceback that was hard to refactor meaningfully. Updated descriptions and comments as well.

New backtraces look like this for the same sample code above:

Trace from main, 0 depth
goroutine 1 [running]:
main.printstackall()
	/Users/eric/Downloads/test.go:11 +0xa7
main.main()
	/Users/eric/Downloads/test.go:22 +0x66

Trace from multiple goroutines
goroutine 1 [running]:
main.printstackall()
	/Users/eric/Downloads/test.go:11 +0xa7
main.main()
	/Users/eric/Downloads/test.go:29 +0x106

goroutine 23 [chan receive]:
main.bar(0xc0000880c0, 0x0)
	/Users/eric/Downloads/test.go:51 +0x14a
main.foo.func2()
	/Users/eric/Downloads/test.go:44 +0x37
created by main.d1
	/Users/eric/Downloads/test.go:63 +0x3d
[originating from goroutine 22]:
main.d1(...)
	/Users/eric/Downloads/test.go:63 +0x3d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.foo(...)
	/Users/eric/Downloads/test.go:44 +0x103
main.bar.func1(...)
	/Users/eric/Downloads/test.go:55 +0x37
created by main.d1
	/Users/eric/Downloads/test.go:63 +0x3d
[originating from goroutine 21]:
main.d1(...)
	/Users/eric/Downloads/test.go:63 +0x3d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.bar(...)
	/Users/eric/Downloads/test.go:55 +0x97
main.foo.func2(...)
	/Users/eric/Downloads/test.go:44 +0x37
created by main.d1
	/Users/eric/Downloads/test.go:63 +0x3d
[originating from goroutine 20]:
main.d1(...)
	/Users/eric/Downloads/test.go:63 +0x3d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.foo(...)
	/Users/eric/Downloads/test.go:44 +0x103
main.bar.func1(...)
	/Users/eric/Downloads/test.go:55 +0x37
created by main.d1
	/Users/eric/Downloads/test.go:63 +0x3d
[originating from goroutine 19]:
main.d1(...)
	/Users/eric/Downloads/test.go:63 +0x3d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.bar(...)
	/Users/eric/Downloads/test.go:55 +0x97
main.foo.func2(...)
	/Users/eric/Downloads/test.go:44 +0x37
created by main.d1
	/Users/eric/Downloads/test.go:63 +0x3d
[originating from goroutine 18]:
main.d1(...)
	/Users/eric/Downloads/test.go:63 +0x3d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.d1(...)
	/Users/eric/Downloads/test.go:66 +0x5d
main.foo(...)
	/Users/eric/Downloads/test.go:44 +0x103
created by main.main
	/Users/eric/Downloads/test.go:27 +0xea
[originating from goroutine 1]:
main.main(...)
	/Users/eric/Downloads/test.go:27 +0xea

Diff between previous and new method:

15,17c15,17
< goroutine 10 [chan receive]:
< main.bar(0xc420078060, 0x0)
< 	/Users/eric/Downloads/test.go:51 +0x166
---
> goroutine 23 [chan receive]:
> main.bar(0xc0000880c0, 0x0)
> 	/Users/eric/Downloads/test.go:51 +0x14a
22,23c22,23
< [originating from goroutine 9]:
< main.d1(0xc42000a160, 0x0)
---
> [originating from goroutine 22]:
> main.d1(...)
25c25
< main.d1(0xc42000a160, 0x1)
---
> main.d1(...)
27c27
< main.d1(0xc42000a160, 0x2)
---
> main.d1(...)
29c29
< main.d1(0xc42000a160, 0x3)
---
> main.d1(...)
31c31
< main.d1(0xc42000a160, 0x4)
---
> main.d1(...)
33c33
< main.d1(0xc42000a160, 0x5)
---
> main.d1(...)
35,37c35,37
< main.foo(0xc420078060, 0x1)
< 	/Users/eric/Downloads/test.go:44 +0x116
< main.bar.func1()
---
> main.foo(...)
> 	/Users/eric/Downloads/test.go:44 +0x103
> main.bar.func1(...)
41,42c41,42
< [originating from goroutine 8]:
< main.d1(0xc42000a140, 0x0)
---
> [originating from goroutine 21]:
> main.d1(...)
44c44
< main.d1(0xc42000a140, 0x1)
---
> main.d1(...)
46c46
< main.d1(0xc42000a140, 0x2)
---
> main.d1(...)
48c48
< main.d1(0xc42000a140, 0x3)
---
> main.d1(...)
50c50
< main.d1(0xc42000a140, 0x4)
---
> main.d1(...)
52c52
< main.d1(0xc42000a140, 0x5)
---
> main.d1(...)
54,56c54,56
< main.bar(0xc420078060, 0x2)
< 	/Users/eric/Downloads/test.go:55 +0x9c
< main.foo.func2()
---
> main.bar(...)
> 	/Users/eric/Downloads/test.go:55 +0x97
> main.foo.func2(...)
60,61c60,61
< [originating from goroutine 7]:
< main.d1(0xc42000a120, 0x0)
---
> [originating from goroutine 20]:
> main.d1(...)
63c63
< main.d1(0xc42000a120, 0x1)
---
> main.d1(...)
65c65
< main.d1(0xc42000a120, 0x2)
---
> main.d1(...)
67c67
< main.d1(0xc42000a120, 0x3)
---
> main.d1(...)
69c69
< main.d1(0xc42000a120, 0x4)
---
> main.d1(...)
71c71
< main.d1(0xc42000a120, 0x5)
---
> main.d1(...)
73,75c73,75
< main.foo(0xc420078060, 0x3)
< 	/Users/eric/Downloads/test.go:44 +0x116
< main.bar.func1()
---
> main.foo(...)
> 	/Users/eric/Downloads/test.go:44 +0x103
> main.bar.func1(...)
79,80c79,80
< [originating from goroutine 6]:
< main.d1(0xc42000a100, 0x0)
---
> [originating from goroutine 19]:
> main.d1(...)
82c82
< main.d1(0xc42000a100, 0x1)
---
> main.d1(...)
84c84
< main.d1(0xc42000a100, 0x2)
---
> main.d1(...)
86c86
< main.d1(0xc42000a100, 0x3)
---
> main.d1(...)
88c88
< main.d1(0xc42000a100, 0x4)
---
> main.d1(...)
90c90
< main.d1(0xc42000a100, 0x5)
---
> main.d1(...)
92,94c92,94
< main.bar(0xc420078060, 0x4)
< 	/Users/eric/Downloads/test.go:55 +0x9c
< main.foo.func2()
---
> main.bar(...)
> 	/Users/eric/Downloads/test.go:55 +0x97
> main.foo.func2(...)
98,99c98,99
< [originating from goroutine 5]:
< main.d1(0xc42000a0e0, 0x0)
---
> [originating from goroutine 18]:
> main.d1(...)
101c101
< main.d1(0xc42000a0e0, 0x1)
---
> main.d1(...)
103c103
< main.d1(0xc42000a0e0, 0x2)
---
> main.d1(...)
105c105
< main.d1(0xc42000a0e0, 0x3)
---
> main.d1(...)
107c107
< main.d1(0xc42000a0e0, 0x4)
---
> main.d1(...)
109c109
< main.d1(0xc42000a0e0, 0x5)
---
> main.d1(...)
111,112c111,112
< main.foo(0xc420078060, 0x5)
< 	/Users/eric/Downloads/test.go:44 +0x116
---
> main.foo(...)
> 	/Users/eric/Downloads/test.go:44 +0x103
116c116
< main.main()
---
> main.main(...)

[rsc]

Per comments from @aclements after discussion with Go runtime/compiler team, this is accepted with a bound on the pain it can cause (as in discussion above).

[edaniels]

@rsc great! Let me know if more modifications need to be made to the CL or if the team will just implement on its own.