go: slow exit of a network-using binary built with go 1.21rc3 and the race detector

[vrischmann]

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

on macOS: go version go1.21rc3 darwin/arm64
on Linux: go version go1.21rc3 linux/amd64

Does this issue reproduce with the latest release?

No

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

on macOS:

go env Output

$ go1.21rc3 env

GO111MODULE=''

GOARCH='arm64'

GOBIN=''

GOCACHE='/Users/vincent/Library/Caches/go-build'

GOENV='/Users/vincent/Library/Application Support/go/env'

GOEXE=''

GOEXPERIMENT=''

GOFLAGS='-mod=mod'

GOHOSTARCH='arm64'

GOHOSTOS='darwin'

GOINSECURE=''

GOMODCACHE='/Users/vincent/go/pkg/mod'

GONOPROXY=''

GONOSUMDB=''

GOOS='darwin'

GOPATH='/Users/vincent/go'

GOPRIVATE=''

GOPROXY='direct'

GOROOT='/Users/vincent/sdk/go1.21rc3'

GOSUMDB='sum.golang.org'

GOTMPDIR=''

GOTOOLCHAIN='auto'

GOTOOLDIR='/Users/vincent/sdk/go1.21rc3/pkg/tool/darwin_arm64'

GOVCS=''

GOVERSION='go1.21rc3'

GCCGO='gccgo'

AR='ar'

CC='clang'

CXX='clang++'

CGO_ENABLED='1'

GOMOD='/Users/vincent/tmp/go1.21-hang/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 -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/j8/g2_vrmzs1qzby1dv2f9klr9w0000gn/T/go-build3304684056=/tmp/go-build -gno-record-gcc-switches -fno-common'

on Linux:

go env Output

$ go1.21rc3 env

O111MODULE=''

GOARCH='amd64'

GOBIN=''

GOCACHE='/home/vincent/.cache/go-build'

GOENV='/home/vincent/.config/go/env'

GOEXE=''

GOEXPERIMENT=''

GOFLAGS='-mod=mod'

GOHOSTARCH='amd64'

GOHOSTOS='linux'

GOINSECURE=''

GOMODCACHE='/home/vincent/go/pkg/mod'

GONOPROXY=''

GONOSUMDB=''

GOOS='linux'

GOPATH='/home/vincent/go'

GOPRIVATE=''

GOPROXY='proxy.golang.org'

GOROOT='/home/vincent/sdk/go1.21rc3'

GOSUMDB='sum.golang.org'

GOTMPDIR=''

GOTOOLCHAIN='auto'

GOTOOLDIR='/home/vincent/sdk/go1.21rc3/pkg/tool/linux_amd64'

GOVCS=''

GOVERSION='go1.21rc3'

GCCGO='gccgo'

GOAMD64='v1'

AR='ar'

CC='gcc'

CXX='g++'

CGO_ENABLED='1'

GOMOD='/home/vincent/tmp/go1.21-hang/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-build3703279461=/tmp/go-build -gno-record-gcc-switches'

What did you do?

I'm working on a tool which sometimes talks to PostgreSQL. While developing I build the tool with go 1.21rc3 and with the flag -race enabled. I noticed something odd: everytime the tool uses networking it would take approximately a second to exit (after the main function has returned).

After some testing I found out the following code exhibits the same problem:

package main

import (
	"log"
	"net/http"
	"time"
)

func main() {
	start := time.Now()
	defer func() {
		log.Printf("elapsed: %s", time.Since(start))
	}()

	_, err := http.Get("https://google.com")
	if err != nil {
		log.Fatal(err)
	}
}

This is what I found:

• If you build this code with Go 1.21rc3 and with -race you should notice a significant delay before the program exits, after the "elapsed" log has been printed.
• Building with Go 1.21rc3 without -race doesn't have the problem
• Building with Go 1.20, with or without -race doesn't have the problem
• This is true on macOS and on Linux

What did you expect to see?

I expected the program to exit immediately after the main function has returned, as it does when built with Go 1.20.

What did you see instead?

After the main function has returned the program takes ~1s to exit

[mauri870]

I believe this is expected. Quoting the Data Race Detector page

The GORACE environment variable sets race detector options. The format is:

GORACE="option1=val1 option2=val2"

The options are:
...
atexit_sleep_ms (default 1000): Amount of milliseconds to sleep in the main goroutine before exiting. 

If you try to run your example after setting GORACE properly there is no sleep:

$ unset GORACE
$ go build -race main.go
$ time ./main
2023/07/30 13:51:25 elapsed: 569.891334ms
./main  0.11s user 0.00s system 6% cpu 1.576 total
$ export GORACE=atexit_sleep_ms=0
$ time ./main
2023/07/30 13:51:46 elapsed: 488.13579ms
./main  0.08s user 0.03s system 22% cpu 0.494 total

[seankhliao]

Duplicate of #20364

[vrischmann]

Thanks for the information, I didn't know this existed.

I'm still unsure why I don't experience this delay every time though.