runtime?: "concurrent map read and write" crashes no longer put the 2 offending goroutines at the top of the output

[fishy]

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

$ go version
go version go1.21.1 linux/amd64

Does this issue reproduce with the latest release?

This is the latest release

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

go env Output

$ go env
GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/home/fishy/.cache/go-build'
GOENV='/home/fishy/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/home/fishy/.gopath/pkg/mod'
GONOPROXY='redacted'
GONOSUMDB='redacted'
GOOS='linux'
GOPATH='/home/fishy/.gopath'
GOPRIVATE='redacted'
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/lib/go-1.21'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/lib/go-1.21/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.21.1'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='g++'
CGO_ENABLED='1'
GOMOD='/home/fishy/work/test/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 -ffile-prefix-map=/tmp/go-build3767391268=/tmp/go-build -gno-record-gcc-switches'

What did you do?

I have a simple code to cause "concurrent map read and write" crash:

package main

import (
        "fmt"
        "sync"
)

var m = make(map[string]string)

//go:noinline
func write(k, v string, n int) {
        for i := 0; i < n; i++ {
                m[k] = v
        }
}

//go:noinline
func read(k string) string {
        return m[k]
}

func main() {
        var wg sync.WaitGroup
        wg.Add(1)
        go func() {
                write("foo", "bar", 100)
                wg.Done()
        }()
        for i := 0; i < 100; i++ {
                wg.Add(1)
                go func(i int) {
                        fmt.Println(i, read("bar"))
                        wg.Done()
                }(i)
        }
        wg.Wait()
}

And dumped the crash log:

crash.log

fatal error: concurrent map read and map write
goroutine 7 [running]:

main.read({0x494a3e?, 0x0?})

test/main.go:19 +0x2f

main.main.func2(0x0?)

test/main.go:32 +0x31

created by main.main in goroutine 1

test/main.go:31 +0x7f
goroutine 1 [runnable]:

sync.(*WaitGroup).Add(0xc0000120f0?, 0x1?)

sync/waitgroup.go:43 +0xe8

main.main()

test/main.go:30 +0xa5
goroutine 37 [runnable]:

main.main.func3()

test/main.go:31

runtime.goexit()

runtime/asm_amd64.s:1650 +0x1

created by main.main in goroutine 1

test/main.go:31 +0x7f
goroutine 38 [runnable]:

main.main.func3()

test/main.go:31

runtime.goexit()

runtime/asm_amd64.s:1650 +0x1

created by main.main in goroutine 1

test/main.go:31 +0x7f
goroutine 40 [runnable]:

main.main.func3()

test/main.go:31

runtime.goexit()

runtime/asm_amd64.s:1650 +0x1

created by main.main in goroutine 1

test/main.go:31 +0x7f
goroutine 41 [runnable]:

main.main.func3()

test/main.go:31

runtime.goexit()

runtime/asm_amd64.s:1650 +0x1

created by main.main in goroutine 1

test/main.go:31 +0x7f
goroutine 42 [runnable]:

main.main.func3()

test/main.go:31

runtime.goexit()

runtime/asm_amd64.s:1650 +0x1

created by main.main in goroutine 1

test/main.go:31 +0x7f
goroutine 43 [runnable]:

main.main.func3()

test/main.go:31

runtime.goexit()

runtime/asm_amd64.s:1650 +0x1

created by main.main in goroutine 1

test/main.go:31 +0x7f
goroutine 44 [runnable]:

main.main.func3()

test/main.go:31

runtime.goexit()

runtime/asm_amd64.s:1650 +0x1

created by main.main in goroutine 1

test/main.go:31 +0x7f
goroutine 45 [runnable]:

main.main.func3()

test/main.go:31

runtime.goexit()

runtime/asm_amd64.s:1650 +0x1

created by main.main in goroutine 1

test/main.go:31 +0x7f
goroutine 46 [runnable]:

main.main.func3()

test/main.go:31

runtime.goexit()

runtime/asm_amd64.s:1650 +0x1

created by main.main in goroutine 1

test/main.go:31 +0x7f
goroutine 47 [runnable]:

main.main.func3()

test/main.go:31

runtime.goexit()

runtime/asm_amd64.s:1650 +0x1

created by main.main in goroutine 1

test/main.go:31 +0x7f
goroutine 48 [runnable]:

main.main.func3()

test/main.go:31

runtime.goexit()

runtime/asm_amd64.s:1650 +0x1

created by main.main in goroutine 1

test/main.go:31 +0x7f
goroutine 49 [runnable]:

main.main.func3()

test/main.go:31

runtime.goexit()

runtime/asm_amd64.s:1650 +0x1

created by main.main in goroutine 1

test/main.go:31 +0x7f

I remember in older versions of go, in those crash logs the first 2 goroutine would be the 2 goroutines reading and writing to the map (e.g. the offending goroutines). But now only the first goroutine in the output is the offending one, while the other offending one hidden in all other goroutines, making it extremely hard to find the root cause of the bug:

$ head -n 16 crash.log 
fatal error: concurrent map read and map write

goroutine 7 [running]:
main.read({0x494a3e?, 0x0?})
        test/main.go:19 +0x2f
main.main.func2(0x0?)
        test/main.go:32 +0x31
created by main.main in goroutine 1
        test/main.go:31 +0x7f

goroutine 1 [runnable]:
sync.(*WaitGroup).Add(0xc0000120f0?, 0x1?)
        sync/waitgroup.go:43 +0xe8
main.main()
        test/main.go:30 +0xa5

What did you expect to see?

The first 2 goroutines in crash output being the 2 offending goroutines

What did you see instead?

Only the first goroutine is one of the offending goroutines in the output, the second offending goroutine is very hard to find from the output when there are thousands of goroutines running.

[fishy]

crash.log
attaching the raw crash.log file since copy-pasting into markdown seems to mess up some whitespaces.

[rittneje]

I remember in older versions of go, in those crash logs the first 2 goroutine would be the 2 goroutines reading and writing to the map (e.g. the offending goroutines).

I checked a few old versions and none of them did that. Perhaps you are thinking of the race detector?

==================
WARNING: DATA RACE
Write at 0x00c00007e000 by goroutine 6:
runtime.mapassign_faststr()
/home/rittneje/go/src/runtime/map_faststr.go:203 +0x0
main.write()
/home/rittneje/go-workspace/src/bug63172/main.go:12 +0x7b
main.main.func1()
/home/rittneje/go-workspace/src/bug63172/main.go:26 +0x4d

Previous read at 0x00c00007e000 by goroutine 7:
runtime.mapaccess1_faststr()
/home/rittneje/go/src/runtime/map_faststr.go:13 +0x0
main.read()
/home/rittneje/go-workspace/src/bug63172/main.go:18 +0x4d
main.main.func2()
/home/rittneje/go-workspace/src/bug63172/main.go:34 +0x3e

Goroutine 6 (running) created at:
main.main()
/home/rittneje/go-workspace/src/bug63172/main.go:24 +0xc4

Goroutine 7 (running) created at:
main.main()
/home/rittneje/go-workspace/src/bug63172/main.go:32 +0x144
==================

[seankhliao]

see above