runtime/pprof: doesn't dump goroutine labels when stacks collected

[xaurx]

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

$ go version
1.21.3

What did you do?

when collecting all goroutine call traces for debug purposes (e.g. using gops tool) one expects to see labels associated with goroutines. However, writeGoroutine() with debug>=2 which calls writeGoroutineStacks() do not provide them.

Yet legacy call traces provided with debug<2 in call like this:

pprof.Lookup("goroutine").WriteTo(conn, 1)

provide goroutine labels.

What did you expect to see?

goroutines stacks with labels.

What did you see instead?

goroutines stacks without labels.

[rhysh]

Thank you for the report.

Looks like debug=0 and debug=1 worked with Go 1.18 and stopped working with Go 1.19. Looks like debug=2 may never have worked?

Yet legacy call traces provided with debug<2 in call like this: pprof.Lookup("goroutine").WriteTo(conn, 1) provide goroutine labels.

It looks to me like this was true for Go 1.18, but is no longer the case. Do you see it working now @xaurx , with go1.21.3?

https://go.dev/play/p/BkLFOW46oiO

$ go1.18 version
go version go1.18.10 darwin/arm64
$ go1.18 run /tmp/63712.go
pprof.Lookup("goroutine").WriteTo(..., 0); len=573 idx=545
pprof.Lookup("goroutine").WriteTo(..., 1); len=689 idx=127
pprof.Lookup("goroutine").WriteTo(..., 2); len=434 idx=-1

$ go1.19 version
go version go1.19.13 darwin/arm64
$ go1.19 run /tmp/63712.go
pprof.Lookup("goroutine").WriteTo(..., 0); len=603 idx=-1
pprof.Lookup("goroutine").WriteTo(..., 1); len=657 idx=-1
pprof.Lookup("goroutine").WriteTo(..., 2); len=442 idx=-1

$ go1.20 version
go version go1.20.10 darwin/arm64
$ go1.20 run /tmp/63712.go
pprof.Lookup("goroutine").WriteTo(..., 0); len=623 idx=-1
pprof.Lookup("goroutine").WriteTo(..., 1); len=657 idx=-1
pprof.Lookup("goroutine").WriteTo(..., 2); len=442 idx=-1

$ go1.21 version
go version go1.21.3 darwin/arm64
$ go1.21 run /tmp/63712.go
pprof.Lookup("goroutine").WriteTo(..., 0); len=623 idx=-1
pprof.Lookup("goroutine").WriteTo(..., 1); len=657 idx=-1
pprof.Lookup("goroutine").WriteTo(..., 2); len=434 idx=-1

$ go1.22 version                                        
go version devel go1.22-9162c4be9c Tue Oct 24 18:12:46 2023 +0000 darwin/arm64
$ go1.22 run /tmp/63712.go                              
pprof.Lookup("goroutine").WriteTo(..., 0); len=729 idx=-1
pprof.Lookup("goroutine").WriteTo(..., 1); len=657 idx=-1
pprof.Lookup("goroutine").WriteTo(..., 2); len=442 idx=-1

[xaurx]

@rhysh thanks for so fast reply. Seems you faced another "bug"... if you add

    go pprof.Do(context.Background(), pprof.Labels("key123", "val456_VALUE_IS_HERE"), func(ctx context.Context) { time.Sleep(time.Hour) })

you will notice it starts to work with debug=1 (https://go.dev/play/p/lgGnPLuSN1Z). I've checked and it seems to be an issue with the main goroutine only. If you call pprof.SetGoroutineLabels() in a newly spawned goroutine - your test works fine (i.e. debug=1 outputs labels, debug=2 - doesn't).

[rhysh]

Here's some previous discussion of "include labels in debug=2 goroutine profile", but it's mixed in with discussions of adding labels to other profiles: https://github.com/golang/go/issues/23458#issuecomment-620149386 . I don't see an issue specifically for that request / proposal. @mknyszek might have more context paged in on what obstacles we might need to overcome to make that happen.

Yes, I see now that with debug=0 and debug=1, the labels are missing only from the single goroutine that captures the profile. (The finalizer goroutine gets some other special handling, which is working properly.) https://go.dev/play/p/YTkp_laHyly I'll send a CL to repair that and add the missing test.

CC @mknyszek @golang/runtime

[gopherbot]

Change https://go.dev/cl/537515 mentions this issue: runtime/pprof: include labels for caller of goroutine profile

[mknyszek]

@rhysh Is this fixed as of https://go.dev/cl/537515? Closing optimistically; let me know if we should reopen.

[rhysh]

@mknyszek I understood this to be a feature request, asking that goroutine labels be included in the debug=2 output. Then while trying to understand the request, I accidentally discovered a bug with debug=0 and =1 which I fixed with CL 537515 — but the original feature request remains unaddressed. I think we should reopen the issue, thanks.

However, writeGoroutine() with debug>=2 which calls writeGoroutineStacks() do not provide them.

[mknyszek]

Got it, misunderstood. Thanks!

[xaurx]

Any chance this to be fixed as it's very important to be able to see labels on goroutines for debugging? Thanks!