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

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

Open
xaurx opened this issue Oct 24, 2023 · 8 comments
Open

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

xaurx opened this issue Oct 24, 2023 · 8 comments
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.

Comments

@xaurx
Copy link

xaurx commented Oct 24, 2023

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.

@xaurx xaurx changed the title affected/package: runtime/pprof runtime/pprof doesn't dump goroutine labels when stacks collected Oct 24, 2023
@rhysh
Copy link
Contributor

rhysh commented Oct 24, 2023

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
Copy link
Author

xaurx commented Oct 24, 2023

@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).

xaurx added a commit to xaurx/gops that referenced this issue Oct 24, 2023
Unfortunately legacy format is more helpful in debug as it dumps
goroutine labels. 'gops stack' doesn't dump them.

Golang issue: golang/go#63712
@rhysh
Copy link
Contributor

rhysh commented Oct 24, 2023

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: #23458 (comment) . 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
Copy link

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

@seankhliao seankhliao changed the title runtime/pprof doesn't dump goroutine labels when stacks collected runtime/pprof: doesn't dump goroutine labels when stacks collected Oct 25, 2023
@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Oct 25, 2023
gopherbot pushed a commit that referenced this issue Oct 25, 2023
The goroutine profile has close to three code paths for adding a
goroutine record to the goroutine profile: one for the goroutine that
requested the profile, one for every other goroutine, plus some special
handling for the finalizer goroutine. The first of those captured the
goroutine stack, but neglected to include that goroutine's labels.

Update the tests to check for the inclusion of labels for all three
types of goroutines, and include labels for the creator of the goroutine
profile.

For #63712

Change-Id: Id5387a5f536d3c37268c240e0b6db3d329a3d632
Reviewed-on: https://go-review.googlesource.com/c/go/+/537515
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Michael Pratt <mpratt@google.com>
Auto-Submit: Rhys Hiltner <rhys@justin.tv>
Reviewed-by: David Chase <drchase@google.com>
@dr2chase dr2chase added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Oct 25, 2023
@mknyszek
Copy link
Contributor

mknyszek commented Nov 1, 2023

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

@mknyszek mknyszek closed this as completed Nov 1, 2023
@rhysh
Copy link
Contributor

rhysh commented Nov 1, 2023

@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
Copy link
Contributor

mknyszek commented Nov 1, 2023

Got it, misunderstood. Thanks!

@mknyszek mknyszek reopened this Nov 1, 2023
@xaurx
Copy link
Author

xaurx commented Dec 13, 2023

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Status: In Progress
Development

No branches or pull requests

5 participants