runtime: stop-the-world never completes while goroutines are blocked in read(2) on a pipe (go1.26 regression)
Go version
go version go1.27.1 linux/amd64 (also go1.26.0, go1.26.3 and go1.26.8; go1.25.5 is not affected)
Output of go env in your module/workspace:
AR='ar'
CC='gcc'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='0'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='g++'
GCCGO='gccgo'
GO111MODULE=''
GOAMD64='v1'
GOARCH='amd64'
GOAUTH='netrc'
GOBIN='/nfs/users/nfs_s/sb10/go/bin'
GOCACHE='/nfs/users/nfs_s/sb10/.cache/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/nfs/users/nfs_s/sb10/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -m64 -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build2312301903=/tmp/go-build -gno-record-gcc-switches'
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMOD='/dev/null'
GOMODCACHE='/nfs/users/nfs_s/sb10/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPACKAGESDRIVER=''
GOPATH='/nfs/users/nfs_s/sb10/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/nfs/users/nfs_s/sb10/go/pkg/mod/golang.org/[email protected]'
GOSUMDB='sum.golang.org'
GOTELEMETRY='on'
GOTELEMETRYDIR='/nfs/users/nfs_s/sb10/.config/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='go1.27.1'
GOTOOLDIR='/nfs/users/nfs_s/sb10/go/pkg/mod/golang.org/[email protected]/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.27.1'
GOWORK=''
PKG_CONFIG='pkg-config'What did you do?
The program below runs as three processes. The first process (the watcher) makes two FIFOs, req and rep. It then re-execs itself as a Go "server" and as a "feeder":
- The server opens both FIFOs with blocking
syscall.Open, so the fds are not in the netpoller. It starts 4 goroutines that each loop onsyscall.Read(req, 1 byte)and thensyscall.Write(rep, 1 byte). The main goroutine runsfor { runtime.GC() }. - The feeder writes 1 byte to
req, then blocks reading the 1-byte reply fromrep, and repeats. It prints a line every 1000 round trips. - The watcher reads the feeder's output. If no line arrives for 5s it prints
HUNG; if 30s pass without a stall it printsOK. It then kills the server and feeder process group and removes the FIFOs.
The feeder only writes the next byte after the server replies, so at most one reader goroutine has data at a time. The other readers stay blocked in read(2) for as long as the server is stalled.
Run it with go run main.go. Setting GOTRACEBACK=all makes the watcher send SIGQUIT to the hung server before killing it, so the goroutine dump goes to stderr.
Host: Ubuntu 22.04, Linux 5.15.0-153-generic x86_64, 8 vCPUs (Intel Xeon Skylake).
// Command stwhang shows a stop-the-world that never completes while
// goroutines sit in blocking read(2) calls on a FIFO that another process
// writes to only after it gets a reply.
//
// Run with no arguments. It re-execs itself twice: as the Go server under
// test, and as the feeder. The original process watches the feeder's progress
// and prints one verdict line.
package main
import (
"bufio"
"fmt"
"os"
"os/exec"
"path/filepath"
"runtime"
"strings"
"syscall"
"time"
)
const (
readers = 4
duration = 30 * time.Second
stall = 5 * time.Second
)
func main() {
if len(os.Args) == 3 {
switch os.Args[1] {
case "server":
server(os.Args[2])
case "feeder":
feeder(os.Args[2])
}
return
}
os.Exit(watch())
}
// server blocks readers goroutines in read(2) on dir/req, replies to each
// byte on dir/rep, and runs the GC back to back.
func server(dir string) {
req := must(syscall.Open(filepath.Join(dir, "req"), syscall.O_RDONLY, 0))
rep := must(syscall.Open(filepath.Join(dir, "rep"), syscall.O_WRONLY, 0))
for i := 0; i < readers; i++ {
go func() {
buf := make([]byte, 1)
for {
if n, err := syscall.Read(req, buf); err == syscall.EINTR {
continue
} else if n != 1 {
panic(fmt.Sprint("read: ", n, err))
}
must(syscall.Write(rep, buf))
}
}()
}
for {
runtime.GC()
}
}
// feeder writes one byte to dir/req, waits for the one-byte reply on dir/rep,
// and prints a line every 1000 round trips.
func feeder(dir string) {
req := must(syscall.Open(filepath.Join(dir, "req"), syscall.O_WRONLY, 0))
rep := must(syscall.Open(filepath.Join(dir, "rep"), syscall.O_RDONLY, 0))
buf := []byte{'x'}
for i := 1; ; i++ {
must(syscall.Write(req, buf))
if n := must(syscall.Read(rep, buf)); n != 1 {
os.Exit(1)
}
if i%1000 == 0 {
fmt.Println(i)
}
}
}
// watch starts the server and feeder, and reports HUNG if the feeder makes
// no progress for the stall period.
func watch() int {
dir := must(os.MkdirTemp("", "stwhang"))
defer os.RemoveAll(dir)
for _, name := range []string{"req", "rep"} {
must(0, syscall.Mkfifo(filepath.Join(dir, name), 0o600))
}
srv := exec.Command(os.Args[0], "server", dir)
srv.Stderr = os.Stderr
srv.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
must(0, srv.Start())
fdr := exec.Command(os.Args[0], "feeder", dir)
fdr.SysProcAttr = &syscall.SysProcAttr{Setpgid: true, Pgid: srv.Process.Pid}
out := must(fdr.StdoutPipe())
must(0, fdr.Start())
defer func() { // kill the server and feeder process group, then reap both
syscall.Kill(-srv.Process.Pid, syscall.SIGKILL)
srv.Wait()
fdr.Wait()
}()
progress := make(chan string)
go func() {
for sc := bufio.NewScanner(out); sc.Scan(); {
progress <- sc.Text()
}
close(progress)
}()
last, end := "0", time.After(duration)
for {
select {
case p, ok := <-progress:
if !ok {
fmt.Printf("ERROR: feeder exited after %s round trips\n", last)
return 2
}
last = p
case <-time.After(stall):
fmt.Printf("HUNG: %s: no progress for %s after %s round trips; server threads (wchan/state): %s\n",
runtime.Version(), stall, last, threads(srv.Process.Pid))
if os.Getenv("GOTRACEBACK") != "" {
syscall.Kill(srv.Process.Pid, syscall.SIGQUIT)
time.Sleep(2 * time.Second)
}
return 1
case <-end:
fmt.Printf("OK: %s: %s round trips in %s, no hang\n", runtime.Version(), last, duration)
return 0
}
}
}
// threads counts the server's threads by kernel wait channel and state.
func threads(pid int) string {
counts := map[string]int{}
tasks, _ := filepath.Glob(fmt.Sprintf("/proc/%d/task/*", pid))
for _, task := range tasks {
wchan, _ := os.ReadFile(task + "/wchan")
stat, _ := os.ReadFile(task + "/stat")
state := "?"
if f := strings.Fields(string(stat)); len(f) > 2 {
state = f[2]
}
counts[string(wchan)+"/"+state]++
}
return fmt.Sprint(counts)
}
func must[T any](v T, err error) T {
if err != nil {
panic(err)
}
return v
}What did you see happen?
On go1.26 and go1.27 the server stops replying, after anywhere from 1,000 to 307,000 round trips in these runs. It never recovers:
$ go run main.go
HUNG: go1.27.1: no progress for 5s after 101000 round trips; server threads (wchan/state): map[futex_wait_queue_me/S:11 pipe_read/S:3]Hung runs per version, 30s per run (blank: not tried):
| Version | default (8 CPUs) | GODEBUG=asyncpreemptoff=1 | GOMAXPROCS=1 | GOMAXPROCS=2 | GOMAXPROCS=8 |
|---|---|---|---|---|---|
| go1.25.5 | 0/10 | 0/5 | 0/5 | 0/5 | 0/5 |
| go1.26.0 | 10/10 | ||||
| go1.26.3 | 10/10 | 5/5 | 0/5 | 4/5 | 5/5 |
| go1.26.8 | 10/10 | ||||
| go1.27.1 | 10/10 | 5/5 | 0/5 | 4/5 | 5/5 |
In every hung run the server's threads were in the same kernel state, read from /proc/<pid>/task/*/{wchan,stat}: 3 threads sleeping in pipe_read and all the others in futex_wait_queue_me. In a few runs, one thread was also running (wchan 0, state R). The one reader that got the feeder's last byte has left read(2), but its reply never arrives. The feeder is blocked in pipe_read on rep.
The SIGQUIT dump (go1.27.1, trimmed to the relevant goroutines) shows a mark-termination stop-the-world in progress. The reader that returned from read(2) is [runnable] and has no M, and no goroutine is running. Goroutines 20 and 22 are the same as goroutine 19: [syscall], each still on an M. The other goroutines in the dump are idle GC workers, the finalizer, the sweeper, the scavenger, and a second mark worker in semacquire inside gcMarkDone.
goroutine 1 gp=0x10a627a101e0 m=nil [wait for GC cycle]:
runtime.gopark(0x10a627a9ecf0?, 0x10a627a52000?, 0x0?, 0x0?, 0x0?)
$GOROOT/src/runtime/proc.go:474 +0xca
runtime.goparkunlock(...)
$GOROOT/src/runtime/proc.go:480
runtime.gcWaitOnMark(0x19d2)
$GOROOT/src/runtime/mgc.go:663 +0x5b
runtime.GC()
$GOROOT/src/runtime/mgc.go:558 +0x45
main.server({0x7ffec3f40823, 0xa9})
main.go:60 +0x136
main.main()
main.go:32 +0x66
runtime.main()
$GOROOT/src/runtime/proc.go:302 +0x427
runtime.goexit({})
$GOROOT/src/runtime/asm_amd64.s:1264 +0x1
goroutine 19 gp=0x10a627b823c0 m=10 mp=0x10a627b01808 [syscall]:
syscall.Syscall(0x0, 0x5, 0x10a627a75777, 0x1)
$GOROOT/src/syscall/syscall_linux.go:74 +0x25
syscall.read(0x5?, {0x10a627a75777?, 0x1?, 0x1?})
$GOROOT/src/syscall/zsyscall_linux_amd64.go:736 +0x38
syscall.Read(...)
$GOROOT/src/syscall/syscall_unix.go:183
main.server.func1()
main.go:50 +0x46
runtime.goexit({})
$GOROOT/src/runtime/asm_amd64.s:1264 +0x1
created by main.server in goroutine 1
main.go:47 +0x11e
goroutine 21 gp=0x10a627b82780 m=nil [runnable]:
syscall.Syscall(0x0, 0x5, 0x10a627a76777, 0x1)
$GOROOT/src/syscall/syscall_linux.go:74 +0x25
syscall.read(0x6?, {0x10a627a76777?, 0x1?, 0x1?})
$GOROOT/src/syscall/zsyscall_linux_amd64.go:736 +0x38
syscall.Read(...)
$GOROOT/src/syscall/syscall_unix.go:183
main.server.func1()
main.go:50 +0x46
runtime.goexit({})
$GOROOT/src/runtime/asm_amd64.s:1264 +0x1
created by main.server in goroutine 1
main.go:47 +0x11e
goroutine 25 gp=0x10a627b82f00 m=5 mp=0x10a627c00008 [stopping the world]:
runtime.systemstack_switch()
$GOROOT/src/runtime/asm_amd64.s:481 +0x8
runtime.gcMarkDone()
$GOROOT/src/runtime/mgc.go:1065 +0x21f
runtime.gcBgMarkWorker(0x10a627b860e0)
$GOROOT/src/runtime/mgc.go:1928 +0x2c5
runtime.gcBgMarkStartWorkers.gowrap1()
$GOROOT/src/runtime/mgc.go:1711 +0x17
runtime.goexit({})
$GOROOT/src/runtime/asm_amd64.s:1264 +0x1
created by runtime.gcBgMarkStartWorkers in goroutine 1
$GOROOT/src/runtime/mgc.go:1711 +0xfcWhat did you expect to see?
The program should run for the full 30s and print OK, as it does on go1.25.5. Goroutines blocked in a syscall should not stop the stop-the-world from completing. The reader that returned from its syscall should then run and reply.
Context: I found this in a FUSE server built on go-fuse, in wr. There, a process blocked on a FUSE request plays the feeder's role, and /dev/fuse plays req. The program above reproduces the hang without FUSE, cgo or third-party code. It is not #11155: nothing here forks, and no thread is blocked in vfork or chdir.
Suspected area (unverified): go1.26's change to how stop-the-world takes the Ps of goroutines in syscalls (_Psyscall removed; setBlockOnExitSyscall in runtime/proc.go).
Source: golang/go