runtime/pprof: race detected between goroutines?debug=1 and setting goroutine labels

[tbg]

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

$ go version
go version go1.17.3 darwin/amd64

Does this issue reproduce with the latest release?

yes, same with 1.17.5 (just checked)

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/tobias/Library/Caches/go-build"
GOENV="/Users/tobias/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/tobias/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/tobias/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="go1.17.5"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/dev/null"
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/nm/j0343rr1275fpm9r3bk3vr200000gq/T/go-build2415583411=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

go test -race foo_test.go

var labelSet = pprof.Labels("foo", "bar")

func TestRace(t *testing.T) {
	go func(ctx context.Context) {
		ctx = pprof.WithLabels(ctx, labelSet)
		pprof.SetGoroutineLabels(ctx)
	}(context.Background())
	require.NoError(t, pprof.Lookup("goroutine").WriteTo(io.Discard, 1))
}

What did you expect to see?

Passing test and no data race.

What did you see instead?

=== RUN   TestRace
==================
WARNING: DATA RACE
Read at 0x00c000124020 by goroutine 22:
  runtime/pprof.(*labelMap).String()
      /usr/local/go/src/runtime/pprof/label.go:46 +0x53
  runtime/pprof.printCountProfile.func1()
      /usr/local/go/src/runtime/pprof/pprof.go:415 +0x178
  runtime/pprof.printCountProfile()
      /usr/local/go/src/runtime/pprof/pprof.go:424 +0x2f1
  runtime/pprof.writeRuntimeProfile()
      /usr/local/go/src/runtime/pprof/pprof.go:732 +0x1b8
  runtime/pprof.writeGoroutine()
      /usr/local/go/src/runtime/pprof/pprof.go:684 +0x8f
  runtime/pprof.(*Profile).WriteTo()
      /usr/local/go/src/runtime/pprof/pprof.go:331 +0x1b0
  github.com/cockroachdb/cockroach/pkg/util/stop.TestRace()
      /Users/tobias/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/tc_test.go:29 +0x129
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/local/go/src/testing/testing.go:1306 +0x47

Previous write at 0x00c000124020 by goroutine 23:
  runtime/pprof.WithLabels()
      /usr/local/go/src/runtime/pprof/label.go:60 +0x88
  github.com/cockroachdb/cockroach/pkg/util/stop.TestRace.func1()
      /Users/tobias/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/tc_test.go:26 +0x57
  github.com/cockroachdb/cockroach/pkg/util/stop.TestRace·dwrap·20()
      /Users/tobias/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/tc_test.go:28 +0x58

[tbg]

I see that there's already some special casing around labels:

go/src/runtime/profbuf.go

Lines 545 to 558 in 90fb5a4

	b.rNext = br.addCountsAndClearFlags(skip+di, ti)
	if raceenabled {
	// Match racereleasemerge in runtime_setProfLabel,
	// so that the setting of the labels in runtime_setProfLabel
	// is treated as happening before any use of the labels
	// by our caller. The synchronization on labelSync itself is a fiction
	// for the race detector. The actual synchronization is handled
	// by the fact that the signal handler only reads from the current
	// goroutine and uses atomics to write the updated queue indices,
	// and then the read-out from the signal handler buffer uses
	// atomics to read those queue indices.
	raceacquire(unsafe.Pointer(&labelSync))
	}

go/src/runtime/proflabel.go

Lines 11 to 33 in 90fb5a4

	//go:linkname runtime_setProfLabel runtime/pprof.runtime_setProfLabel
	func runtime_setProfLabel(labels unsafe.Pointer) {
	// Introduce race edge for read-back via profile.
	// This would more properly use &getg().labels as the sync address,
	// but we do the read in a signal handler and can't call the race runtime then.
	//
	// This uses racereleasemerge rather than just racerelease so
	// the acquire in profBuf.read synchronizes with *all* prior
	// setProfLabel operations, not just the most recent one. This
	// is important because profBuf.read will observe different
	// labels set by different setProfLabel operations on
	// different goroutines, so it needs to synchronize with all
	// of them (this wouldn't be an issue if we could synchronize
	// on &getg().labels since we would synchronize with each
	// most-recent labels write separately.)
	//
	// racereleasemerge is like a full read-modify-write on
	// labelSync, rather than just a store-release, so it carries
	// a dependency on the previous racereleasemerge, which
	// ultimately carries forward to the acquire in profBuf.read.
	if raceenabled {
	racereleasemerge(unsafe.Pointer(&labelSync))
	}

Perhaps this isn't quite working out as intended.

[gopherbot]

Change https://go.dev/cl/385660 mentions this issue: runtime/pprof: add race annotations for goroutine profiles