proposal: runtime: permit setting goroutine name to appear in stack dumps

[Cyberax]

I've created this issue according to https://github.com/golang/proposal .

This is an issue to discuss a proposal to add goroutine names for debugging purposes only. The name will appear only in stack dumps. I do not propose any new mechanism that would allow creation of a thread-local storage.

In essence, I propose adding several new functions to the runtime package:

1. SetGoroutineName(name string) - set the current goroutine name to the specified value. The name can be up to runtime.MaxGoroutineNameLen (exact value TBD, I expect it to be around 40).
2. SetEnableGoroutineName(bool) - enable goroutine name output in backtraces. By default goroutines are not enabled.
3. IsGoroutineNameEnabled() bool - returns the status of name output enablement.

Sidenote: I don't like the name "name", as Go routines are anonymous. Perhaps I should rename it to "Trace ID" or something like it?

The goroutine name will be silently inherited by any goroutines spawned by the parent process.

Here's an example of use:

package main
import (
    "runtime"
    "net/http"
)
func main() {
    runtime.SetEnableGoroutineName(true)
    http.HandleFunc("/", HelloServer)
    http.ListenAndServe(":8080", nil)
}
func HelloServer(w http.ResponseWriter, r *http.Request) {
    runtime.SetGoroutineName(r.Header.Get("Request-Id"))
    panic("An error happened")
}

Run it:

cyberax@CybMac:~/aurora/go/bin$ curl -H "Request-Id: req-id-123123" http://localhost:8080/
curl: (52) Empty reply from server

With the server output:

cyberax@CybMac:~/aurora/go$ ./bin/go run test.go
2019/10/25 21:34:28 http: panic serving [::1]:61981: An error happened
goroutine 6 (req-id-123123) [running]:
net/http.(*conn).serve.func1(0xc00009cb40)
	/Users/cyberax/aurora/go/src/net/http/server.go:1772 +0x139
panic(0x127aa00, 0x133df70)
....

I have created a proof-of-concept implementation: https://github.com/Cyberax/go/commit/ee50b1e771a3afdb760f56b6d1b1603772e3b3f0 and for the Delve debugger: https://github.com/Cyberax/delve/commit/c69a60eba91723425619654dce55236376d3929d

[agnivade]

This has been discussed before (#27361) and rejected. See Russ' comment.

[robaho]

Rob will say to pass this in a context and panic/recover print the context, or print the context during debugging - no matter that the context contains lots of state.

You’re not going to win here and it’s a shame. TLS has been around a long time - it could of been replaced by context param long ago - no one felt it necessary but RP.

[Cyberax]

This has been discussed before (#27361) and rejected. See Russ' comment.

I believe that my approach is different.

1. It's common for Go programs to spawn new helper goroutines, so I've added goroutine name inheritance. All gorouitnes spawned from a named goroutine will share the name with the parent.

E.g.:

package main
import (
    "fmt"
    "runtime"
    "net/http"
)
func main() {
    runtime.SetEnableGoroutineName(true)
    http.HandleFunc("/", HelloServer)
    http.ListenAndServe(":8080", nil)
}
func HelloServer(w http.ResponseWriter, r *http.Request) {
    runtime.SetGoroutineName(r.Header.Get("Request-Id"))

    done := make(chan bool)
    ready := make(chan bool)
    go func() {
	    close(ready)
	    <- done
    }()
    <- ready
    defer close(done)

    buf := make([]byte, 1<<16)
    stackSize := runtime.Stack(buf, true)
    fmt.Printf("%s\n", string(buf[0:stackSize]))
}

Outputs:

goroutine 6 (req-id-123123) [running]:
main.HelloServer(0x1348c80, 0xc0000d60e0, 0xc0000ec000)
	/Users/cyberax/aurora/go/test.go:25 +0x1af
net/http.HandlerFunc.ServeHTTP(0x12f82e0, 0x1348c80, 0xc0000d60e0, 0xc0000ec000)
	/Users/cyberax/aurora/go/src/net/http/server.go:2012 +0x44
....
goroutine 8 (req-id-123123) [chan receive]:
main.HelloServer.func1(0xc0000221e0, 0xc000022180)
	/Users/cyberax/aurora/go/test.go:19 +0x42
created by main.HelloServer
	/Users/cyberax/aurora/go/test.go:17 +0x12b
...

2. There is NO other option here. Logging does NOT help at all with the problem of goroutine names in many cases. For example, deadlock debugging or profiling will produce only stack traces that are uncorrelated with contexts.

3. Most importantly, panics triggered by asynchronous events (e.g. a nil pointer dereference or out-of-bounds access) are also often impossible to correlate with the context that triggered them unless the recovery code happens to have the context. There is absolutely no workaround for that.

4. And most importantly for me, I'm doing some hairy multi-threaded processing that is hell to debug because I can't easily switch between goroutines in the debugger. The lack of a name makes it really hard to switch between multiple goroutines. I would actually be fine with including the name only for debugging purposes.

[Cyberax]

To further expand on point 3, here's an example of a work that migrates between goroutines:

package main
import (
    "fmt"
    "runtime"
    "time"
    "net/http"
)
func main() {
    runtime.SetEnableGoroutineName(true)
    http.HandleFunc("/", HelloServer)
    http.ListenAndServe(":8080", nil)
}
func HelloServer(w http.ResponseWriter, r *http.Request) {
    runtime.SetGoroutineName(r.Header.Get("Request-Id"))

    ready := make(chan bool)
    go func() {
	    close(ready)
	    time.Sleep(1 * time.Second)
	    var ptr *string
	    fmt.Print(*ptr)
    }()
    <- ready
}

With my proposal you get a nice error that would allow one to trace it exactly to the request that caused it (even though the request has completed by the time the error is triggered):

cyberax@CybMac:~/aurora/go$ ./bin/go run test.go
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x125343e]

goroutine 21 (req-id-123123) [running]:
main.HelloServer.func1(0xc000088120)
	/Users/cyberax/aurora/go/test.go:21 +0x3e
created by main.HelloServer
	/Users/cyberax/aurora/go/test.go:17 +0xd9
exit status 2

[gmichelo]

Most importantly, panics triggered by asynchronous events (e.g. a nil pointer dereference or out-of-bounds access) are also often impossible to correlate with the context that triggered them unless the recovery code happens to have the context. There is absolutely no workaround for that.

What is wrong with that? Deferred function can access input context.Context and easily enrich panic's message with context info.

I think that if we accepted this proposal, the next ask would be: "why don't we add also a GetGoroutineName() string API? Thanks to that user can read goroutine's name after setting it". And I would like that not to happen, as it enables wrong code pattern and design, IMHO.

[robaho]

Regardless of this, TLS plays a far bigger role in optimizing code paths without creating lots of external code changes and cruft. Very common in server side applications where different code paths call the same pattern based functions with different values. You can try doing this with context.Context but to do it right, every function no matter how small needs it - that essentially makes it a crippled TLS so why not start with a good one?

…

On Oct 27, 2019, at 5:43 AM, Giulio Micheloni ***@***.***> wrote:  Most importantly, panics triggered by asynchronous events (e.g. a nil pointer dereference or out-of-bounds access) are also often impossible to correlate with the context that triggered them unless the recovery code happens to have the context. There is absolutely no workaround for that. What is wrong with that? Deferred function can access input context.Context and easily enrich panic's message with context info. I think that if we accept this proposal, the next ask would be: "why don't we add also a GetGoroutineName() string API? Thanks to that user can read goroutine's name after setting it". And I would like that not to happen, as it enables wrong code pattern and design, IMHO. — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or unsubscribe.

[Cyberax]

Most importantly, panics triggered by asynchronous events (e.g. a nil pointer dereference or out-of-bounds access) are also often impossible to correlate with the context that triggered them unless the recovery code happens to have the context. There is absolutely no workaround for that.
What is wrong with that? Deferred function can access input context.Context and easily enrich panic's message with context info.

There's nothing wrong with that per se, until you start using third-party libraries that can launch goroutines behind your back.

Additionally, the main way to pass the context these days is context.Context. But there's no Context.Detach() method to detach the context from its cancellation lifetime, so third-party libraries often have to create a new context and they can't generically extract information that is needed for logging from the context that was passed to them.

The example that has caused me problems was in AWS X-Ray SDK that launches a goroutine that asynchronously closes an active segment and in a TCP multiplexing library that did the same for non-blocking reads.

I think that if we accepted this proposal, the next ask would be: "why don't we add also a GetGoroutineName() string API? Thanks to that user can read goroutine's name after setting it". And I would like that not to happen, as it enables wrong code pattern and design, IMHO.

I agree, any attempts to add TLS should be directed to the FAQ about them. TLS is just ugly. If this is accepted, I'll make sure to add a huge warning to SetGoroutineName about this very issue.

[Cyberax]

Here's an example of goroutine names in Delve. This is an output of "goroutines" command on my staging server:

[xdg]

The goroutine name will be silently inherited by any goroutines spawned by the parent process.

I like the general idea of goroutine naming, but I have concerns about the specific design decision above. I think there's value in giving goroutines unique names, such as making it trivial to attach a debugger to a specific goroutine without having to correlate to the line that launched it. Having names inherited defeats that benefit of uniqueness. Name inheritance seems to be just another form of dynamic context passing: "everything from here on down the call stack, pass this name along". If that form of dynamic context passing makes sense, why limit it to a single string value? Why special case its handling in the call stack?

Some languages allow assigning names to otherwise anonymous closures. This proposal seems comparable to that: giving a name to an otherwise anonymous construct of the runtime. I think it should be explored further but that limitation on the scope of it.

[Cyberax]

I feel that name inheritance is a necessary feature because it's fairly common for third-party libraries to launch utility goroutines in regular-looking methods and then screw them up somehow. I've seen more than one such example.

I debated with myself about adding a unique suffix for inherited goroutines but ultimately decided against it. This feature is designed for human users, and typically once you have a request ID in the goroutine name it's not that hard to find the context. I played a bit with Delve today and the combination of goroutine name and last digits of the goroutine ID works for me perfectly.

Oh, and names are not guaranteed to be unique. I'm going to rename the whole patch to use "Trace ID" instead of "Name".

As for generalizing it, I don't want this at all. The Go language authors stated their opposition to TLS and any generalized "context inheritance" would necessitate it. My proposal is meant to solve one very specific use-case, without introducing new sweeping changes.

[rsc]

If we added this, it would be complexity that everyone who has a go statement will eventually be forced to know about. It would infect all code.

People will send PRs to add debug.SetGoroutineName in every go statement. And of course then you can't go f(x) anymore. You now have to go func(x int) { debug.SetGoroutineName("fred"); f(x) }(x) to appease the users who otherwise keep filing bug reports that your goroutines don't have names. Personally, I prefer the approach that lets me write go f(x) without being told I am holding it wrong.

"Name inheritance" does not solve the problem. For example there are plenty of cases where a library might lazily create a background goroutine the first time it is entered. It is wrong to inherit the name in that case. People will still send PRs to add debug.SetGoroutineName in every go statement.

There is also plenty that debuggers can do to identify goroutines without having to shift the burden onto users. The stack traces already record and display the location where the goroutine was created in the code, which identifies the specific go statement that created it. That should be enough for a debugger like Delve to group goroutines meaningfully. In the past I have also used the exact receiver pointers to group related goroutines. Delve or another tool could use those for clustering too. (Show me all goroutines with this specific receiver in the top-most function call, for example.)

Let's work on making the debugger better instead of on forcing users to add what amount to print statements to their code.

[robaho]

@rsc I understand those concerns, and they are valid, but I think the point being overlooked is that often all of the Go routines have the exact same creation point - this is especially common for request handlers (http, grpc) - so if you break-point in the debugger, or perform traces/analysis - you can't just use the creation site to distinguish.

I guess the debugger could be changed to look to a context var in the call stack, and then be configured to use a property of the context to display as the "name", but this is asking a lot and every context would need to be handled differently.

I don't fully understand the push-back here - this sort of "thread of execution context/name" has been around a long time, and was added because it is nearly required in performing concurrent application analysis - it is SO much more difficult debugging large concurrent programs in Go than any other environment I've worked with - and this is a shame, because the tracing facility / pprof is top notch (and a big component).