runtime/metrics: data race detected in Read #53542

cristiangreco · 2022-06-24T17:41:45Z

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

$ go version
go version go1.18.3 darwin/arm64

Does this issue reproduce with the latest release?

Yes, still reproducible with 1.19beta1.

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

go env Output

$ go env
GO111MODULE=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/cristian/Library/Caches/go-build"
GOENV="/Users/cristian/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/cristian/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/cristian/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/opt/homebrew/Cellar/go/1.18.3/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/opt/homebrew/Cellar/go/1.18.3/libexec/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="go1.18.3"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/dev/null"
GOWORK=""
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 arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/98/fgzhqvmx7x1d61fqsvw9cg9m0000gn/T/go-build1308397819=/tmp/go-build -gno-record-gcc-switches -fno-common"
GOROOT/bin/go version: go version go1.18.3 darwin/arm64
GOROOT/bin/go tool compile -V: compile version go1.18.3
uname -v: Darwin Kernel Version 21.5.0: Tue Apr 26 21:08:29 PDT 2022; root:xnu-8020.121.3~4/RELEASE_ARM64_T8101
ProductName:	macOS
ProductVersion:	12.4
BuildVersion:	21F79
lldb --version: lldb-1316.0.9.46
Apple Swift version 5.6.1 (swiftlang-5.6.0.323.66 clang-1316.0.20.12)

What did you do?

runtime/metrics says that "It is safe to execute multiple Read calls concurrently". However, running the following code with race detector enabled suggests a data race. Unsure whether this is a false positive (metrics.Read uses a semaphore lock).

package main

import (
        "fmt"
        "runtime/metrics"
        "sync"
)

func main() {
        var wg sync.WaitGroup

        for i := 0; i < 2; i++ {
                wg.Add(1)
                go func() {
                        sample := make([]metrics.Sample, 1)
                        sample[0].Name = "/gc/heap/allocs:bytes"
                        metrics.Read(sample)
                        fmt.Printf("bytes allocated: %d\n", sample[0].Value.Uint64())
                        wg.Done()
                }()
        }

        wg.Wait()
}

What did you expect to see?

No race detected.

What did you see instead?

Data race detected.

$ go run -race main.go
bytes allocated: 511392
==================
WARNING: DATA RACE
Read at 0x00c000100030 by goroutine 8:
  runtime.evacuate_fast64()
      /opt/homebrew/Cellar/go/1.18.3/libexec/src/runtime/map_fast64.go:376 +0x3fc
  runtime/metrics.runtime_readMetrics()
      /opt/homebrew/Cellar/go/1.18.3/libexec/src/runtime/metrics.go:563 +0xc0

Previous write at 0x00c000100030 by goroutine 7:
  runtime.mapaccess2_faststr()
      /opt/homebrew/Cellar/go/1.18.3/libexec/src/runtime/map_faststr.go:108 +0x43c
  runtime.initMetrics()
      /opt/homebrew/Cellar/go/1.18.3/libexec/src/runtime/metrics.go:67 +0x254

Goroutine 8 (running) created at:
  main.main()
      /Users/cristian/Desktop/main.go:14 +0x50

Goroutine 7 (finished) created at:
  main.main()
      /Users/cristian/Desktop/main.go:14 +0x50
==================
bytes allocated: 552264
Found 1 data race(s)
exit status 66

The text was updated successfully, but these errors were encountered:

ianlancetaylor · 2022-06-24T17:57:15Z

CC @golang/runtime

prattmic · 2022-06-24T18:07:27Z

I believe this is a false positive, as semacquire/semrelease aren't race instrumented.

cc @mknyszek

aclements · 2022-06-28T15:15:08Z

Given that readMetrics and initMetrics are both in package runtime (readMetrics is linknamed to runtime/metrics, but race instrumentation just looks at the package we're compiling), why did this get any race instrumentation at all?

aclements · 2022-06-28T15:17:12Z

Oh, readMetrics didn't get any race instrumentation. The race instrumentation in this case is hand-coded in the map implementation (and hence insensitive to what package it's being called from). Probably we just need a little manual race instrumentation around the map usage in the metrics code.

aclements · 2022-06-28T18:05:49Z

This isn't new in 1.19, so it doesn't have to be a release-blocker. It's also probably easy to fix, so for now I'll leave it marked just so we don't lose track.

gopherbot · 2022-06-28T19:22:19Z

Change https://go.dev/cl/414517 mentions this issue: runtime: add race annotations to metricsSema

prattmic · 2022-06-28T19:41:29Z

@gopherbot please backport to 1.17 and 1.18.

This triggers a false positive in the race detector for programs calling runtime/metrics.Read from multiple goroutines. There is a workaround: use a single global lock around all calls to metrics.Read in the program. However, that is quite invasive and has serious performance implications for a high-performance API.

gopherbot · 2022-06-28T19:41:45Z

Backport issue(s) opened: #53589 (for 1.17), #53590 (for 1.18).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://go.dev/wiki/MinorReleases.

cherrymui · 2022-06-28T19:52:38Z

Would it make sense to change the map functions to not call the race functions if the caller PC is in the runtime package? It would add the overhead of a PC lookup, but it can be limited to race mode, so maybe it could be acceptable?

prattmic · 2022-06-28T20:01:34Z

I don't think it is necessary. Maps aren't too widely used in the runtime, and I'd prefer us to be able to expand the number of races in the runtime rather than turning it off. It would be nice to catch these quicker though.

cherrymui · 2022-06-28T20:08:24Z

I recall Windows callback is another place that uses a map and causes false race, #50249 .

prattmic · 2022-06-28T21:43:19Z

Argh. I sent a fix for that too, but that one is nastier because it is called prior to scheduler initialization, which is fine for the raceread/racewrite in the map, but not raceacquire/racerelease.

prattmic · 2022-06-28T21:43:48Z

That one does me a bit more inclined to turn it off in the map.

prattmic · 2022-06-28T22:07:19Z

FWIW, I did a quick benchmark. A non-race map access is ~3ns. A race map access is ~17ns. With an additional runtime pc check (for runtime. prefix), a race map access is ~32ns [1].

This isn't horrible given we're in race mode, but it is still pretty large.

[1] My map was in runtime_test, so the string comparison had to go through most of the characters before failing.

cherrymui · 2022-06-28T22:25:36Z

Thanks for the benchmark.

There are a few places where we check whether a PC is in the runtime. Maybe we could provide a 1-bit metadata for whether a function is a runtime function, to avoid the string comparison. But I guess in this case most of the overhead is probably the PC lookup, instead of the string comparison. Maybe we could make it simply an address range comparison, as the linker already lay out runtime functions together (mostly, I think).

gopherbot · 2022-06-29T20:08:30Z

Change https://go.dev/cl/415195 mentions this issue: [release-branch.go1.18] runtime: add race annotations to metricsSema

gopherbot · 2022-06-29T20:10:14Z

Change https://go.dev/cl/415196 mentions this issue: [release-branch.go1.17] runtime: add race annotations to metricsSema

metricsSema protects the metrics map. The map implementation is race instrumented regardless of which package is it called from. semacquire/semrelease are not automatically race instrumented, so we can trigger race false positives without manually annotating our lock acquire and release. See similar instrumentation on trace.shutdownSema and reflectOffs.lock. Fixes #53589. For #53542. Change-Id: Ia3fd239ac860e037d09c7cb9c4ad267391e70705 Reviewed-on: https://go-review.googlesource.com/c/go/+/414517 Run-TryBot: Michael Pratt <mpratt@google.com> TryBot-Result: Gopher Robot <gobot@golang.org> Reviewed-by: Cherry Mui <cherryyz@google.com> (cherry picked from commit d6481d5) Reviewed-on: https://go-review.googlesource.com/c/go/+/415196

metricsSema protects the metrics map. The map implementation is race instrumented regardless of which package is it called from. semacquire/semrelease are not automatically race instrumented, so we can trigger race false positives without manually annotating our lock acquire and release. See similar instrumentation on trace.shutdownSema and reflectOffs.lock. Fixes #53590. For #53542. Change-Id: Ia3fd239ac860e037d09c7cb9c4ad267391e70705 Reviewed-on: https://go-review.googlesource.com/c/go/+/414517 Run-TryBot: Michael Pratt <mpratt@google.com> TryBot-Result: Gopher Robot <gobot@golang.org> Reviewed-by: Cherry Mui <cherryyz@google.com> (cherry picked from commit d6481d5) Reviewed-on: https://go-review.googlesource.com/c/go/+/415195

metricsSema protects the metrics map. The map implementation is race instrumented regardless of which package is it called from. semacquire/semrelease are not automatically race instrumented, so we can trigger race false positives without manually annotating our lock acquire and release. See similar instrumentation on trace.shutdownSema and reflectOffs.lock. Fixes golang#53590. For golang#53542. Change-Id: Ia3fd239ac860e037d09c7cb9c4ad267391e70705 Reviewed-on: https://go-review.googlesource.com/c/go/+/414517 Run-TryBot: Michael Pratt <mpratt@google.com> TryBot-Result: Gopher Robot <gobot@golang.org> Reviewed-by: Cherry Mui <cherryyz@google.com> (cherry picked from commit d6481d5) Reviewed-on: https://go-review.googlesource.com/c/go/+/415195

metricsSema protects the metrics map. The map implementation is race instrumented regardless of which package is it called from. semacquire/semrelease are not automatically race instrumented, so we can trigger race false positives without manually annotating our lock acquire and release. See similar instrumentation on trace.shutdownSema and reflectOffs.lock. Fixes golang#53542. Change-Id: Ia3fd239ac860e037d09c7cb9c4ad267391e70705 Reviewed-on: https://go-review.googlesource.com/c/go/+/414517 Run-TryBot: Michael Pratt <mpratt@google.com> TryBot-Result: Gopher Robot <gobot@golang.org> Reviewed-by: Cherry Mui <cherryyz@google.com>

ianlancetaylor changed the title ~~Data race detected in metrics.Read~~ runtime/metrics: data race detected in Read Jun 24, 2022

ianlancetaylor added the NeedsInvestigation label Jun 24, 2022

ianlancetaylor added this to the Go1.19 milestone Jun 24, 2022

ianlancetaylor added the release-blocker label Jun 24, 2022

mknyszek self-assigned this Jun 26, 2022

mknyszek added this to Go Compiler / Runtime Jun 26, 2022

mknyszek moved this to Todo in Go Compiler / Runtime Jun 26, 2022

aclements assigned prattmic Jun 28, 2022

This was referenced Jun 28, 2022

runtime/metrics: data race detected in Read [1.17 backport] #53589

Closed

runtime/metrics: data race detected in Read [1.18 backport] #53590

Closed

cristiangreco mentioned this issue Jun 29, 2022

Race condition in v1.12.2 prometheus/client_golang#1058

Closed

dmitshur added NeedsFix and removed NeedsInvestigation labels Jun 29, 2022

gopherbot closed this as completed in d6481d5 Jun 29, 2022

Repository owner moved this from Todo to Done in Go Compiler / Runtime Jun 29, 2022

mknyszek removed this from Go Compiler / Runtime Feb 15, 2023

golang locked and limited conversation to collaborators Jun 29, 2023

gopherbot added the FrozenDueToAge label Jun 29, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

runtime/metrics: data race detected in Read #53542

runtime/metrics: data race detected in Read #53542

cristiangreco commented Jun 24, 2022

ianlancetaylor commented Jun 24, 2022

prattmic commented Jun 24, 2022

aclements commented Jun 28, 2022

aclements commented Jun 28, 2022

aclements commented Jun 28, 2022

gopherbot commented Jun 28, 2022

prattmic commented Jun 28, 2022

gopherbot commented Jun 28, 2022

cherrymui commented Jun 28, 2022

prattmic commented Jun 28, 2022

cherrymui commented Jun 28, 2022

prattmic commented Jun 28, 2022

prattmic commented Jun 28, 2022

prattmic commented Jun 28, 2022 •

edited

Loading

cherrymui commented Jun 28, 2022

gopherbot commented Jun 29, 2022

gopherbot commented Jun 29, 2022

runtime/metrics: data race detected in Read #53542

runtime/metrics: data race detected in Read #53542

Comments

cristiangreco commented Jun 24, 2022

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

Does this issue reproduce with the latest release?

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

What did you do?

What did you expect to see?

What did you see instead?

ianlancetaylor commented Jun 24, 2022

prattmic commented Jun 24, 2022

aclements commented Jun 28, 2022

aclements commented Jun 28, 2022

aclements commented Jun 28, 2022

gopherbot commented Jun 28, 2022

prattmic commented Jun 28, 2022

gopherbot commented Jun 28, 2022

cherrymui commented Jun 28, 2022

prattmic commented Jun 28, 2022

cherrymui commented Jun 28, 2022

prattmic commented Jun 28, 2022

prattmic commented Jun 28, 2022

prattmic commented Jun 28, 2022 • edited Loading

cherrymui commented Jun 28, 2022

gopherbot commented Jun 29, 2022

gopherbot commented Jun 29, 2022

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

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

prattmic commented Jun 28, 2022 •

edited

Loading