runtime/race: goroutine IDs in race failures are incorrect

[petermattis]

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

Both:
go version go1.10.4 darwin/amd64
go version go1.11 darwin/amd64

Does this issue reproduce with the latest release?

Yes.

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/pmattis/Library/Caches/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/pmattis/Development/go"
GORACE=""
GOROOT="/Users/pmattis/Development/go1.10"
GOTMPDIR=""
GOTOOLDIR="/Users/pmattis/Development/go1.10/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/qc/fpqpgdqd167c70dtc6840xxh0000gn/T/go-build123544902=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

The goroutine IDs contained in stacktraces do not match up with the goroutine IDs in race failure messages. The small repro below demonstrates this.

package racegoid

import (
	"runtime/debug"
	"testing"
	"time"
)

func TestRaceGoroutineID(t *testing.T) {
	var a int
	f := func() {
		start := time.Now()
		debug.PrintStack()
		time.Sleep(time.Second)
		for time.Since(start) < 3*time.Second {
			a = 5
		}
	}
	go f()
	f()
	t.Log(a)
}

Notice that the stack traces indicate that the test is using goroutines 35 and 36 while the race failures indicate goroutines 6 and 7.

~ go test -v -race
=== RUN   TestRaceGoroutineID
goroutine 35 [running]:
runtime/debug.Stack(0x118d679, 0x10a6a51, 0x12f82f8)
	/Users/pmattis/Development/go1.11/src/runtime/debug/stack.go:24 +0xb5
runtime/debug.PrintStack()
	/Users/pmattis/Development/go1.11/src/runtime/debug/stack.go:16 +0x34
github.com/petermattis/race-goid.TestRaceGoroutineID.func1()
	/Users/pmattis/Development/go/src/github.com/petermattis/race-goid/test_test.go:13 +0x69
github.com/petermattis/race-goid.TestRaceGoroutineID(0xc0000cc100)
	/Users/pmattis/Development/go/src/github.com/petermattis/race-goid/test_test.go:20 +0xd8
testing.tRunner(0xc0000cc100, 0x11decf8)
	/Users/pmattis/Development/go1.11/src/testing/testing.go:827 +0x163
created by testing.(*T).Run
	/Users/pmattis/Development/go1.11/src/testing/testing.go:878 +0x651
goroutine 36 [running]:
runtime/debug.Stack(0x118d679, 0x10a6a51, 0x12f82f8)
	/Users/pmattis/Development/go1.11/src/runtime/debug/stack.go:24 +0xb5
runtime/debug.PrintStack()
	/Users/pmattis/Development/go1.11/src/runtime/debug/stack.go:16 +0x34
github.com/petermattis/race-goid.TestRaceGoroutineID.func1()
	/Users/pmattis/Development/go/src/github.com/petermattis/race-goid/test_test.go:13 +0x69
created by github.com/petermattis/race-goid.TestRaceGoroutineID
	/Users/pmattis/Development/go/src/github.com/petermattis/race-goid/test_test.go:19 +0xce
==================
WARNING: DATA RACE
Write at 0x00c00009a090 by goroutine 7:
  github.com/petermattis/race-goid.TestRaceGoroutineID.func1()
      /Users/pmattis/Development/go/src/github.com/petermattis/race-goid/test_test.go:16 +0x85

Previous write at 0x00c00009a090 by goroutine 6:
  github.com/petermattis/race-goid.TestRaceGoroutineID.func1()
      /Users/pmattis/Development/go/src/github.com/petermattis/race-goid/test_test.go:16 +0x85
  github.com/petermattis/race-goid.TestRaceGoroutineID()
      /Users/pmattis/Development/go/src/github.com/petermattis/race-goid/test_test.go:20 +0xd7
  testing.tRunner()
      /Users/pmattis/Development/go1.11/src/testing/testing.go:827 +0x162

Goroutine 7 (running) created at:
  github.com/petermattis/race-goid.TestRaceGoroutineID()
      /Users/pmattis/Development/go/src/github.com/petermattis/race-goid/test_test.go:19 +0xcd
  testing.tRunner()
      /Users/pmattis/Development/go1.11/src/testing/testing.go:827 +0x162

Goroutine 6 (running) created at:
  testing.(*T).Run()
      /Users/pmattis/Development/go1.11/src/testing/testing.go:878 +0x650
  testing.runTests.func1()
      /Users/pmattis/Development/go1.11/src/testing/testing.go:1119 +0xa8
  testing.tRunner()
      /Users/pmattis/Development/go1.11/src/testing/testing.go:827 +0x162
  testing.runTests()
      /Users/pmattis/Development/go1.11/src/testing/testing.go:1117 +0x4ee
  testing.(*M).Run()
      /Users/pmattis/Development/go1.11/src/testing/testing.go:1034 +0x2ee
  main.main()
      _testmain.go:42 +0x221
==================
--- FAIL: TestRaceGoroutineID (3.00s)
    test_test.go:21: 5
    testing.go:771: race detected during execution of test
FAIL
exit status 1
FAIL	github.com/petermattis/race-goid	3.011s

[ianlancetaylor]

CC @dvyukov

[dvyukov]

Should be "relatively easy" fixable as tsan has a notion of "external OS thread ID". Currently we don't uyse it for Go (always pass 0):

void ThreadStart(ThreadState *thr, int tid, tid_t os_id, bool workerthread);

void __tsan_go_start(ThreadState *parent, ThreadState **pthr, void *pc) {
  ThreadState *thr = AllocGoroutine();
  *pthr = thr;
  int goid = ThreadCreate(parent, (uptr)pc, 0, true);
  ThreadStart(thr, goid, 0, /*workerthread*/ false);
}

So if we pass goroutine id to __tsan_go_start and store it as os_id and then print os_id in race reports, it should do.

But this will require synchronously updating Go and tsan and updating all syso files.

[dvyukov]

There was an Unplanned tag IIRC, but can't find it now...

[ianlancetaylor]

Unplanned is a milestone.