runtime/pprof: Missing labels from goroutines stacks containing systemstack

[felixge]

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

$ go version
go version go1.17.1 darwin/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/felix.geisendoerfer/Library/Caches/go-build"
GOENV="/Users/felix.geisendoerfer/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS="-count=1"
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/felix.geisendoerfer/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/felix.geisendoerfer/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.17.1/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.17.1/libexec/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="go1.17.1"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/felix.geisendoerfer/go/src/github.com/felixge/dump/cpu-profiler-label-bug/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/mg/xwzs985x35789zk2l14nk8k80000gn/T/go-build2698991037=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I created a Go program like cpu-profiler-label-bug.go shown below that uses pprof labels and generates a CPU profile:

package main

import (
	"context"
	"fmt"
	"io"
	"os"
	"runtime"
	"runtime/pprof"
	"time"
)

func main() {
	file, _ := os.Create("./cpu.pprof")
	pprof.StartCPUProfile(file)
	defer pprof.StopCPUProfile()

	ctx := context.Background()
	labels := pprof.Labels("foo", "bar")
	pprof.Do(ctx, labels, func(_ context.Context) {
		for i := 0; i < runtime.GOMAXPROCS(0)*10; i++ {
			go cpuHog()
		}
	})
	time.Sleep(10 * time.Second)
}

func cpuHog() {
	for i := 0; ; i++ {
		fmt.Fprintf(io.Discard, "%d", i)
	}
}

I then executed the program and used pprofutils labelframes to turn cpu.pprof into cpu.label.pprof. The latter modifies each sample in the pprof to add a new root frame that contains the value of my label foo (or N/A if the label is not present). This makes it easier to view the labels than in the graph view of pprof.

go run cpu-profiler-label-bug.go
curl --data-binary @cpu.pprof pprof.to/labelframes?label=foo > cpu.label.pprof
go tool pprof -http=:6060 cpu.label.pprof

What did you expect to see?

main.cpuHog should show up only under the foo=bar frame and not the foo=N/A frame:

What did you see instead?

3.95% of all samples containing main.cpuHog show below the foo=N/A frame which means they were missing the foo=bar label.

Zooming into those 3.95% of the flame graph, I noticed that most samples contain a systemstack frame.

See zip file below for code, pprofs and screenshots: cpu-profiler-label-bug.zip

My Analysis

As far as I can tell this problem can be easily fixed via the patch below. In fact that's what I used to create the "What did you expect to see" screenshot above.

diff --git a/src/runtime/proc.go b/src/runtime/proc.go
index a144b36ec8..bebbd7b3b1 100644
--- a/src/runtime/proc.go
+++ b/src/runtime/proc.go
@@ -4773,7 +4773,7 @@ func sigprof(pc, sp, lr uintptr, gp *g, mp *m) {
        }
 
        if prof.hz != 0 {
-               cpuprof.add(gp, stk[:n])
+               cpuprof.add(gp.m.curg, stk[:n])
        }
        getg().m.mallocing--
 }

The reason this is the right thing to do is because gp.m.curg should always point to the right goroutine, even when the systemstack goroutine is executing. At least that's how traceback.go stitches the stacks together.

Since I suspect this to be the correct fix, I'll be submitting a CL shortly. It's like to fix more situations as well (morestack, newstack, etc.)

[gopherbot]

Change https://golang.org/cl/351751 mentions this issue: runtime: fix missing pprof labels

[prattmic]

Reverted in https://golang.org/cl/360757 due to broken builders on the new test.

[gopherbot]

Change https://golang.org/cl/362614 mentions this issue: runtime/pprof: include labels in profile dump

[gopherbot]

Change https://golang.org/cl/367200 mentions this issue: runtime: fix missing pprof labels

[prattmic]

greplogs --dashboard -md -l -e 'TestLabelSystemstack':

2021-12-05T12:50:44-ecf6b52/freebsd-arm-paulzhol
2021-12-05T12:50:44-ecf6b52/linux-mipsle-rtrk
2021-12-04T17:16:07-3396878/freebsd-arm-paulzhol
2021-12-04T17:16:07-3396878/openbsd-mips64-jsing
2021-12-04T11:59:35-1876b38/freebsd-arm-paulzhol
2021-12-04T11:59:35-1876b38/openbsd-mips64-jsing
2021-12-04T04:50:55-549cfef/freebsd-arm-paulzhol
2021-12-04T01:07:21-821bf04/linux-386
2021-12-03T21:25:05-d20a0bf/linux-ppc64le-buildlet
2021-12-03T21:25:05-d20a0bf/openbsd-mips64-jsing
2021-12-03T16:11:38-9b0de08/linux-riscv64-unmatched

[felixge]

Update: Turns out this issue also impacted cgo stacks, which pretty much never have labels in go1.17 in my testing.

However, CL 367200 seems to have also fixed the cgo case 🥳