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.

Sign up for GitHub

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

Jump to bottom

cmd/compile/internal: DATA RACE if -coverprofile flag is provided #56370

Closed
olegbespalov opened this issue Oct 21, 2022 · 7 comments
Closed

cmd/compile/internal: DATA RACE if -coverprofile flag is provided #56370

olegbespalov opened this issue Oct 21, 2022 · 7 comments
Assignees
@thanm
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Go1.20

Comments

@olegbespalov
Copy link

olegbespalov commented Oct 21, 2022 •
edited by mvdan
Loading

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

$  gotip version
go version devel go1.20-c75b10b Fri Oct 21 05:28:30 2022 +0000 linux/amd64

Does this issue reproduce with the latest release?

Not from my experience

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

go env Output
$ gotip env
GO111MODULE="auto"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/olegbespalov/.cache/go-build"
GOENV="/home/olegbespalov/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/olegbespalov/go/pkg/mod"
GOOS="linux"
GOPATH="/home/olegbespalov/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/olegbespalov/sdk/gotip"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/olegbespalov/sdk/gotip/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="devel go1.20-c75b10b Fri Oct 21 05:28:30 2022 +0000"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/olegbespalov/projects/sandbox/go/race/go.mod"
GOWORK=""
CGO_CFLAGS="-O2 -g"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build352388576=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Run

gotip test --count=1 -race -coverprofile=/tmp/code-coverage.out ./...

On the package that filter

filter.go

package filter

func New() func(error) bool {
	return func(error) bool {
		return false
	}
}

filter_test.go

package filter_test

import (
	"testing"

	"github.com/olegbespalov/race/filter"
)

func Test1(t *testing.T) {
	t.Parallel()

	_ = filter.New()
}

func Test2(t *testing.T) {
	t.Parallel()

	_ = filter.New()
}

func Test3(t *testing.T) {
	t.Parallel()

	_ = filter.New()
}

func Test4(t *testing.T) {
	t.Parallel()

	_ = filter.New()
}

My go.mod, just in case

module github.com/olegbespalov/race

go 1.19

What did you expect to see?

No data races

What did you see instead?

A race was detected.

race trace stack 
==================
WARNING: DATA RACE
Write at 0x000001692fe0 by goroutine 8:
  github.com/olegbespalov/race/filter.New()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter.go:3 +0x50
  github.com/olegbespalov/race/filter_test.Test2()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter_test.go:18 +0x31
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.(*T).Run.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x47

Previous write at 0x000001692fe0 by goroutine 7:
  github.com/olegbespalov/race/filter.New()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter.go:3 +0x50
  github.com/olegbespalov/race/filter_test.Test1()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter_test.go:12 +0x31
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.(*T).Run.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x47

Goroutine 8 (running) created at:
  testing.(*T).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x75d
  testing.runTests.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1913 +0x72
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.runTests()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1911 +0x884
  testing.(*M).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1783 +0xa84
  main.main()
      _testmain.go:86 +0x2fc

Goroutine 7 (running) created at:
  testing.(*T).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x75d
  testing.runTests.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1913 +0x72
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.runTests()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1911 +0x884
  testing.(*M).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1783 +0xa84
  main.main()
      _testmain.go:86 +0x2fc
==================
==================
WARNING: DATA RACE
Write at 0x000001692fe0 by goroutine 9:
  github.com/olegbespalov/race/filter.New()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter.go:3 +0x50
  github.com/olegbespalov/race/filter_test.Test3()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter_test.go:24 +0x31
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.(*T).Run.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x47

Previous write at 0x000001692fe0 by goroutine 10:
  github.com/olegbespalov/race/filter.New()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter.go:3 +0x50
  github.com/olegbespalov/race/filter_test.Test4()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter_test.go:30 +0x31
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.(*T).Run.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x47

Goroutine 9 (running) created at:
  testing.(*T).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x75d
  testing.runTests.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1913 +0x72
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.runTests()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1911 +0x884
  testing.(*M).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1783 +0xa84
  main.main()
      _testmain.go:86 +0x2fc

Goroutine 10 (running) created at:
  testing.(*T).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x75d
  testing.runTests.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1913 +0x72
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.runTests()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1911 +0x884
  testing.(*M).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1783 +0xa84
  main.main()
      _testmain.go:86 +0x2fc
==================
==================
WARNING: DATA RACE
Write at 0x000001692fe4 by goroutine 9:
  github.com/olegbespalov/race/filter.New()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter.go:3 +0x7c
  github.com/olegbespalov/race/filter_test.Test3()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter_test.go:24 +0x31
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.(*T).Run.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x47

Previous write at 0x000001692fe4 by goroutine 8:
  github.com/olegbespalov/race/filter.New()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter.go:3 +0x7c
  github.com/olegbespalov/race/filter_test.Test2()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter_test.go:18 +0x31
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.(*T).Run.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x47

Goroutine 9 (running) created at:
  testing.(*T).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x75d
  testing.runTests.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1913 +0x72
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.runTests()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1911 +0x884
  testing.(*M).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1783 +0xa84
  main.main()
      _testmain.go:86 +0x2fc

Goroutine 8 (running) created at:
  testing.(*T).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x75d
  testing.runTests.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1913 +0x72
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.runTests()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1911 +0x884
  testing.(*M).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1783 +0xa84
  main.main()
      _testmain.go:86 +0x2fc
==================
==================
WARNING: DATA RACE
Write at 0x000001692fe8 by goroutine 8:
  github.com/olegbespalov/race/filter.New()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter.go:3 +0x92
  github.com/olegbespalov/race/filter_test.Test2()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter_test.go:18 +0x31
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.(*T).Run.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x47

Previous write at 0x000001692fe8 by goroutine 10:
  github.com/olegbespalov/race/filter.New()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter.go:3 +0x92
  github.com/olegbespalov/race/filter_test.Test4()
      /home/olegbespalov/projects/sandbox/go/race/filter/filter_test.go:30 +0x31
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.(*T).Run.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x47

Goroutine 8 (running) created at:
  testing.(*T).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x75d
  testing.runTests.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1913 +0x72
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.runTests()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1911 +0x884
  testing.(*M).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1783 +0xa84
  main.main()
      _testmain.go:86 +0x2fc

Goroutine 10 (running) created at:
  testing.(*T).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1548 +0x75d
  testing.runTests.func1()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1913 +0x72
  testing.tRunner()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1501 +0x216
  testing.runTests()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1911 +0x884
  testing.(*M).Run()
      /home/olegbespalov/sdk/gotip/src/testing/testing.go:1783 +0xa84
  main.main()
      _testmain.go:86 +0x2fc
==================
--- FAIL: Test1 (0.00s)
--- FAIL: Test2 (0.00s)
    testing.go:1374: race detected during execution of test
--- FAIL: Test3 (0.00s)
    testing.go:1374: race detected during execution of test
--- FAIL: Test4 (0.00s)
    testing.go:1374: race detected during execution of test
FAIL
	github.com/olegbespalov/race/filter	coverage: 50.0% of statements
FAIL	github.com/olegbespalov/race/filter	0.011s
FAIL

So this is around for a week or so in our CI. I tried to git bisect, and it showed me that this commit 4a459cb is the one where it started, but maybe I'm wrong here 🤷

If I run the go test without -coverprofile flag, no data race appears.

$ gotip test --count=1 -race ./...
ok      github.com/olegbespalov/race/filter     0.021s
@mvdan
Copy link
Member

mvdan commented Oct 21, 2022

What makes you think that this is not a valid data race in your code? The two writes which are racing are both in your code, and your tests are calling your code in parallel. So that seems like a valid race to me.

@mvdan mvdan added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Oct 21, 2022
@olegbespalov
Copy link
Author

olegbespalov commented Oct 21, 2022 •
edited
Loading

Hi @mvdan !

I'm not sure if I get your point 🤔

Which writes you're referring to? In the example, I'm just doing assignments (using Blank Identifier).

My assumption is based on the fact that all of the variables that I'm assigning are local variables.

Also, as I said below, the data race happens only when the code coverage is measured.

@mvdan
Copy link
Member

mvdan commented Oct 21, 2022

I see, I hadn't noticed how innocent the New function is. It's not writing to any shared memory by design, as far as I can tell. Perhaps you're right that it's the instrumentation.

cc @thanm

@mvdan mvdan removed the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Oct 21, 2022
@thanm
Copy link
Contributor

thanm commented Oct 21, 2022

Thanks, I'll take a look.

@olegbespalov
Copy link
Author

No worries, if that makes sense, I've put the example into the CI just for the sake of clarity

https://github.com/olegbespalov/race/actions/runs/3297314972/jobs/5437986048

@thanm
Copy link
Contributor

thanm commented Oct 21, 2022

OK, I can see the issue, will send a fix later this morning. Thanks for the report.

@thanm thanm self-assigned this Oct 21, 2022
@thanm thanm added the NeedsFix The path to resolution is known, but the work has not been done. label Oct 21, 2022
@thanm thanm added this to the Go1.20 milestone Oct 21, 2022
@gopherbot
Copy link
Contributor

Change https://go.dev/cl/444617 mentions this issue: cmd/cover: fix problem with race mode and inlining

romaindoumenc pushed a commit to TroutSoftware/go that referenced this issue Nov 3, 2022
@thanm @romaindoumenc
cmd/cover: fix problem with race mode and inlining
02a1f14 
This patch fixes a problem in which we can get a data race on a
coverage counter function registration sequence. The scenario is that
package P contains a function F that is built with coverage, then F is
inlined into some other package that isn't being instrumented. Within
F's exported function body counter updates were being done with
atomics, but the initial registration sequence was not, which had the
potential to trigger a race. Fix: if race mode is enabled and we're
using atomics for counter increments, also use atomics in the
registration sequence.

Fixes golang#56370.

Change-Id: If274b61714b90275ff95fc6529239e9264b0ab0c
Reviewed-on: https://go-review.googlesource.com/c/go/+/444617
Reviewed-by: Cherry Mui <cherryyz@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Than McIntosh <thanm@google.com>
@golang golang locked and limited conversation to collaborators Oct 21, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@thanm thanm

Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Milestone
Go1.20
Development

No branches or pull requests
4 participants
@mvdan @olegbespalov @gopherbot @thanm